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 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