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