Slow HVM boot time, was "HVM boot time optimization"

Slow HVM boot time, was "HVM boot time optimization"

[Stefano Stabellini]

[-- Attachment #1: Type: TEXT/PLAIN, Size: 1975 bytes --]

CC'ing xen-devel and a few relevant people

On Thu, 8 Feb 2018, Yessine Daoud wrote:
> Dear Sir,
> I need your help please.
> 
> I am using a direct kernel boot (HVM guest) with kernel + ramdisk.
> At boot, seabios is bloqued about 20 seconds (or more) at the following state:
> 
> (d4) RamSizeOver4G: 0x0000000000000000 [cmos]
> (d4) boot order:
> (d4) 1: /rom@genroms/linuxboot.bin
> (d4) Found 4 PCI devices (max PCI bus is 00)
> (d4) Allocated Xen hypercall page at ffff000
> (d4) Detected Xen v4.9-unstable
> (d4) xen: copy BIOS tables...
> (d4) Copying SMBIOS entry point from 0x00010020 to 0x000f69b0
> (d4) Copying MPTABLE from 0xfc001170/fc001180 to 0x000f68b0
> (d4) Copying PIR from 0x00010040 to 0x000f6830
> (d4) CPU Mhz=1335
> (d4) Scan for VGA option rom
> (d4) ATA controller 1 at 1f0/3f4/c100 (irq 14 dev 9)
> (d4) ATA controller 2 at 170/374/c108 (irq 15 dev 9)
> (d4) Found 0 lpt ports
> (d4) Found 1 serial ports
> (d4) PS2 keyboard initialized
> (d4) All threads complete.
> (d4) Scan for option roms
> (d4) Running option rom at c000:0003
> (d4) Searching bootorder for: /rom@genroms/linuxboot.bin
> (d4) Searching bootorder for: HALT
> (d4) Space available for UMB: c0800-ec800, f61d0-f67f0
> (d4) Returned 258048 bytes of ZoneHigh
> (d4) e820 map has 6 items:
> (d4)   0: 0000000000000000 - 000000000009fc00 = 1 RAM
> (d4)   1: 000000000009fc00 - 00000000000a0000 = 2 RESERVED
> (d4)   2: 00000000000f0000 - 0000000000100000 = 2 RESERVED
> (d4)   3: 0000000000100000 - 000000000ffff000 = 1 RAM
> (d4)   4: 000000000ffff000 - 0000000010000000 = 2 RESERVED
> (d4)   5: 00000000fc000000 - 0000000100000000 = 2 RESERVED
> (d4) enter handle_19:
> (d4)   NULL
> (d4) Booting from ROM...
> (d4) Booting from c000:00
> 
> 
> Then (after 20 seconds) the kernel starts booting.
> Any idea about this behavior?

I am guessing one of the ROMs take a long time to run. It might be
waiting for a timeout, like ipxe. Does anybody know about this issue?

[-- Attachment #2: Type: text/plain, Size: 157 bytes --]

_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xenproject.org
https://lists.xenproject.org/mailman/listinfo/xen-devel

Re: Slow HVM boot time, was "HVM boot time optimization"

[George Dunlap]

On Thu, Feb 8, 2018 at 4:31 PM, Stefano Stabellini
<sstabellini@kernel.org> wrote:
> CC'ing xen-devel and a few relevant people
>
> On Thu, 8 Feb 2018, Yessine Daoud wrote:
>> Dear Sir,
>> I need your help please.
>>
>> I am using a direct kernel boot (HVM guest) with kernel + ramdisk.
>> At boot, seabios is bloqued about 20 seconds (or more) at the following state:
>>
>> (d4) RamSizeOver4G: 0x0000000000000000 [cmos]
>> (d4) boot order:
>> (d4) 1: /rom@genroms/linuxboot.bin
>> (d4) Found 4 PCI devices (max PCI bus is 00)
>> (d4) Allocated Xen hypercall page at ffff000
>> (d4) Detected Xen v4.9-unstable
>> (d4) xen: copy BIOS tables...
>> (d4) Copying SMBIOS entry point from 0x00010020 to 0x000f69b0
>> (d4) Copying MPTABLE from 0xfc001170/fc001180 to 0x000f68b0
>> (d4) Copying PIR from 0x00010040 to 0x000f6830
>> (d4) CPU Mhz=1335
>> (d4) Scan for VGA option rom
>> (d4) ATA controller 1 at 1f0/3f4/c100 (irq 14 dev 9)
>> (d4) ATA controller 2 at 170/374/c108 (irq 15 dev 9)
>> (d4) Found 0 lpt ports
>> (d4) Found 1 serial ports
>> (d4) PS2 keyboard initialized
>> (d4) All threads complete.
>> (d4) Scan for option roms
>> (d4) Running option rom at c000:0003
>> (d4) Searching bootorder for: /rom@genroms/linuxboot.bin
>> (d4) Searching bootorder for: HALT
>> (d4) Space available for UMB: c0800-ec800, f61d0-f67f0
>> (d4) Returned 258048 bytes of ZoneHigh
>> (d4) e820 map has 6 items:
>> (d4)   0: 0000000000000000 - 000000000009fc00 = 1 RAM
>> (d4)   1: 000000000009fc00 - 00000000000a0000 = 2 RESERVED
>> (d4)   2: 00000000000f0000 - 0000000000100000 = 2 RESERVED
>> (d4)   3: 0000000000100000 - 000000000ffff000 = 1 RAM
>> (d4)   4: 000000000ffff000 - 0000000010000000 = 2 RESERVED
>> (d4)   5: 00000000fc000000 - 0000000100000000 = 2 RESERVED
>> (d4) enter handle_19:
>> (d4)   NULL
>> (d4) Booting from ROM...
>> (d4) Booting from c000:00
>>
>>
>> Then (after 20 seconds) the kernel starts booting.
>> Any idea about this behavior?
>
> I am guessing one of the ROMs take a long time to run. It might be
> waiting for a timeout, like ipxe. Does anybody know about this issue?

The ipxe roms should only be loaded if specified in the VM config
file, right?  Why would you specify ipxe if you're going to be
direct-booting anyway?

 -George

_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xenproject.org
https://lists.xenproject.org/mailman/listinfo/xen-devel

Re: Slow HVM boot time, was "HVM boot time optimization"

[Wei Liu]

On Thu, Feb 08, 2018 at 08:31:40AM -0800, Stefano Stabellini wrote:
> CC'ing xen-devel and a few relevant people
> 
> On Thu, 8 Feb 2018, Yessine Daoud wrote:
> > Dear Sir,
> > I need your help please.
> > 
> > I am using a direct kernel boot (HVM guest) with kernel + ramdisk.
> > At boot, seabios is bloqued about 20 seconds (or more) at the following state:
> > 

The manual seems a bit confusing to me but maybe I misremember how it
works. My understanding is direct kernel boot jumps straight to kernel
entry point without going through firmware.

If this is direct kernel boot why is seabios involved?

Wei.

_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xenproject.org
https://lists.xenproject.org/mailman/listinfo/xen-devel

Re: Slow HVM boot time, was "HVM boot time optimization"

[Anthony PERARD]

On Thu, Feb 08, 2018 at 04:48:10PM +0000, Wei Liu wrote:
> On Thu, Feb 08, 2018 at 08:31:40AM -0800, Stefano Stabellini wrote:
> > CC'ing xen-devel and a few relevant people
> > 
> > On Thu, 8 Feb 2018, Yessine Daoud wrote:
> > > Dear Sir,
> > > I need your help please.
> > > 
> > > I am using a direct kernel boot (HVM guest) with kernel + ramdisk.
> > > At boot, seabios is bloqued about 20 seconds (or more) at the following state:
> > > 
> 
> The manual seems a bit confusing to me but maybe I misremember how it
> works. My understanding is direct kernel boot jumps straight to kernel
> entry point without going through firmware.
> 
> If this is direct kernel boot why is seabios involved?

seabios is the one to load the kernel into memory and start it.

-- 
Anthony PERARD

_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xenproject.org
https://lists.xenproject.org/mailman/listinfo/xen-devel

Re: Slow HVM boot time, was "HVM boot time optimization"

[Wei Liu]

On Thu, Feb 08, 2018 at 04:56:00PM +0000, Anthony PERARD wrote:
> On Thu, Feb 08, 2018 at 04:48:10PM +0000, Wei Liu wrote:
> > On Thu, Feb 08, 2018 at 08:31:40AM -0800, Stefano Stabellini wrote:
> > > CC'ing xen-devel and a few relevant people
> > > 
> > > On Thu, 8 Feb 2018, Yessine Daoud wrote:
> > > > Dear Sir,
> > > > I need your help please.
> > > > 
> > > > I am using a direct kernel boot (HVM guest) with kernel + ramdisk.
> > > > At boot, seabios is bloqued about 20 seconds (or more) at the following state:
> > > > 
> > 
> > The manual seems a bit confusing to me but maybe I misremember how it
> > works. My understanding is direct kernel boot jumps straight to kernel
> > entry point without going through firmware.
> > 
> > If this is direct kernel boot why is seabios involved?
> 
> seabios is the one to load the kernel into memory and start it.
> 

I see. Thank for explaining.

Wei.

_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xenproject.org
https://lists.xenproject.org/mailman/listinfo/xen-devel

Re: Slow HVM boot time, was "HVM boot time optimization"

[Yessine Daoud]

[-- Attachment #1.1: Type: text/plain, Size: 1150 bytes --]

 Hello,

Thank you for your quick response.
Any hints how can I "fix" this "issue"? *Any workaround?

ᐧ

2018-02-08 18:32 GMT+01:00 Wei Liu <wei.liu2@citrix.com>:

> On Thu, Feb 08, 2018 at 04:56:00PM +0000, Anthony PERARD wrote:
> > On Thu, Feb 08, 2018 at 04:48:10PM +0000, Wei Liu wrote:
> > > On Thu, Feb 08, 2018 at 08:31:40AM -0800, Stefano Stabellini wrote:
> > > > CC'ing xen-devel and a few relevant people
> > > >
> > > > On Thu, 8 Feb 2018, Yessine Daoud wrote:
> > > > > Dear Sir,
> > > > > I need your help please.
> > > > >
> > > > > I am using a direct kernel boot (HVM guest) with kernel + ramdisk.
> > > > > At boot, seabios is bloqued about 20 seconds (or more) at the
> following state:
> > > > >
> > >
> > > The manual seems a bit confusing to me but maybe I misremember how it
> > > works. My understanding is direct kernel boot jumps straight to kernel
> > > entry point without going through firmware.
> > >
> > > If this is direct kernel boot why is seabios involved?
> >
> > seabios is the one to load the kernel into memory and start it.
> >
>
> I see. Thank for explaining.
>
> Wei.
>

[-- Attachment #1.2: Type: text/html, Size: 3487 bytes --]

[-- Attachment #2: Type: text/plain, Size: 157 bytes --]

_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xenproject.org
https://lists.xenproject.org/mailman/listinfo/xen-devel

Re: Slow HVM boot time, was "HVM boot time optimization"

[Wei Liu]

On Mon, Feb 12, 2018 at 09:27:25AM +0100, Yessine Daoud wrote:
>  Hello,
> 
> Thank you for your quick response.
> Any hints how can I "fix" this "issue"? *Any workaround?
> 

Honestly I have no idea why it is slow unless there is more logging
available.

Wei.

_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xenproject.org
https://lists.xenproject.org/mailman/listinfo/xen-devel

Re: Slow HVM boot time, was "HVM boot time optimization"

[Yessine Daoud]

[-- Attachment #1.1: Type: text/plain, Size: 1216 bytes --]

 Hello,

I tried to debug the issue and this what I found:
the HVM boot takes some time at the following section
(qemu/pc-bios/optionrom/linuxboot.S)
/* Load kernel and initrd */
read_fw_blob_addr32_edi(FW_CFG_INITRD) (ramdisk about 3M takes ~~7.s)
read_fw_blob_addr32(FW_CFG_KERNEL) (vmlinuz about 7M takes ~~15.s)
read_fw_blob_addr32(FW_CFG_CMDLINE)

#define read_fw_blob_addr32(var) \
read_fw var ## _ADDR; \
mov %eax, %edi; \
read_fw_blob_pre(var); \
/* old as(1) doesn't like this insn so emit the bytes instead: \
addr32 rep insb (%dx), %es:(%edi); \
*/ \
.dc.b 0x67,0xf3,0x6c

#define read_fw_blob_addr32_edi(var) \
read_fw_blob_pre(var); \
/* old as(1) doesn't like this insn so emit the bytes instead: \
addr32 rep insb (%dx), %es:(%edi); \
*/ \
.dc.b 0x67,0xf3,0x6c

Any idea how to speed the  I/O read ?
Thanks.


ᐧ

2018-02-12 15:42 GMT+01:00 Wei Liu <wei.liu2@citrix.com>:

> On Mon, Feb 12, 2018 at 09:27:25AM +0100, Yessine Daoud wrote:
> >  Hello,
> >
> > Thank you for your quick response.
> > Any hints how can I "fix" this "issue"? *Any workaround?
> >
>
> Honestly I have no idea why it is slow unless there is more logging
> available.
>
> Wei.
>

[-- Attachment #1.2: Type: text/html, Size: 8561 bytes --]

[-- Attachment #2: Type: text/plain, Size: 157 bytes --]

_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xenproject.org
https://lists.xenproject.org/mailman/listinfo/xen-devel

Re: Slow HVM boot time, was "HVM boot time optimization"

[Alexey G]

On Thu, 15 Feb 2018 17:02:35 +0100
Yessine Daoud <da.yessine@gmail.com> wrote:

> Hello,
>
>I tried to debug the issue and this what I found:
>the HVM boot takes some time at the following section
>(qemu/pc-bios/optionrom/linuxboot.S)
>/* Load kernel and initrd */
>read_fw_blob_addr32_edi(FW_CFG_INITRD) (ramdisk about 3M takes ~~7.s)
>read_fw_blob_addr32(FW_CFG_KERNEL) (vmlinuz about 7M takes ~~15.s)
>read_fw_blob_addr32(FW_CFG_CMDLINE)
>
>#define read_fw_blob_addr32(var) \
>read_fw var ## _ADDR; \
>mov %eax, %edi; \
>read_fw_blob_pre(var); \
>/* old as(1) doesn't like this insn so emit the bytes instead: \
>addr32 rep insb (%dx), %es:(%edi); \
>*/ \
>.dc.b 0x67,0xf3,0x6c
>
>#define read_fw_blob_addr32_edi(var) \
>read_fw_blob_pre(var); \
>/* old as(1) doesn't like this insn so emit the bytes instead: \
>addr32 rep insb (%dx), %es:(%edi); \
>*/ \
>.dc.b 0x67,0xf3,0x6c
>
>Any idea how to speed the  I/O read ?
>Thanks.

Hmm, looks like it does rep insb with every I/O iteration emulated
individually for some reason, hence its so slow. Normally it should be
emulated on a buffer basis. There might be a bug somewhere which cause
string I/O to be handled by every iteration.

You may try to collect QEMU trace logs using 
device_model_args = ["-trace", "events=<path to your events file>"]
Where the events file should contain lines like this:
xen_ioreq_server_create
xen_ioreq_server_destroy
xen_ioreq_server_state
xen_map_portio_range
xen_unmap_portio_range
cpu_ioreq_pio
cpu_ioreq_pio_read_reg
cpu_ioreq_pio_write_reg
handle_ioreq
handle_ioreq_read
handle_ioreq_write

The resulting log file in /var/log/xen might be large (may even require
to specify XEN_QEMU_CONSOLE_LIMIT=0) but will show how the string I/O
with port 510h is processed. This should narrow the issue.

_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xenproject.org
https://lists.xenproject.org/mailman/listinfo/xen-devel

Re: Slow HVM boot time, was "HVM boot time optimization"

[Alexey G]

On Fri, 16 Feb 2018 09:05:02 +0100
Yessine Daoud <da.yessine@gmail.com> wrote:

>Hello,
>
>Please find attached the requested log file.

According to the log, string I/O is actually passed from IOREQ buffered
-- in groups of 4096 I/O read ops, but they're still emulated one by
one, calling QEMU's fw_cfg emulation for every I/O byte -- that's the
reason of slow loading.

In order to speed up fw_cfg reading, I/O interface with fw_cfg should
be somehow replaced with a DMA one (fw_cfg_init_io_dma). SeaBIOS have
support for reading fw_cfg via emulated DMA, so switching to the
DMA-version of fw_cfg will allow to pass kernel files faster.

Basically, we need to replace the following line in xen_load_linux():
    fw_cfg = fw_cfg_init_io(FW_CFG_IO_BASE);
with:
    fw_cfg = fw_cfg_init_io_dma(FW_CFG_IO_BASE, FW_CFG_IO_BASE + 4,
                                &address_space_memory);

But this step might (at least) require few additional adjustments for
IOREQ_TYPE_COPY handling in xen-hvm.c -- looks like right now it's the
same 'for every single data item' loop like for buffered I/O processing.
However, unlike I/O processing this can be modified to feed
cpu_physical_memory_rw() with larger chunks of data thus reducing the
number of emulator calls.

>2018-02-16 3:08 GMT+01:00 Alexey G <x1917x@gmail.com>:
>
>> On Thu, 15 Feb 2018 17:02:35 +0100
>> Yessine Daoud <da.yessine@gmail.com> wrote:
>>  
>> > Hello,
>> >
>> >I tried to debug the issue and this what I found:
>> >the HVM boot takes some time at the following section
>> >(qemu/pc-bios/optionrom/linuxboot.S)
>> >/* Load kernel and initrd */
>> >read_fw_blob_addr32_edi(FW_CFG_INITRD) (ramdisk about 3M takes
>> >~~7.s) read_fw_blob_addr32(FW_CFG_KERNEL) (vmlinuz about 7M takes
>> >~~15.s) read_fw_blob_addr32(FW_CFG_CMDLINE)
>> >
>> >#define read_fw_blob_addr32(var) \
>> >read_fw var ## _ADDR; \
>> >mov %eax, %edi; \
>> >read_fw_blob_pre(var); \
>> >/* old as(1) doesn't like this insn so emit the bytes instead: \
>> >addr32 rep insb (%dx), %es:(%edi); \
>> >*/ \
>> >.dc.b 0x67,0xf3,0x6c
>> >
>> >#define read_fw_blob_addr32_edi(var) \
>> >read_fw_blob_pre(var); \
>> >/* old as(1) doesn't like this insn so emit the bytes instead: \
>> >addr32 rep insb (%dx), %es:(%edi); \
>> >*/ \
>> >.dc.b 0x67,0xf3,0x6c
>> >
>> >Any idea how to speed the  I/O read ?
>> >Thanks.  
>>
>> Hmm, looks like it does rep insb with every I/O iteration emulated
>> individually for some reason, hence its so slow. Normally it should
>> be emulated on a buffer basis. There might be a bug somewhere which
>> cause string I/O to be handled by every iteration.
>>
>> You may try to collect QEMU trace logs using
>> device_model_args = ["-trace", "events=<path to your events file>"]
>> Where the events file should contain lines like this:
>> xen_ioreq_server_create
>> xen_ioreq_server_destroy
>> xen_ioreq_server_state
>> xen_map_portio_range
>> xen_unmap_portio_range
>> cpu_ioreq_pio
>> cpu_ioreq_pio_read_reg
>> cpu_ioreq_pio_write_reg
>> handle_ioreq
>> handle_ioreq_read
>> handle_ioreq_write
>>
>> The resulting log file in /var/log/xen might be large (may even
>> require to specify XEN_QEMU_CONSOLE_LIMIT=0) but will show how the
>> string I/O with port 510h is processed. This should narrow the issue.
>>  


_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xenproject.org
https://lists.xenproject.org/mailman/listinfo/xen-devel