Re: [Qemu-devel] Hack integrating SeaBios / LinuxBoot option rom with QEMU trace backends

[Anthony Liguori <anthony@codemonkey.ws>]

On 10/10/2011 12:08 PM, Daniel P. Berrange wrote:
> I've been investigating where time disappears to when booting Linux guests.
>
> Initially I enabled DEBUG_BIOS in QEMU's hw/pc.c, and then hacked it so
> that it could print a timestamp before each new line of debug output. The
> problem with that is that it slowed down startup, so the timings I was
> examining all changed.
>
> What I really wanted was to use QEMU's trace infrastructure with a simple
> SystemTAP script. This is easy enough in the QEMU layer, but I also need
> to see where time goes to inside the various BIOS functions, and the
> options ROMs such as LinuxBoot. So I came up with a small hack to insert
> "probes" into SeaBios and LinuxBoot, which trigger a special IO port
> (0x404), which then cause QEMU to emit a trace event.
>
> The implementation is really very crude and does not allow any arguments
> to be passed each probes, but since all I care about is timing information,
> it is good enough for my needs.
>
> I'm not really expecting these patches to be merged into QEMU/SeaBios
> since they're just a crude hack&  I don't have time to write something
> better. I figure they might be useful for someone else though...
>
> With the attached patches applied to QEMU and SeaBios, the attached
> systemtap script can be used to debug timings in QEMU startup.
>
> For example, one execution of QEMU produced the following log:
>
>    $ stap qemu-timing.stp
>    0.000 Start
>    0.036 Run
>    0.038 BIOS post
>    0.180 BIOS int 19
>    0.181 BIOS boot OS
>    0.181 LinuxBoot copy kernel
>    1.371 LinuxBoot copy initrd

Yeah, there was a thread a bit ago about the performance of the interface to 
read the kernel/initrd.  I think at it was using single byte access instructions 
and there were patches to use string accessors instead?  I can't remember where 
that threaded ended up.

CC'ing Gleb and Alex who may recall more.

Regards,

Anthony Liguori


>    1.616 LinuxBoot boot OS
>    2.489 Shutdown request
>    2.490 Stop
>
> showing that LinuxBoot is responsible for by far the most execution
> time (~1500ms), in my test which runs for 2500ms in total.
>
> Regards,
> Daniel