[SeaBIOS] Hack integrating SeaBios / LinuxBoot option rom with QEMU trace backends
Daniel P. Berrange
berrange at redhat.com
Mon Oct 10 19:08:03 CEST 2011
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
--
|: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :|
|: http://libvirt.org -o- http://virt-manager.org :|
|: http://autobuild.org -o- http://search.cpan.org/~danberr/ :|
|: http://entangle-photo.org -o- http://live.gnome.org/gtk-vnc :|
-------------- next part --------------
diff --git a/hw/pc.c b/hw/pc.c
index 203627d..76d0790 100644
--- a/hw/pc.c
+++ b/hw/pc.c
@@ -43,6 +43,7 @@
#include "ui/qemu-spice.h"
#include "memory.h"
#include "exec-memory.h"
+#include "trace.h"
/* output Bochs bios info messages */
//#define DEBUG_BIOS
@@ -516,6 +517,16 @@ static void handle_a20_line_change(void *opaque, int irq, int level)
/***********************************************************/
/* Bochs BIOS debug ports */
+enum {
+ PROBE_SEABIOS_POST = 1001,
+ PROBE_SEABIOS_INT_18 = 1002,
+ PROBE_SEABIOS_INT_19 = 1003,
+ PROBE_SEABIOS_BOOT_OS = 1004,
+
+ PROBE_LINUXBOOT_COPY_KERNEL = 2001,
+ PROBE_LINUXBOOT_COPY_INITRD = 2002,
+ PROBE_LINUXBOOT_BOOT_OS = 2003,
+};
static void bochs_bios_write(void *opaque, uint32_t addr, uint32_t val)
{
@@ -534,6 +545,31 @@ static void bochs_bios_write(void *opaque, uint32_t addr, uint32_t val)
fprintf(stderr, "%c", val);
#endif
break;
+ case 0x404: {
+ switch (val) {
+ case PROBE_SEABIOS_POST:
+ trace_seabios_post();
+ break;
+ case PROBE_SEABIOS_INT_18:
+ trace_seabios_int_18();
+ break;
+ case PROBE_SEABIOS_INT_19:
+ trace_seabios_int_19();
+ break;
+ case PROBE_SEABIOS_BOOT_OS:
+ trace_seabios_boot_OS();
+ break;
+ case PROBE_LINUXBOOT_COPY_KERNEL:
+ trace_linuxboot_copy_kernel();
+ break;
+ case PROBE_LINUXBOOT_COPY_INITRD:
+ trace_linuxboot_copy_initrd();
+ break;
+ case PROBE_LINUXBOOT_BOOT_OS:
+ trace_linuxboot_boot_OS();
+ break;
+ }
+ } break;
case 0x8900:
/* same as Bochs power off */
if (val == shutdown_str[shutdown_index]) {
@@ -589,6 +625,7 @@ static void *bochs_bios_init(void)
register_ioport_write(0x401, 1, 2, bochs_bios_write, NULL);
register_ioport_write(0x402, 1, 1, bochs_bios_write, NULL);
register_ioport_write(0x403, 1, 1, bochs_bios_write, NULL);
+ register_ioport_write(0x404, 1, 4, bochs_bios_write, NULL);
register_ioport_write(0x8900, 1, 1, bochs_bios_write, NULL);
register_ioport_write(0x501, 1, 1, bochs_bios_write, NULL);
diff --git a/pc-bios/linuxboot.bin b/pc-bios/linuxboot.bin
index e7c3669..40b9217 100644
Binary files a/pc-bios/linuxboot.bin and b/pc-bios/linuxboot.bin differ
diff --git a/pc-bios/optionrom/linuxboot.S b/pc-bios/optionrom/linuxboot.S
index 748c831..5c39fb1 100644
--- a/pc-bios/optionrom/linuxboot.S
+++ b/pc-bios/optionrom/linuxboot.S
@@ -108,11 +108,21 @@ copy_kernel:
/* We're now running in 16-bit CS, but 32-bit ES! */
/* Load kernel and initrd */
+ mov $0x7d1,%eax
+ mov $0x404,%edx
+ outl %eax,(%dx)
read_fw_blob_addr32(FW_CFG_KERNEL)
+ mov $0x7d2,%eax
+ mov $0x404,%edx
+ outl %eax,(%dx)
read_fw_blob_addr32(FW_CFG_INITRD)
read_fw_blob_addr32(FW_CFG_CMDLINE)
read_fw_blob_addr32(FW_CFG_SETUP)
+ mov $0x7d3,%eax
+ mov $0x404,%edx
+ outl %eax,(%dx)
+
/* And now jump into Linux! */
mov $0, %eax
mov %eax, %cr0
diff --git a/trace-events b/trace-events
index a31d9aa..34ca28b 100644
--- a/trace-events
+++ b/trace-events
@@ -289,6 +289,11 @@ scsi_request_sense(int target, int lun, int tag) "target %d lun %d tag %d"
# vl.c
vm_state_notify(int running, int reason) "running %d reason %d"
+main_start(void) "startup"
+main_loop(void) "loop"
+main_stop(void) "stop"
+qemu_shutdown_request(void) "shutdown request"
+qemu_powerdown_request(void) "powerdown request"
# block/qed-l2-cache.c
qed_alloc_l2_cache_entry(void *l2_cache, void *entry) "l2_cache %p entry %p"
@@ -502,3 +507,12 @@ escc_sunkbd_event_in(int ch) "Untranslated keycode %2.2x"
escc_sunkbd_event_out(int ch) "Translated keycode %2.2x"
escc_kbd_command(int val) "Command %d"
escc_sunmouse_event(int dx, int dy, int buttons_state) "dx=%d dy=%d buttons=%01x"
+
+seabios_post(void) "BIOS post"
+seabios_int_18(void) "BIOS int18"
+seabios_int_19(void) "BIOS int19"
+seabios_boot_OS(void) "BIOS boot OS"
+
+linuxboot_copy_kernel(void) "LinuxBoot Copy Kernel"
+linuxboot_copy_initrd(void) "LinuxBoot Copy InitRD"
+linuxboot_boot_OS(void) "LinuxBoot boot OS"
diff --git a/vl.c b/vl.c
index bd4a5ce..91e6f5e 100644
--- a/vl.c
+++ b/vl.c
@@ -162,7 +162,7 @@ int main(int argc, char **argv)
#include "qemu-queue.h"
#include "cpus.h"
#include "arch_init.h"
-
+#include "trace.h"
#include "ui/qemu-spice.h"
//#define DEBUG_NET
@@ -1414,12 +1414,14 @@ void qemu_system_killed(int signal, pid_t pid)
void qemu_system_shutdown_request(void)
{
+ trace_qemu_shutdown_request();
shutdown_requested = 1;
qemu_notify_event();
}
void qemu_system_powerdown_request(void)
{
+ trace_qemu_powerdown_request();
powerdown_requested = 1;
qemu_notify_event();
}
@@ -2313,6 +2315,8 @@ int main(int argc, char **argv, char **envp)
const char *trace_events = NULL;
const char *trace_file = NULL;
+ trace_main_start();
+
atexit(qemu_run_exit_notifiers);
error_set_progname(argv[0]);
@@ -3571,10 +3575,12 @@ int main(int argc, char **argv, char **envp)
os_setup_post();
+ trace_main_loop();
main_loop();
quit_timers();
net_cleanup();
res_free();
+ trace_main_stop();
return 0;
}
-------------- next part --------------
diff --git a/src/boot.c b/src/boot.c
index 119f290..931ec3f 100644
--- a/src/boot.c
+++ b/src/boot.c
@@ -14,7 +14,7 @@
#include "cmos.h" // inb_cmos
#include "paravirt.h" // romfile_loadfile
#include "pci.h" //pci_bdf_to_*
-
+#include "probes.h"
/****************************************************************
* Boot priority ordering
@@ -512,6 +512,7 @@ call_boot_entry(struct segoff_s bootsegip, u8 bootdrv)
// Set the magic number in ax and the boot drive in dl.
br.dl = bootdrv;
br.ax = 0xaa55;
+ PROBE(BOOT_OS);
call16(&br);
}
@@ -643,6 +644,7 @@ do_boot(u16 seq_nr)
void VISIBLE32FLAT
handle_18(void)
{
+ PROBE(INT_18);
debug_serial_setup();
debug_enter(NULL, DEBUG_HDL_18);
u16 ebda_seg = get_ebda_seg();
@@ -655,6 +657,7 @@ handle_18(void)
void VISIBLE32FLAT
handle_19(void)
{
+ PROBE(INT_19);
debug_serial_setup();
debug_enter(NULL, DEBUG_HDL_19);
SET_EBDA(boot_sequence, 0);
diff --git a/src/post.c b/src/post.c
index b4ad1fa..59e6a37 100644
--- a/src/post.c
+++ b/src/post.c
@@ -26,6 +26,7 @@
#include "xen.h" // xen_probe_hvm_info
#include "ps2port.h" // ps2port_setup
#include "virtio-blk.h" // virtio_blk_setup
+#include "probes.h"
/****************************************************************
@@ -354,6 +355,7 @@ dopost(void)
void VISIBLE32FLAT
handle_post(void)
{
+ PROBE(POST);
debug_serial_setup();
dprintf(1, "Start bios (version %s)\n", VERSION);
diff --git a/src/probes.h b/src/probes.h
new file mode 100644
index 0000000..1ec639f
--- /dev/null
+++ b/src/probes.h
@@ -0,0 +1,25 @@
+#ifndef __PROBES_H
+#define __PROBES_H
+
+/* Copy from QEMU pc.c */
+enum {
+ PROBE_SEABIOS_POST = 1001,
+ PROBE_SEABIOS_INT_18 = 1002,
+ PROBE_SEABIOS_INT_19 = 1003,
+ PROBE_SEABIOS_BOOT_OS = 1004,
+};
+
+#define PROBE_IO_PORT 0x404
+
+static inline void _probe(u32 event)
+{
+ outl(event, PROBE_IO_PORT);
+}
+
+#define PROBE(name) \
+ do { \
+ dprintf(9, "PROBE " #name "\n"); \
+ _probe(PROBE_SEABIOS_ ## name); \
+ } while (0)
+
+#endif /* __PROBES_H */
-------------- next part --------------
global start;
function print_ts(str) {
now = gettimeofday_ns() / (1000*1000)
delta = (now - start)
printf("%3d.%03d %s\n",
(delta / 1000), (delta % 1000), str);
}
probe process("qemu-system-x86_64").mark("main_start") {
start = gettimeofday_ns() / (1000*1000);
print_ts("Start");
}
probe process("qemu-system-x86_64").mark("main_loop") {
print_ts("Run");
}
probe process("qemu-system-x86_64").mark("main_stop") {
print_ts("Stop");
}
probe process("qemu-system-x86_64").mark("qemu_shutdown_request") {
print_ts("Shutdown request");
}
probe process("qemu-system-x86_64").mark("qemu_powerdown_request") {
print_ts("Powerdown request");
}
probe process("qemu-system-x86_64").mark("seabios_post") {
print_ts("BIOS post");
}
probe process("qemu-system-x86_64").mark("seabios_int_18") {
print_ts("BIOS int 18");
}
probe process("qemu-system-x86_64").mark("seabios_int_19") {
print_ts("BIOS int 19");
}
probe process("qemu-system-x86_64").mark("seabios_boot_OS") {
print_ts("BIOS boot OS");
}
probe process("qemu-system-x86_64").mark("linuxboot_copy_kernel") {
print_ts("LinuxBoot copy kernel");
}
probe process("qemu-system-x86_64").mark("linuxboot_copy_initrd") {
print_ts("LinuxBoot copy initrd");
}
probe process("qemu-system-x86_64").mark("linuxboot_boot_OS") {
print_ts("LinuxBoot boot OS");
}
More information about the SeaBIOS
mailing list