Synthetic Test Case =================== Create a Xenial KVM guest ---
mfo@rotom:~$ uvt-simplestreams-libvirt sync release=xenial arch=amd64 mfo@rotom:~$ uvt-kvm create --mem 4096 --cpu 2 --disk 16 mfo-sf194614 release=xenial arch=amd64 Modify the virsh XML to add a virtio-scsi controller + disk --- mfo@rotom:~$ virsh shutdown mfo-sf194614 mfo@rotom:~$ virsh edit mfo-sf194614 Check the virtio-scsi disk --- mfo@rotom:~$ virsh start mfo-sf194614 mfo@rotom:~$ uvt-kvm ssh mfo-sf194614 ubuntu@mfo-sf194614:~$ ls -ld /sys/block/sda lrwxrwxrwx 1 root root 0 Oct 13 14:22 /sys/block/sda -> ../devices/pci0000:00/0000:00:07.0/virtio3/host2/target2:0:1/2:0:1:0/block/sda ubuntu@mfo-sf194614:~$ lspci -s 7.0 00:07.0 SCSI storage controller: Red Hat, Inc Virtio SCSI Check the SCSI logging for a dd one block transfer + TUR (test-unit-ready) --- root@mfo-sf194614:~# apt-get install sg3-utils root@mfo-sf194614:~# scsi_logging_level --set --mlqueue=4 --mlcomplete=2 root@mfo-sf194614:~# dd if=/dev/sda of=/dev/null count=1 [ 557.084898] sd 2:0:1:0: [sda] tag#1 Send: scmd 0xffff880139fe14f0 [ 557.088133] sd 2:0:1:0: [sda] tag#1 CDB: Read(10) 28 00 00 00 00 00 00 00 20 00 [ 557.093154] sd 2:0:1:0: [sda] tag#1 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK [ 557.097336] sd 2:0:1:0: [sda] tag#1 CDB: Read(10) 28 00 00 00 00 00 00 00 20 00 [ 557.100955] sd 2:0:1:0: tag#1 Send: scmd 0xffff880139fe14f0 [ 557.103159] sd 2:0:1:0: tag#1 CDB: Test Unit Ready 00 00 00 00 00 00 [ 557.106005] sd 2:0:1:0: tag#1 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK [ 557.109498] sd 2:0:1:0: tag#1 CDB: Test Unit Ready 00 00 00 00 00 00 Synthetic reproducer (original kernel) --- root@mfo-sf194614:~# uname -a Linux mfo-sf194614 4.4.0-138-generic #164-Ubuntu SMP Tue Oct 2 17:16:02 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux root@mfo-sf194614:~# cat /sys/module/virtio_scsi/sections/.text 0xffffffffc001c000 Start GDB server in QEMU: mfo@rotom:~$ virsh qemu-monitor-command mfo-sf194614 --hmp 'gdbserver' Waiting for gdb connection on device 'tcp::1234' Get kernel debug symbols: mfo@rotom:~/ddebs$ wget http://ddebs.ubuntu.com/pool/main/l/linux/linux-image-4.4.0-138-generic-dbgsym_4.4.0-138.164_amd64.ddeb mfo@rotom:~/ddebs$ dpkg-deb -x linux-image-4.4.0-138-generic-dbgsym_4.4.0-138.164_amd64.ddeb linux-image-4.4.0-138-generic-dbgsym_4.4.0-138.164_amd64 mfo@rotom:~/ddebs$ cd linux-image-4.4.0-138-generic-dbgsym_4.4.0-138.164_amd64/usr/lib/debug Attach GDB: $ gdb boot/vmlinux-4.4.0-138-generic \ -ex 'set confirm off' \ -ex 'add-symbol-file lib/modules/4.4.0-138-generic/kernel/drivers/scsi/virtio_scsi.ko 0xffffffffc001c000' \ -ex 'break virtscsi_queuecommand' \ -ex 'target remote localhost:1234' \ -ex 'continue' Run dd: root@mfo-sf194614:~# dd if=/dev/sda of=/dev/null count=1 2>/dev/null <freeze> [ 1271.471568] sd 2:0:1:0: [sda] tag#1 Send: scmd 0xffff880139fe14f0 [ 1271.474633] sd 2:0:1:0: [sda] tag#1 CDB: Read(10) 28 00 00 00 00 00 00 00 20 00 <freeze> Back to GDB: Thread 1 hit Breakpoint 1, virtscsi_queuecommand (vscsi=0xffff880036eb07d8, req_vq=0xffff880036eb09e8, sc=0xffff880139fe14f0) at /build/linux-zdslHp/linux-4.4.0/drivers/scsi/virtio_scsi.c:534 534 /build/linux-zdslHp/linux-4.4.0/drivers/scsi/virtio_scsi.c: No such file or directory. (gdb) Add breakpoint to the point where the SCSI command request is to be added into the virtio ring: @ virtio_ring.c 129: static inline int virtqueue_add(struct virtqueue *_vq, ... 196: 197: if (vq->vq.num_free < descs_used) { (gdb) break virtio_ring.c:196 Breakpoint 2 at 0xffffffff814e323f: virtio_ring.c:196. (3 locations) (gdb) info break Num Type Disp Enb Address What 1 breakpoint keep y 0xffffffffc001d330 in virtscsi_queuecommand at /build/linux-zdslHp/linux-4.4.0/drivers/scsi/virtio_scsi.c:534 breakpoint already hit 1 time 2 breakpoint keep y <MULTIPLE> 2.1 y 0xffffffff814e323f in virtqueue_add_sgs at /build/linux-zdslHp/linux-4.4.0/drivers/virtio/virtio_ring.c:196 2.2 y 0xffffffff814e37ec in virtqueue_add_inbuf at /build/linux-zdslHp/linux-4.4.0/drivers/virtio/virtio_ring.c:196 2.3 y 0xffffffff814e3a9c in virtqueue_add_outbuf at /build/linux-zdslHp/linux-4.4.0/drivers/virtio/virtio_ring.c:196 (gdb) disable 1 (gdb) disable 2.2 (gdb) disable 2.3 (gdb) continue Thread 1 hit Breakpoint 2, virtqueue_add (gfp=<optimized out>, data=<optimized out>, in_sgs=<optimized out>, out_sgs=<optimized out>, total_sg=<optimized out>, sgs=<optimized out>, _vq=<optimized out>) at /build/linux-zdslHp/linux-4.4.0/drivers/virtio/virtio_ring.c:197 Check the point where the comparison above (in line 197) is done: (gdb) disass ... => 0xffffffff814e323f <+175>: cmp %ecx,%ebx 0xffffffff814e3241 <+177>: ja 0xffffffff814e3415 <virtqueue_add_sgs+645> Check and modify the registers (ECX is num_free, EBX is descs_used): (gdb) info reg $ecx $ebx ecx 0x80 128 ebx 0x1 1 (gdb) set $ecx = 0 (gdb) info reg $ecx $ebx ecx 0x0 0 ebx 0x1 1 Now we just faked that there are no num_free entries in the queue/ring. Which will cause the SCSI command requeue. Let's set a breakpoint for the target removal point now, and resume the guest. (gdb) disable 2.1 (gdb) break virtscsi_target_destroy (gdb) continue In the guest, we see the SCSI command was first rejected, then re-sent, then it succeeded normally. [ 1271.471568] sd 2:0:1:0: [sda] tag#1 Send: scmd 0xffff880139fe14f0 [ 1271.474633] sd 2:0:1:0: [sda] tag#1 CDB: Read(10) 28 00 00 00 00 00 00 00 20 00 <freeze> [ 1271.481964] sd 2:0:1:0: [sda] tag#1 queuecommand : request rejected [ 1271.511692] scsi host2: unblocking host at zero depth [ 1271.514607] sd 2:0:1:0: [sda] tag#1 Send: scmd 0xffff880139fe14f0 [ 1271.517870] sd 2:0:1:0: [sda] tag#1 CDB: Read(10) 28 00 00 00 00 00 00 00 20 00 [ 1271.525639] sd 2:0:1:0: [sda] tag#1 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK [ 1271.531594] sd 2:0:1:0: [sda] tag#1 CDB: Read(10) 28 00 00 00 00 00 00 00 20 00 [ 1271.535696] sd 2:0:1:0: tag#0 Send: scmd 0xffff880139fe0170 [ 1271.538885] sd 2:0:1:0: tag#0 CDB: Test Unit Ready 00 00 00 00 00 00 [ 1271.543911] sd 2:0:1:0: tag#0 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK [ 1271.546548] sd 2:0:1:0: tag#0 CDB: Test Unit Ready 00 00 00 00 00 00 Now we trigger the virtio-scsi device removal from QEMU: mfo@rotom:~$ virsh qemu-monitor-command mfo-sf194614 --hmp 'device_del scsi1-0-1-0' [ 1511.698495] sd 2:0:1:0: [sda] Synchronizing SCSI cache ... [ 1511.738562] sd 2:0:1:0: [sda] Synchronize Cache(10) failed: Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK And go back to GDB: Thread 1 hit Breakpoint 3, virtscsi_target_destroy (starget=0xffff880036ebd800) at /build/linux-zdslHp/linux-4.4.0/drivers/scsi/virtio_scsi.c:787 787 /build/linux-zdslHp/linux-4.4.0/drivers/scsi/virtio_scsi.c: No such file or directory. (gdb) And let's get to the tgt-reqs counter value: (gdb) disass Dump of assembler code for function virtscsi_target_destroy: => 0xffffffffc001c020 <+0>: nopl 0x0(%rax,%rax,1) 0xffffffffc001c025 <+5>: push %rbp 0xffffffffc001c026 <+6>: mov 0x328(%rdi),%rdi 0xffffffffc001c02d <+13>: mov %rsp,%rbp 0xffffffffc001c030 <+16>: mov 0x4(%rdi),%eax 0xffffffffc001c033 <+19>: test %eax,%eax 0xffffffffc001c035 <+21>: je 0xffffffffc001c040 <virtscsi_target_destroy+32> 0xffffffffc001c037 <+23>: pause 0xffffffffc001c039 <+25>: mov 0x4(%rdi),%eax 0xffffffffc001c03c <+28>: test %eax,%eax 0xffffffffc001c03e <+30>: jne 0xffffffffc001c037 <virtscsi_target_destroy+23> 0xffffffffc001c040 <+32>: callq 0xffffffff811f6400 <kfree> 0xffffffffc001c045 <+37>: pop %rbp 0xffffffffc001c046 <+38>: retq End of assembler dump. (gdb) si (gdb) si (gdb) si (gdb) si (gdb) si (gdb) disass Dump of assembler code for function virtscsi_target_destroy: 0xffffffffc001c020 <+0>: nopl 0x0(%rax,%rax,1) 0xffffffffc001c025 <+5>: push %rbp 0xffffffffc001c026 <+6>: mov 0x328(%rdi),%rdi 0xffffffffc001c02d <+13>: mov %rsp,%rbp 0xffffffffc001c030 <+16>: mov 0x4(%rdi),%eax => 0xffffffffc001c033 <+19>: test %eax,%eax 0xffffffffc001c035 <+21>: je 0xffffffffc001c040 <virtscsi_target_destroy+32> 0xffffffffc001c037 <+23>: pause 0xffffffffc001c039 <+25>: mov 0x4(%rdi),%eax 0xffffffffc001c03c <+28>: test %eax,%eax 0xffffffffc001c03e <+30>: jne 0xffffffffc001c037 <virtscsi_target_destroy+23> 0xffffffffc001c040 <+32>: callq 0xffffffff811f6400 <kfree> 0xffffffffc001c045 <+37>: pop %rbp 0xffffffffc001c046 <+38>: retq End of assembler dump. And it's ONE, as we requeued a SCSI command ONE time. (gdb) info reg $eax eax 0x1 1 If we let the guest run, in the hopes that the req counter would eventually drop to zero, we find it never happens, and the QEMU process keeps spinning taking 100% / 1 CPU in the host: (gdb) disable 3 (gdb) continue $ pid=$(ps ax | grep qemu | grep mfo-sf194614 | cut -d' ' -f1) $ top -b -d 1 -n 10 -p $pid | grep qemu 38562 libvirt+ 20 0 6035792 399520 23564 S 106.7 0.3 6:21.47 qemu-system-x86 38562 libvirt+ 20 0 6035792 399520 23564 S 101.0 0.3 6:22.48 qemu-system-x86 38562 libvirt+ 20 0 6035792 399520 23564 S 101.0 0.3 6:23.49 qemu-system-x86 38562 libvirt+ 20 0 6035792 399520 23564 S 101.0 0.3 6:24.51 qemu-system-x86 38562 libvirt+ 20 0 6035792 399520 23564 S 101.0 0.3 6:25.52 qemu-system-x86 38562 libvirt+ 20 0 6035792 399520 23564 S 102.0 0.3 6:26.54 qemu-system-x86 38562 libvirt+ 20 0 6035792 399520 23564 S 101.0 0.3 6:27.55 qemu-system-x86 38562 libvirt+ 20 0 6035792 399520 23564 S 102.0 0.3 6:28.57 qemu-system-x86 38562 libvirt+ 20 0 6035792 399520 23564 S 100.0 0.3 6:29.58 qemu-system-x86 38562 libvirt+ 20 0 6035792 399520 23564 S 101.0 0.3 6:30.59 qemu-system-x86 Now, let's pause the guest from GDB and modify the reqs value to zero: (gdb) c Continuing. ^C Thread 1 received signal SIGINT, Interrupt. virtscsi_target_destroy (starget=<optimized out>) at /build/linux-zdslHp/linux-4.4.0/drivers/scsi/virtio_scsi.c:791 791 in /build/linux-zdslHp/linux-4.4.0/drivers/scsi/virtio_scsi.c (gdb) disass Dump of assembler code for function virtscsi_target_destroy: 0xffffffffc001c020 <+0>: nopl 0x0(%rax,%rax,1) 0xffffffffc001c025 <+5>: push %rbp 0xffffffffc001c026 <+6>: mov 0x328(%rdi),%rdi 0xffffffffc001c02d <+13>: mov %rsp,%rbp 0xffffffffc001c030 <+16>: mov 0x4(%rdi),%eax 0xffffffffc001c033 <+19>: test %eax,%eax 0xffffffffc001c035 <+21>: je 0xffffffffc001c040 <virtscsi_target_destroy+32> 0xffffffffc001c037 <+23>: pause => 0xffffffffc001c039 <+25>: mov 0x4(%rdi),%eax 0xffffffffc001c03c <+28>: test %eax,%eax 0xffffffffc001c03e <+30>: jne 0xffffffffc001c037 <virtscsi_target_destroy+23> 0xffffffffc001c040 <+32>: callq 0xffffffff811f6400 <kfree> 0xffffffffc001c045 <+37>: pop %rbp 0xffffffffc001c046 <+38>: retq End of assembler dump. (gdb) si 791 in /build/linux-zdslHp/linux-4.4.0/drivers/scsi/virtio_scsi.c (gdb) set $eax = 0 (gdb) continue Now the guest resumes responding to keyboard / working normally, and QEMU is no longer taking 100% / 1 CPU of the host. With the PATCHED KERNEL: --- root@mfo-sf194614:~# uname -a Linux mfo-sf194614 4.4.0-138-generic #164+forTESTING.sf194614.1 SMP Sat Oct 13 13:20:35 -03 2018 x86_64 x86_64 x86_64 GNU/Linux QEMU monitor device_del after fresh reboot (check for regressions without requeued SCSI commands): All OK. CPU stays low. not looping. mfo@rotom:~/sf194614$ top -b -d 1 -n 10 -p $pid | grep qemu 55683 libvirt+ 20 0 5241060 401584 23160 S 0.0 0.3 0:10.97 qemu-system-x86 55683 libvirt+ 20 0 5241060 401584 23160 S 0.0 0.3 0:10.97 qemu-system-x86 55683 libvirt+ 20 0 5241060 401584 23160 S 1.0 0.3 0:10.98 qemu-system-x86 55683 libvirt+ 20 0 5241060 401584 23160 S 0.0 0.3 0:10.98 qemu-system-x86 55683 libvirt+ 20 0 5241060 401584 23160 S 0.0 0.3 0:10.98 qemu-system-x86 Testcase: <same procedure in GDB, check for virtio-scsi module .text section address, cause the SCSI command requeue, etc.> [ 178.039058] sd 2:0:1:0: [sda] tag#0 Send: scmd 0xffff880139f30170 [ 178.042039] sd 2:0:1:0: [sda] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 20 00 <freeze> [ 178.049500] sd 2:0:1:0: [sda] tag#0 queuecommand : request rejected [ 178.081789] scsi host2: unblocking host at zero depth [ 178.084185] sd 2:0:1:0: [sda] tag#0 Send: scmd 0xffff880139f30170 [ 178.086683] sd 2:0:1:0: [sda] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 20 00 [ 178.088764] sd 2:0:1:0: [sda] tag#0 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK [ 178.090952] sd 2:0:1:0: [sda] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 20 00 [ 178.092897] sd 2:0:1:0: tag#0 Send: scmd 0xffff880139f30170 [ 178.094696] sd 2:0:1:0: tag#0 CDB: Test Unit Ready 00 00 00 00 00 00 [ 178.096462] sd 2:0:1:0: tag#0 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK [ 178.099108] sd 2:0:1:0: tag#0 CDB: Test Unit Ready 00 00 00 00 00 00 And in GDB we can confirm that the tgt->reqs counter is zero, even with the SCSI command requeue: Thread 1 hit Breakpoint 3, virtscsi_target_destroy (starget=0xffff880139a42400) at /home/ubuntu/sf194614/linux-4.4.0/drivers/scsi/virtio_scsi.c:793 793 /home/ubuntu/sf194614/linux-4.4.0/drivers/scsi/virtio_scsi.c: No such file or directory. (gdb) si (gdb) (gdb) (gdb) (gdb) (gdb) disass Dump of assembler code for function virtscsi_target_destroy: 0xffffffffc001c020 <+0>: nopl 0x0(%rax,%rax,1) 0xffffffffc001c025 <+5>: push %rbp 0xffffffffc001c026 <+6>: mov 0x328(%rdi),%rdi 0xffffffffc001c02d <+13>: mov %rsp,%rbp 0xffffffffc001c030 <+16>: mov 0x4(%rdi),%eax => 0xffffffffc001c033 <+19>: test %eax,%eax 0xffffffffc001c035 <+21>: je 0xffffffffc001c040 <virtscsi_target_destroy+32> 0xffffffffc001c037 <+23>: pause 0xffffffffc001c039 <+25>: mov 0x4(%rdi),%eax 0xffffffffc001c03c <+28>: test %eax,%eax 0xffffffffc001c03e <+30>: jne 0xffffffffc001c037 <virtscsi_target_destroy+23> 0xffffffffc001c040 <+32>: callq 0xffffffff811f6400 <kfree> 0xffffffffc001c045 <+37>: pop %rbp 0xffffffffc001c046 <+38>: retq End of assembler dump. (gdb) info reg $eax eax 0x0 0 And the guest finishes that function, as expected, and the SCSi target removal ends. (gdb) continue [ 221.376878] sd 2:0:1:0: [sda] Synchronizing SCSI cache ... [ 221.419942] sd 2:0:1:0: [sda] Synchronize Cache(10) failed: Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK The guest responds normally and does not go to 100% CPU. mfo@rotom:~/sf194614$ pid=$(ps ax | grep qemu | grep mfo-sf194614 | cut -d' ' -f1) mfo@rotom:~/sf194614$ top -b -d 1 -n 10 -p $pid | grep qemu 55807 libvirt+ 20 0 5375216 410616 23304 S 0.0 0.3 0:14.54 qemu-system-x86 55807 libvirt+ 20 0 5375216 410616 23304 S 1.0 0.3 0:14.55 qemu-system-x86 55807 libvirt+ 20 0 5375216 410616 23304 S 0.0 0.3 0:14.55 qemu-system-x86 55807 libvirt+ 20 0 5375216 410616 23304 S 0.0 0.3 0:14.55 qemu-system-x86 55807 libvirt+ 20 0 5375216 410616 23304 S 1.0 0.3 0:14.56 qemu-system-x86 55807 libvirt+ 20 0 5375216 410616 23304 S 0.0 0.3 0:14.56 qemu-system-x86 55807 libvirt+ 20 0 5375216 410616 23304 S 0.0 0.3 0:14.56 qemu-system-x86 55807 libvirt+ 20 0 5375216 410616 23304 S 0.0 0.3 0:14.56 qemu-system-x86 55807 libvirt+ 20 0 5375216 410616 23304 S 0.0 0.3 0:14.56 qemu-system-x86 55807 libvirt+ 20 0 5375216 410616 23304 S 0.0 0.3 0:14.56 qemu-system-x86 ** Changed in: linux (Ubuntu) Status: Incomplete => Confirmed -- You received this bug notification because you are a member of Kernel Packages, which is subscribed to linux in Ubuntu. https://bugs.launchpad.net/bugs/1798110 Title: xenial: virtio-scsi: CPU soft lockup due to loop in virtscsi_target_destroy() Status in linux package in Ubuntu: Confirmed Bug description: (I'll add the SRU template + testing steps and post to ML shortly.) A customer reported a CPU soft lockup on Trusty HWE kernel from Xenial when detaching a virtio-scsi drive, and provided a crashdump that shows 2 things: 1) The soft locked up CPU is waiting for another CPU to finish something, and that does not happen because the other CPU is infinitely looping in virtscsi_target_destroy(). 2) The loop happens because the 'tgt->reqs' counter is non-zero, and that probably happened due to a missing decrement in SCSI command requeue path, exercised when the virtio ring is full. The reported problem itself happens because of a downstream/SAUCE patch, coupled with the problem of the missing decrement for the reqs counter. Introducing a decrement in the SCSI command requeue path resolves the problem, verified synthetically with QEMU+GDB and with test-case/loop provided by the customer as problem reproducer. To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1798110/+subscriptions -- Mailing list: https://launchpad.net/~kernel-packages Post to : kernel-packages@lists.launchpad.net Unsubscribe : https://launchpad.net/~kernel-packages More help : https://help.launchpad.net/ListHelp
