Hi,
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?