Hi,
Thanks for your analysis. It has definitely helped. With the right fixes, OSv can now properly boot on microvm with both block and networking devices.
qemu-system-x86_64 -M microvm,x-option-roms=off,pit=off,pic=off,rtc=off \
-enable-kvm -cpu host,+x2apic -m 64m -smp 1 \
-nodefaults -no-user-config -nographic -no-reboot \
-kernel loader.elf -append "--nopci /hello" \
-gdb tcp::1234,server,nowait \
-serial stdio \
-global virtio-mmio.force-legacy=off \
-device virtio-blk-device,id=blk0,drive=hd0,scsi=off \
-drive file=usr.img,if=none,id=hd0,cache=none
OSv v0.54.0-34-g55403bc8
Booted up in 3.56 ms
Cmdline: /hello
Hello from C code
real 0m0.051s
user 0m0.039s
sys 0m0.008s
On average it takes around 4ms to boot OSv with a single block device. On average the same example boots 20% faster than on firecracker which is great!!!
On another hand if I boot OSv image with a disk with ZFS filesystem on it it takes 350-550 ms to boot (mostly spent on mounting the filesystem which apparently requires far more interactions/exists than trivial ROFS). The lower number happens when the image is raw and higher when image is qcow2.
To compare with firecracker, the exact same OSv raw image boots in ~ 60ms - which is 6-9 times faster than microvm. What could be the culprit?
Waldek Kozaczuk <address@hidden> writes:
> Hi,
>
> In the last couple of days, I have been trying to run OSv (
> https://github.com/cloudius-systems/osv) on new microvm machine and I came
> across a problem I need some advice to solve.
>
> In short, when I try to boot OSv with a single block device, it properly
> detects and completes the 8-steps initialization phase per virtio spec.
> However, it gets stuck after the fist virtqueue kick when trying to read
> the partition block from disk. It appears that OSv never receives
> relevant interrupt and ends up waiting forever. At least this is my
> understanding.
>
> Here is the QEMU command line with all parameters and some diagnostic
> output from OSv (I added some extra debug statements to OSv):
>
> qemu-system-x86_64 -M microvm,x-option-roms=off,pit=off,pic=off,rtc=off \
> -enable-kvm -cpu host,+x2apic -m 64m -smp 1 \
> -kernel loader.elf -append "--nopci --verbose /hello" \
> -nodefaults -no-user-config -nographic -no-reboot \
> -gdb tcp::1234,server,nowait \
> -serial stdio \
> -device virtio-blk-device,id=blk0,drive=hd0,scsi=off \
> -drive file=usr.img,if=none,id=hd0,cache=none
>
> OSv v0.54.0-29-g3357ae07
> CmdLine: --nopci --verbose /hello virtio_mmio.device=512@0xc0000e00:12
> 1 CPUs detected
> Firmware vendor: Unknown
> bsd: initializing - done
> VFS: mounting ramfs at /
> VFS: mounting devfs at /dev
> net: initializing - done
> Detected virtio-mmio device: (2,17745)
> -> virtio_driver: device initialized
> -> virtio_driver: device reset
> -> virtio_driver: device acknowledged
> VIRTIO BLK INSTANCE 0
> -> virtio_driver: device is modern
> blk config: seg_max: 126
> blk config: geometry: 1058013192
> blk config: block size: 512
> blk config: wce: 0
> Queue[0] -> size 1024, paddr d23000
> -> virtio_driver: detected 1 queues
> blk: device setup with interrupt irq: 12!
> !! Kicking queue: 0 at 0xffff8000c0000e50
>
> And also part of the stack trace on OSv side that may help illustrate the
> problem:
> (gdb) osv thread 26
> (gdb) bt
> #0 sched::thread::switch_to (this=this@entry=0xffff8000001a7040) at
> arch/x64/arch-switch.hh:108
> #1 0x00000000403f7164 in sched::cpu::reschedule_from_interrupt
> (this=0xffff80000000a040,
> called_from_yield=called_from_yield@entry=false, preempt_after=...,
> preempt_after@entry=...) at core/sched.cc:339
> #2 0x00000000403f765c in sched::cpu::schedule () at
> include/osv/sched.hh:1310
> #3 0x00000000403f7d42 in sched::thread::wait
> (this=this@entry=0xffff800000d1c040)
> at core/sched.cc:1214
> #4 0x000000004041fa92 in sched::thread::do_wait_for<lockfree::mutex,
> sched::wait_object<waitqueue> > (mtx=...)
> at include/osv/mutex.h:41
> #5 sched::thread::wait_for<waitqueue&> (mtx=...) at
> include/osv/sched.hh:1220
> #6 waitqueue::wait (this=this@entry=0xffffa000008f9ea0, mtx=...) at
> core/waitqueue.cc:56
> #7 0x0000000040435ca3 in bio_wait (bio=bio@entry=0xffffa000008f9e00) at
> fs/vfs/kern_physio.cc:42
> #8 0x0000000040436449 in rw_buf (bp=bp@entry=0x408a71c0 <buf_table>,
> rw=rw@entry=0) at fs/vfs/vfs_bio.cc:133
> #9 0x00000000404368a2 in bread (dev=dev@entry=0xffffa00000cba100,
> blkno=blkno@entry=0, bpp=bpp@entry=0x200000100638)
> at fs/vfs/vfs_bio.cc:236
> #10 0x000000004043e96f in read_partition_table
> (dev=dev@entry=0xffffa00000cba100)
> at fs/devfs/device.cc:110
> #11 0x000000004037c2db in virtio::blk::blk (this=0xffffa000008e5c00,
> virtio_dev=...) at drivers/virtio-blk.cc:174
> #12 0x000000004037c439 in virtio::probe<virtio::blk, (unsigned short)2>
> (dev=<optimized out>) at ./drivers/device.hh:33
> #13 0x00000000403657ef in std::function<hw::hw_driver*
> (hw::hw_device*)>::operator()(hw::hw_device*) const (
> __args#0=<optimized out>, this=0x200000100820) at
> /usr/include/c++/8/bits/std_function.h:682
> #14 hw::driver_manager::<lambda(hw::hw_device*)>::operator()
> (__closure=0x2000001008c0, dev=0xffffa000008eb980)
> at drivers/driver.cc:40
> #15 std::_Function_handler<void(hw::hw_device*),
> hw::driver_manager::load_all()::<lambda(hw::hw_device*)> >::_M_invoke(const
> std::_Any_data &, hw::hw_device *&&) (__functor=..., __args#0=<optimized
> out>)
> at /usr/include/c++/8/bits/std_function.h:297
> #16 0x0000000040362ae3 in std::function<void
> (hw::hw_device*)>::operator()(hw::hw_device*) const (
> __args#0=<optimized out>, this=0x2000001008c0) at
> /usr/include/c++/8/bits/std_function.h:682
> #17 hw::device_manager::for_each_device(std::function<void
> (hw::hw_device*)>) (this=this@entry=0xffffa000008eb940,
> func=...) at drivers/device.cc:67
> #18 0x00000000403655a3 in hw::driver_manager::load_all
> (this=this@entry=0xffffa000008eb900)
> at /usr/include/c++/8/new:169
> #19 0x000000004038bffd in arch_init_drivers () at arch/x64/arch-setup.cc:293
> #20 0x000000004022b06b in do_main_thread (_main_args=0xffffa000008c40b2) at
> loader.cc:365
> #21 0x000000004045b7c6 in pthread_private::pthread::<lambda()>::operator()
> (__closure=0xffffa000008f9d00)
> at libc/pthread.cc:114
> #22 std::_Function_handler<void(), pthread_private::pthread::pthread(void*
> (*)(void*), void*, sigset_t, const
> pthread_private::thread_attr*)::<lambda()> >::_M_invoke(const
> std::_Any_data &) (__functor=...)
> at /usr/include/c++/8/bits/std_function.h:297
> #23 0x00000000403f8ae7 in sched::thread_main_c (t=0xffff800000d1c040) at
> arch/x64/arch-switch.hh:321
> #24 0x000000004039e7d3 in thread_main () at arch/x64/entry.S:113
> (gdb) osv thread 27
> (gdb) bt
> #0 sched::thread::switch_to (this=0xffff8000001a7040,
> this@entry=0xffff800000d1c040)
> at arch/x64/arch-switch.hh:108
> #1 0x00000000403f7164 in sched::cpu::reschedule_from_interrupt
> (this=0xffff80000000a040,
> called_from_yield=called_from_yield@entry=false, preempt_after=...,
> preempt_after@entry=...) at core/sched.cc:339
> #2 0x00000000403f765c in sched::cpu::schedule () at
> include/osv/sched.hh:1310
> #3 0x00000000403f7d42 in sched::thread::wait
> (this=this@entry=0xffff800000d2e040)
> at core/sched.cc:1214
> #4 0x000000004036c1c1 in
> sched::thread::do_wait_until<sched::noninterruptible,
> sched::thread::dummy_lock,
> virtio::virtio_driver::wait_for_queue(virtio::vring*, bool
> (virtio::vring::*)() const)::<lambda()> > (mtx=<synthetic pointer>...,
> pred=...) at drivers/virtio.cc:184
> #5
> sched::thread::wait_until<virtio::virtio_driver::wait_for_queue(virtio::vring*,
> bool (virtio::vring::*)() const)::<lambda()> > (pred=...) at
> include/osv/sched.hh:1077
> #6 virtio::virtio_driver::wait_for_queue (this=this@entry=0xffffa000008e5c00,
> queue=queue@entry=0xffffa000008f9c00,
> pred=<optimized out>) at drivers/virtio.cc:168
> #7 0x000000004037b7c5 in virtio::blk::req_done (this=<optimized out>) at
> drivers/virtio-blk.cc:238
> #8 0x000000004037ba6c in virtio::blk::<lambda()>::operator()
> (__closure=<optimized out>) at drivers/virtio-blk.cc:132
> #9 std::_Function_handler<void(),
> virtio::blk::blk(virtio::virtio_device&)::<lambda()> >::_M_invoke(const
> std::_Any_data &) (__functor=...) at
> /usr/include/c++/8/bits/std_function.h:297
> #10 0x00000000403f8ae7 in sched::thread_main_c (t=0xffff800000d2e040) at
> arch/x64/arch-switch.hh:321
> #11 0x000000004039e7d3 in thread_main () at arch/x64/entry.S:113
>
> For comparison, when I run the same image with a single block device on
> firecracker it works fine and the OSv output looks like this:
>
> OSv v0.54.0-29-g3357ae07
> CmdLine: --verbose --nopci /hello virtio_mmio.device=4K@0xd0000000:5
> 1 CPUs detected
> Firmware vendor: Unknown
> bsd: initializing - done
> VFS: mounting ramfs at /
> VFS: mounting devfs at /dev
> net: initializing - done
> Detected virtio-mmio device: (2,0)
> -> virtio_driver: device initialized
> -> virtio_driver: device reset
> -> virtio_driver: device acknowledged
> VIRTIO BLK INSTANCE 0
> setup_features: found feature intersec of bit 9
> setup_features: found feature intersec of bit 41
> -> virtio_driver: device is modern
> Queue[0] -> size 256, paddr d23000
> -> virtio_driver: detected 1 queues
> blk: device setup with interrupt irq: 5!
> !! Kicking queue: 0 at 0xffff8000d0000050
> ------> Acked
> virtio-blk: Add blk device instances 0 as vblk0, devsize=4360192
> random: intel drng, rdrand registered as a source.
> random: <Software, Yarrow> initialized
> VFS: unmounting /dev
> VFS: mounting rofs at /rofs
> virtio features: 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0 0 0 0
> 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0 0 0 0 0 1 0
> 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1
> !! Kicking queue: 0 at 0xffff8000d0000050
> ------> Acked
> !! Kicking queue: 0 at 0xffff8000d0000050
> ------> Acked
> !! Kicking queue: 0 at 0xffff8000d0000050
> ------> Acked
> VFS: mounting devfs at /dev
> VFS: mounting procfs at /proc
> VFS: mounting sysfs at /sys
> VFS: mounting ramfs at /tmp
> Booted up in 27.11 ms
> Cmdline: /hello
> !! Kicking queue: 0 at 0xffff8000d0000050
> ------> Acked
> !! Kicking queue: 0 at 0xffff8000d0000050
> ------> Acked
> Hello from C code
> VFS: unmounting /dev
> VFS: unmounting /proc
> VFS: unmounting /
> ROFS: spent 6.52 ms reading from disk
> ROFS: read 64 512-byte blocks from disk
> ROFS: allocated 61 512-byte blocks of cache memory
> ROFS: hit ratio is 93.02%
> Powering off.
>
> In the end, it makes me think there is some issue related to interrupts.
> Either wrong ones are used or misconfigured on OSv side or something else
> altogether.
>
> Like on firecracker OSv sets up GSI edge interrupts for QEMU microvm
> virtio-mmio devices but maybe it needs to use GSI level ones? Also, OSv
> works just fine with a traditional QEMU machine and PCI devices.
>
> Lastly, I tried to enable microvm pit and pic options - it did not make any
> difference.
>
> Any suggestions on what might be wrong? What would be the best way to debug
> it on QEMU side?
I gave OSv a quick try (it's been a while since the last time I played
with it), and noticed this:
OSv v0.54.0-26-gcccc7d40
1 CPUs detected
Firmware vendor: Unknown
bsd: initializing - done
VFS: mounting ramfs at /
VFS: mounting devfs at /dev
net: initializing - done
Detected virtio-mmio device: (2,17745)
Thread 1 "qemu-system-x86" hit Breakpoint 1, virtio_queue_notify_aio_vq (vq=0x555556ea4260)
at /root/qemu/hw/virtio/virtio.c:2232
2232 bool ret = false;
(gdb) n
2234 if (vq->vring.desc && vq->handle_aio_output) {
(gdb)
2245 return ret;
(gdb) p vq->vring.desc
$1 = 0
(gdb) p vq->vring
$2 = {num = 1024, num_default = 128, align = 4096, desc = 0, avail = 0, used = 0, caches = 0x0}
As you can see, QEMU receives the kick, but the VQ wasn't properly
initialized, so it will bail out instead of attempting to process the
request.
To get to this point, I've run QEMU with gdb and put a breakpoint on
virtio_queue_notify_aio_vq (you may need to rebuild with CFLAGS="-O0 -g"
to be able to follow the execution flow easily).
As you hinted the issue was in the configuration/initialization phase of the virtqueues. Let me explain what went wrong in the context of this virtio spec snippet:
"
4.2.3.2 Virtqueue ConfigurationThe driver will typically initialize the virtual queue in the following way:
- Select the queue writing its index (first queue is 0) to QueueSel.
- Check if the queue is not already in use: read QueueReady, and expect a returned value of zero (0x0).
- Read maximum queue size (number of elements) from QueueNumMax. If the returned value is zero (0x0) the queue is not available.
- Allocate and zero the queue pages, making sure the memory is physically contiguous. It is recommended to align the Used Ring to an optimal boundary (usually the page size).
- Notify the device about the queue size by writing the size to QueueNum.
- Write physical addresses of the queue’s Descriptor Table, Available Ring and Used Ring to (respectively) the QueueDescLow/QueueDescHigh, QueueAvailLow/QueueAvailHigh and QueueUsedLow/QueueUsedHigh register pairs.
- Write 0x1 to QueueReady."
So, in essence, OSv would iterate over all virtqueues until step 3 yields 0. BUT in each iteration, it would ONLY perform steps 1-to-6. After it discovered all queues, OSv would iterate over the identified queues again and execute steps 1, 2 and 7 to activate them. This apparently is tolerated by firecracker and as matter of fact the spec above says "driver will typically initialize" which seems to indicate that it is OK to initialize the virtqueus like OSv does. But apparently QEMU does not like it. So instead I have changed this logic in OSv to adhere to what "driver will typically initialize" sequence (1..7 in each iteration) and now it all works. Firecracker also accepts it.
In the end, the issue is that OSv doesn't support non-legacy virtio-mmio
devices (despite the check at "drivers/virtio-mmio.cc:121" does allow
for "version == 2" ;-), as described in version 1.0 of the VirtIO spec,
and microvm defaults to that model. You can work around the issue by
adding "-global virtio-mmio.force-legacy=off" to the QEMU command line,
but please consider implementing support for the non-legacy personality
(it's quite straightforward).
I think it is the other way - when I start QEMU without ' -global virtio-mmio.force-legacy=off' and add a debug statement to print the virtio version from the mmio configuration register, it shows "1" which indicates the legacy personality.
On another hand, if I add ' -global virtio-mmio.force-legacy=off' it prints "2" which indicates the modern personality.
OSv mmio implementation only handles the modern personality as firecracker does. QEMU microvm seems to be capable of presenting both.
But you are right on the account that OSv should not happily accept both 1 and 2, where in fact it only supports 2. And adding support of the legacy personality can be added to OSv fairly easily but is it worth it given it is legacy one?.
Also relatedly, I know there are parameters that could be added to PCI devices to make them behave as legacy, modern or transitional, for example - 'disable-legacy=off,disable-modern=on". Do the same parameters work with mmio devices with microvm machine? Or is ' -global virtio-mmio.force-legacy=off' the only way to turn legacy or modern personality?
Sergio.