Re: [SeaBIOS] [PATCH v2] qemu: fast boot when linuxboot optionrom is used

[Kevin O'Connor]

On Thu, Nov 29, 2018 at 03:16:39PM +0100, Stefano Garzarella wrote:
> On Wed, Nov 28, 2018 at 3:38 PM Kevin O'Connor  wrote:
> > It would be good to understand what the source of the delay is.  It
> > might be possible to avoid the delay without adding a new config
> > setting.  For example, the patch above will prevent the vga rom from
> > being run, but it should be possible to accomplish the same with
> > "-device VGA,romfile=".  The other change this patch makes is to skip
> > device_hardware_setup() - is it known which items in that function add
> > to the delay?
>
> Hi Kevin,
> thanks for your advice.
>
> I tried to understand what are the sources of the delay, and I found
> that most of the time is spent because of QEMU default devices (eg
> e1000 ROM PCI, mouse, keyboard, etc)
> At this point, (without the patch above) I disabled the default QEMU
> devices (-nodefaults) and I reached 12.5 ms of SeaBIOS boot time
> (compared to 22 ms, where 4 ms is taken by the loading of e1000 ROM).
>
> Other 2 ms is taken by enable_vga_console(), where simply comment out
> the printf("SeaBIOS (version %s)\n", VERSION) I reached 10.7 ms of
> boot time.
> Do you think is acceptable to use dprintf(1, ...) instead of printf()?
> Or maybe check if we found the VGA.

Interesting.  I tracked down this printf delay - it's due to the
save/restore of cpu state when thunking to 16bit mode.  (For every
character displayed on the screen the code enters 16bit mode to invoke
the vgabios and it saves/restores the cr0, gdt, fs, gs, a20, nmi
states during that process.)  It's trivial to eliminate the calls when
there is no vgabios though (see patch below).
> Note: All these tests are done with CONFIG_DEBUG_LEVEL=0, using
> CONFIG_DEBUG_LEVEL=1 the boot time grows up to 24 ms, maybe we should
> put CONFIG_DEBUG_LEVEL=0 in the SeaBIOS configuration used in QEMU.

I think the main seabios binary should have CONFIG_DEBUG_LEVEL=1 as it
helps with debug reports.  I suppose an additional binary could be
made for those looking for the fastest possible speed.  (The sole cost
of the debugging is the additional hardware accesses that results from
those debug messages.)
> > Also, what is the target boot time that is considered acceptable?
>
> I'm using qboot as a reference (6/7 ms). It is very minimal, so 10 ms
> I think is considered acceptable for SeaBIOS

Thanks,
-Kevin

--- a/src/output.c
+++ b/src/output.c
@@ -74,6 +74,9 @@ static struct putcinfo debuginfo = { debug_putc };
 static void
 screenc(char c)
 {
+    if (!MODESEGMENT && GET_IVT(0x10).segoff == FUNC16(entry_10).segoff)
+        // No need to thunk to 16bit mode if vgabios is not present
+        return;
     struct bregs br;
     memset(&br, 0, sizeof(br));
     br.flags = F_IF;

[PATCH v2] qemu: fast boot when linuxboot optionrom is used

[Stefano Garzarella]

On Thu, Nov 29, 2018 at 5:55 PM Kevin O'Connor  wrote:
> On Thu, Nov 29, 2018 at 03:16:39PM +0100, Stefano Garzarella wrote:
> > On Wed, Nov 28, 2018 at 3:38 PM Kevin O'Connor  wrote:
> > > It would be good to understand what the source of the delay is.  It
> > > might be possible to avoid the delay without adding a new config
> > > setting.  For example, the patch above will prevent the vga rom from
> > > being run, but it should be possible to accomplish the same with
> > > "-device VGA,romfile=".  The other change this patch makes is to skip
> > > device_hardware_setup() - is it known which items in that function add
> > > to the delay?
> >
> > Hi Kevin,
> > thanks for your advice.
> >
> > I tried to understand what are the sources of the delay, and I found
> > that most of the time is spent because of QEMU default devices (eg
> > e1000 ROM PCI, mouse, keyboard, etc)
> > At this point, (without the patch above) I disabled the default QEMU
> > devices (-nodefaults) and I reached 12.5 ms of SeaBIOS boot time
> > (compared to 22 ms, where 4 ms is taken by the loading of e1000 ROM).
> >
> > Other 2 ms is taken by enable_vga_console(), where simply comment out
> > the printf("SeaBIOS (version %s)\n", VERSION) I reached 10.7 ms of
> > boot time.
> > Do you think is acceptable to use dprintf(1, ...) instead of printf()?
> > Or maybe check if we found the VGA.
>
> Interesting.  I tracked down this printf delay - it's due to the
> save/restore of cpu state when thunking to 16bit mode.  (For every
> character displayed on the screen the code enters 16bit mode to invoke
> the vgabios and it saves/restores the cr0, gdt, fs, gs, a20, nmi
> states during that process.)  It's trivial to eliminate the calls when
> there is no vgabios though (see patch below).

Thanks, the patch works, but unfortunately, when I use qemu
-nographic, the  /etc/sercon-port is set to PORT_SERIAL1 (in
src/fw/paravirt.c:623), bypassing the patch.
Maybe in QEMU is better to set /etc/sercom-port to 0 when there is no
serial port, or when we want a fast boot.
> > Note: All these tests are done with CONFIG_DEBUG_LEVEL=0, using
> > CONFIG_DEBUG_LEVEL=1 the boot time grows up to 24 ms, maybe we should
> > put CONFIG_DEBUG_LEVEL=0 in the SeaBIOS configuration used in QEMU.
>
> I think the main seabios binary should have CONFIG_DEBUG_LEVEL=1 as it
> helps with debug reports.  I suppose an additional binary could be
> made for those looking for the fastest possible speed.  (The sole cost
> of the debugging is the additional hardware accesses that results from
> those debug messages.)

Okay, I'll discuss it in the QEMU mailing list.
> > > Also, what is the target boot time that is considered acceptable?
> >
> > I'm using qboot as a reference (6/7 ms). It is very minimal, so 10 ms
> > I think is considered acceptable for SeaBIOS
>
> Thanks,
> -Kevin
>
> --- a/src/output.c
> +++ b/src/output.c
> @@ -74,6 +74,9 @@ static struct putcinfo debuginfo = { debug_putc };
>  static void
>  screenc(char c)
>  {
> if (!MODESEGMENT && GET_IVT(0x10).segoff == FUNC16(entry_10).segoff)
>    // No need to thunk to 16bit mode if vgabios is not present
>    return;
> struct bregs br;
>    memset(&br, 0, sizeof(br));
>    br.flags = F_IF;

Do you plan to commit this patch?

Thanks,
Stefano

[PATCH v2] qemu: fast boot when linuxboot optionrom is used

[Gerd Hoffmann]

Hi,
> > Note: All these tests are done with CONFIG_DEBUG_LEVEL=0, using
> > CONFIG_DEBUG_LEVEL=1 the boot time grows up to 24 ms, maybe we should
> > put CONFIG_DEBUG_LEVEL=0 in the SeaBIOS configuration used in QEMU.
>
> I think the main seabios binary should have CONFIG_DEBUG_LEVEL=1 as it
> helps with debug reports.  I suppose an additional binary could be
> made for those looking for the fastest possible speed.  (The sole cost
> of the debugging is the additional hardware accesses that results from
> those debug messages.)

The qemu debugcon (CONFIG_DEBUG_IO) is detecable at runtime, it returns
0xe9 on port reads.  So we should be able to skip that too.  IIRC it
isn't *that* straightforward as seabios is initially mapped read/only so
a simple probe-on-first-putchar, then cache the result in a variable
doesn't work.  We could probe after make_bios_writable though which
should still avoid printing most of the messages.

cheers,
  Gerd

[PATCH v2] qemu: fast boot when linuxboot optionrom is used

[Stefano Garzarella]

On Fri, Nov 30, 2018 at 2:06 PM Gerd Hoffmann  wrote:
> Hi,
> > > Note: All these tests are done with CONFIG_DEBUG_LEVEL=0, using
> > > CONFIG_DEBUG_LEVEL=1 the boot time grows up to 24 ms, maybe we should
> > > put CONFIG_DEBUG_LEVEL=0 in the SeaBIOS configuration used in QEMU.
> >
> > I think the main seabios binary should have CONFIG_DEBUG_LEVEL=1 as it
> > helps with debug reports.  I suppose an additional binary could be
> > made for those looking for the fastest possible speed.  (The sole cost
> > of the debugging is the additional hardware accesses that results from
> > those debug messages.)
>
> The qemu debugcon (CONFIG_DEBUG_IO) is detecable at runtime, it returns
> 0xe9 on port reads.  So we should be able to skip that too.  IIRC it
> isn't *that* straightforward as seabios is initially mapped read/only so
> a simple probe-on-first-putchar, then cache the result in a variable
> doesn't work.  We could probe after make_bios_writable though which
> should still avoid printing most of the messages.

Great! I just tried the patch below and it works as you said. If I
don't have debugcon in QEMU the outs are avoided and the speed is not
bad (11.4 ms).
If I have debugcon (iobase=0x402), I can see the output.

Do you think can be an acceptable trade-off?

Thanks.
Stefano

diff --git a/src/fw/paravirt.c b/src/fw/paravirt.c
index 0770c47..31c080e 100644
--- a/src/fw/paravirt.c
+++ b/src/fw/paravirt.c
@@ -121,6 +121,10 @@ qemu_preinit(void)
         kvm_detect();
     }

+    // Detect qemu debugcon
+    if (inb(GET_GLOBAL(DebugOutputPort)) != QEMU_DEBUGCON_READBACK)
+        DebugOutputPort = 0;
+
     // On emulators, get memory size from nvram.
     u32 rs = ((rtc_read(CMOS_MEM_EXTMEM2_LOW) << 16)
               | (rtc_read(CMOS_MEM_EXTMEM2_HIGH) << 24));
diff --git a/src/fw/paravirt.h b/src/fw/paravirt.h
index a14d83e..f7e1d4c 100644
--- a/src/fw/paravirt.h
+++ b/src/fw/paravirt.h
@@ -49,6 +49,9 @@ static inline int runningOnKVM(void) {
 // QEMU_CFG_DMA ID bit
 #define QEMU_CFG_VERSION_DMA    2

+// QEMU debugcon read value
+#define QEMU_DEBUGCON_READBACK  0xe9
+
 int qemu_cfg_enabled(void);
 int qemu_cfg_dma_enabled(void);
 void qemu_preinit(void);
diff --git a/src/hw/serialio.c b/src/hw/serialio.c
index 319a85c..4e0f2ac 100644
--- a/src/hw/serialio.c
+++ b/src/hw/serialio.c
@@ -107,7 +107,7 @@ u16 DebugOutputPort VARFSEG = 0x402;
 void
 qemu_debug_putc(char c)
 {
-    if (CONFIG_DEBUG_IO && runningOnQEMU())
+    if (CONFIG_DEBUG_IO && runningOnQEMU() && GET_GLOBAL(DebugOutputPort))
         // Send character to debug port.
         outb(c, GET_GLOBAL(DebugOutputPort));
 }
> cheers,
>   Gerd