Re: [Xen-devel] Slow HVM boot time, was "HVM boot time optimization"
On Fri, 16 Feb 2018 09:05:02 +0100 Yessine Daoud 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 : > >> On Thu, 15 Feb 2018 17:02:35 +0100 >> Yessine Daoud 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="] >> 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: [Xen-devel] Slow HVM boot time, was "HVM boot time optimization"
On Thu, 15 Feb 2018 17:02:35 +0100 Yessine Daoud 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="] 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: [Xen-devel] Slow HVM boot time, was "HVM boot time optimization"
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 : > 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: [Xen-devel] Slow HVM boot time, was "HVM boot time optimization"
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: [Xen-devel] Slow HVM boot time, was "HVM boot time optimization"
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 : > On Thu, Feb 08, 2018 at 04:56:00PM +, Anthony PERARD wrote: > > On Thu, Feb 08, 2018 at 04:48:10PM +, 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: [Xen-devel] Slow HVM boot time, was "HVM boot time optimization"
On Thu, Feb 08, 2018 at 04:56:00PM +, Anthony PERARD wrote: > On Thu, Feb 08, 2018 at 04:48:10PM +, 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: [Xen-devel] Slow HVM boot time, was "HVM boot time optimization"
On Thu, Feb 08, 2018 at 04:48:10PM +, 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: [Xen-devel] Slow HVM boot time, was "HVM boot time optimization"
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: [Xen-devel] Slow HVM boot time, was "HVM boot time optimization"
On Thu, Feb 8, 2018 at 4:31 PM, 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: >> >> (d4) RamSizeOver4G: 0x [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 000 >> (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: - 0009fc00 = 1 RAM >> (d4) 1: 0009fc00 - 000a = 2 RESERVED >> (d4) 2: 000f - 0010 = 2 RESERVED >> (d4) 3: 0010 - 0000 = 1 RAM >> (d4) 4: 0000 - 1000 = 2 RESERVED >> (d4) 5: fc00 - 0001 = 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
