From patchwork Mon Oct 10 17:08:03 2011 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: =?utf-8?q?Daniel_P=2E_Berrang=C3=A9?= X-Patchwork-Id: 118792 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.gnu.org (lists.gnu.org [140.186.70.17]) (using TLSv1 with cipher AES256-SHA (256/256 bits)) (Client did not present a certificate) by ozlabs.org (Postfix) with ESMTPS id 6548EB70BB for ; Tue, 11 Oct 2011 04:08:37 +1100 (EST) Received: from localhost ([::1]:48712 helo=lists.gnu.org) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1RDJL4-00086p-GK for incoming@patchwork.ozlabs.org; Mon, 10 Oct 2011 13:08:30 -0400 Received: from eggs.gnu.org ([140.186.70.92]:49349) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1RDJKw-00086P-7L for qemu-devel@nongnu.org; Mon, 10 Oct 2011 13:08:24 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1RDJKt-0004FA-VK for qemu-devel@nongnu.org; Mon, 10 Oct 2011 13:08:22 -0400 Received: from mx1.redhat.com ([209.132.183.28]:22307) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1RDJKt-0004F3-CG for qemu-devel@nongnu.org; Mon, 10 Oct 2011 13:08:19 -0400 Received: from int-mx01.intmail.prod.int.phx2.redhat.com (int-mx01.intmail.prod.int.phx2.redhat.com [10.5.11.11]) by mx1.redhat.com (8.14.4/8.14.4) with ESMTP id p9AH8Hc8012643 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=OK); Mon, 10 Oct 2011 13:08:17 -0400 Received: from redhat.com (vpn1-5-70.ams2.redhat.com [10.36.5.70]) by int-mx01.intmail.prod.int.phx2.redhat.com (8.13.8/8.13.8) with ESMTP id p9AH8CRU022349 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES128-SHA bits=128 verify=NO); Mon, 10 Oct 2011 13:08:14 -0400 Date: Mon, 10 Oct 2011 18:08:03 +0100 From: "Daniel P. Berrange" To: qemu-devel , seabios@seabios.org Message-ID: <20111010170803.GV9408@redhat.com> MIME-Version: 1.0 Content-Disposition: inline User-Agent: Mutt/1.5.21 (2010-09-15) X-Scanned-By: MIMEDefang 2.67 on 10.5.11.11 X-detected-operating-system: by eggs.gnu.org: GNU/Linux 2.6 (newer, 3) X-Received-From: 209.132.183.28 Subject: [Qemu-devel] Hack integrating SeaBios / LinuxBoot option rom with QEMU trace backends X-BeenThere: qemu-devel@nongnu.org X-Mailman-Version: 2.1.14 Precedence: list Reply-To: "Daniel P. Berrange" List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: qemu-devel-bounces+incoming=patchwork.ozlabs.org@nongnu.org Sender: qemu-devel-bounces+incoming=patchwork.ozlabs.org@nongnu.org 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 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; }