[bug report] IO blocked after offline CPU during fio on nvme SSD

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Hi
I found this issue during my NVMe test on 4.17.0-rc7, here is the reproducer and dmesg log, let me know if you need more info, thanks.

Reproduce steps:
#!/bin/bash
set -x
fio -filename=/dev/nvme0n1p1 -iodepth=1 -thread -rw=randwrite -ioengine=psync -bssplit=5k/10:9k/10:13k/10:17k/10:21k/10:25k/10:29k/10:33k/10:37k/10:41k/10 -direct=1 -runtime=120 -size=-group_reporting -name=mytest -numjobs=60 &
sleep 10
echo 0 > /sys/devices/system/cpu/cpu1/online
echo 0 > /sys/devices/system/cpu/cpu2/online
echo 0 > /sys/devices/system/cpu/cpu3/online

dmesg log:
[  153.402709] IRQ 82: no longer affine to CPU1
[  153.408596] smpboot: CPU 1 is now offline
[  153.426422] IRQ 86: no longer affine to CPU2
[  153.431204] IRQ 89: no longer affine to CPU2
[  153.437054] smpboot: CPU 2 is now offline
[  153.682095] IRQ 83: no longer affine to CPU3
[  153.686866] IRQ 85: no longer affine to CPU3
[  153.692712] smpboot: CPU 3 is now offline
[  183.847661] nvme nvme0: I/O 417 QID 2 timeout, completion polled
[  183.854410] nvme nvme0: I/O 251 QID 7 timeout, completion polled
[  183.861133] nvme nvme0: I/O 252 QID 7 timeout, completion polled
[  183.867851] nvme nvme0: I/O 253 QID 7 timeout, aborting
[  183.873699] nvme nvme0: I/O 254 QID 7 timeout, aborting
[  183.879530] nvme nvme0: Abort status: 0x0
[  183.884017] nvme nvme0: I/O 255 QID 7 timeout, aborting
[  183.889847] nvme nvme0: Abort status: 0x0
[  183.894338] nvme nvme0: I/O 495 QID 8 timeout, completion polled
[  183.901033] nvme nvme0: Abort status: 0x0
[  183.905520] nvme nvme0: I/O 496 QID 8 timeout, aborting
[  183.911359] nvme nvme0: I/O 497 QID 8 timeout, aborting
[  183.917190] nvme nvme0: Abort status: 0x0
[  183.921677] nvme nvme0: I/O 498 QID 8 timeout, aborting
[  183.927506] nvme nvme0: Abort status: 0x0
[  183.931994] nvme nvme0: I/O 499 QID 8 timeout, aborting
[  183.937825] nvme nvme0: Abort status: 0x0
[  183.942311] nvme nvme0: I/O 500 QID 8 timeout, aborting
[  183.948141] nvme nvme0: Abort status: 0x0
[  183.952637] nvme nvme0: Abort status: 0x0
[  214.057408] nvme nvme0: I/O 253 QID 7 timeout, reset controller
[  216.422702] nvme nvme0: I/O 254 QID 7 timeout, disable controller
[  216.438524] nvme nvme0: I/O 255 QID 7 timeout, disable controller
[  216.453428] nvme nvme0: I/O 496 QID 8 timeout, disable controller
[  216.469426] nvme nvme0: I/O 497 QID 8 timeout, disable controller
[  216.484435] nvme nvme0: I/O 498 QID 8 timeout, disable controller
[  216.496417] nvme nvme0: I/O 499 QID 8 timeout, disable controller
[  216.511418] nvme nvme0: I/O 500 QID 8 timeout, disable controller
[  249.830165] nvme nvme0: I/O 253 QID 7 timeout, completion polled
[  249.836901] nvme nvme0: I/O 254 QID 7 timeout, disable controller
[  249.858307] nvme nvme0: I/O 255 QID 7 timeout, disable controller
[  249.874172] nvme nvme0: I/O 496 QID 8 timeout, disable controller
[  249.887164] nvme nvme0: I/O 497 QID 8 timeout, disable controller
[  249.903175] nvme nvme0: I/O 498 QID 8 timeout, disable controller
[  249.918171] nvme nvme0: I/O 499 QID 8 timeout, disable controller
[  249.934172] nvme nvme0: I/O 500 QID 8 timeout, disable controller
[  369.695234] INFO: task kworker/u25:8:472 blocked for more than 120 seconds.
[  369.703012]       Not tainted 4.17.0-rc7 #1
[  369.707687] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  369.716433] kworker/u25:8   D    0   472      2 0x80000000
[  369.716443] Workqueue: nvme-reset-wq nvme_reset_work [nvme]
[  369.716445] Call Trace:
[  369.719189]  ? __schedule+0x290/0x870
[  369.723280]  schedule+0x32/0x80
[  369.726791]  blk_mq_freeze_queue_wait+0x46/0xb0
[  369.731853]  ? remove_wait_queue+0x60/0x60
[  369.736435]  nvme_wait_freeze+0x2e/0x50 [nvme_core]
[  369.741876]  nvme_reset_work+0x819/0xd83 [nvme]
[  369.746942]  ? __switch_to+0xa8/0x4f0
[  369.751035]  process_one_work+0x158/0x360
[  369.755513]  worker_thread+0x47/0x3e0
[  369.759604]  kthread+0xf8/0x130
[  369.763114]  ? max_active_store+0x80/0x80
[  369.767590]  ? kthread_bind+0x10/0x10
[  369.771673]  ret_from_fork+0x35/0x40
[  369.775687] INFO: task fio:1826 blocked for more than 120 seconds.
[  369.782588]       Not tainted 4.17.0-rc7 #1
[  369.787259] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  369.796002] fio             D    0  1826      1 0x00000080
[  369.796004] Call Trace:
[  369.798736]  ? __schedule+0x290/0x870
[  369.802826]  schedule+0x32/0x80
[  369.806338]  io_schedule+0x12/0x40
[  369.810139]  __blkdev_direct_IO_simple+0x1d3/0x310
[  369.815493]  ? bdput+0x10/0x10
[  369.818905]  blkdev_direct_IO+0x38e/0x3f0
[  369.823383]  ? __blkdev_direct_IO_simple+0x254/0x310
[  369.828929]  generic_file_direct_write+0xcc/0x170
[  369.834187]  __generic_file_write_iter+0xb7/0x1c0
[  369.839441]  blkdev_write_iter+0x9b/0x120
[  369.843923]  __vfs_write+0x100/0x180
[  369.847917]  vfs_write+0xad/0x1a0
[  369.851622]  ? __audit_syscall_exit+0x213/0x330
[  369.856682]  ksys_pwrite64+0x62/0x90
[  369.860677]  do_syscall_64+0x5b/0x180
[  369.864769]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  369.870411] RIP: 0033:0x7f42e0955073
[  369.874403] RSP: 002b:00007f42ba189b60 EFLAGS: 00000293 ORIG_RAX: 0000000000000012
[  369.882856] RAX: ffffffffffffffda RBX: 00007f429c00cd40 RCX: 00007f42e0955073
[  369.890823] RDX: 0000000000008c00 RSI: 00007f429c001000 RDI: 000000000000001f
[  369.898791] RBP: 00007f42bf195000 R08: 00000000001fc000 R09: 0000000000000007
[  369.906757] R10: 0000005bb1581800 R11: 0000000000000293 R12: 0000000000000001
[  369.914726] R13: 0000000000008c00 R14: 00007f429c00cd68 R15: 00007f42bf195008
[  369.922696] INFO: task fio:1827 blocked for more than 120 seconds.
[  369.929597]       Not tainted 4.17.0-rc7 #1
[  369.934275] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  369.943018] fio             D    0  1827      1 0x00000080
[  369.943020] Call Trace:
[  369.945753]  ? __schedule+0x290/0x870
[  369.949844]  schedule+0x32/0x80
[  369.953355]  blk_queue_enter+0xea/0x1c0
[  369.957641]  ? remove_wait_queue+0x60/0x60
[  369.962216]  generic_make_request+0x45/0x390
[  369.966988]  ? iov_iter_get_pages+0xbe/0x2c0
[  369.971759]  ? __schedule+0x298/0x870
[  369.975849]  submit_bio+0x6e/0x130
[  369.979652]  ? bio_iov_iter_get_pages+0xdd/0x110
[  369.984809]  __blkdev_direct_IO_simple+0x183/0x310
[  369.990162]  ? bdput+0x10/0x10
[  369.993575]  blkdev_direct_IO+0x38e/0x3f0
[  369.998054]  ? common_interrupt+0xa/0xf
[  370.002340]  generic_file_direct_write+0xcc/0x170
[  370.007595]  __generic_file_write_iter+0xb7/0x1c0
[  370.012849]  blkdev_write_iter+0x9b/0x120
[  370.017330]  __vfs_write+0x100/0x180
[  370.021325]  vfs_write+0xad/0x1a0
[  370.025029]  ? __audit_syscall_exit+0x213/0x330
[  370.030089]  ksys_pwrite64+0x62/0x90
[  370.034082]  do_syscall_64+0x5b/0x180
[  370.038173]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  370.043816] RIP: 0033:0x7f42e0955073
[  370.047806] RSP: 002b:00007f42ba98ab60 EFLAGS: 00000293 ORIG_RAX: 0000000000000012
[  370.056260] RAX: ffffffffffffffda RBX: 00007f429400cd40 RCX: 00007f42e0955073
[  370.064229] RDX: 0000000000006400 RSI: 00007f4294001000 RDI: 000000000000002c
[  370.072197] RBP: 00007f42bf1add40 R08: 0000000003e00000 R09: 0000000000000005
[  370.080164] R10: 00000030c362a400 R11: 0000000000000293 R12: 0000000000000001
[  370.088132] R13: 0000000000006400 R14: 00007f429400cd68 R15: 00007f42bf1add48



Best Regards,
  Yi Zhang





[Index of Archives]     [Linux RAID]     [Linux SCSI]     [Linux ATA RAID]     [IDE]     [Linux Wireless]     [Linux Kernel]     [ATH6KL]     [Linux Bluetooth]     [Linux Netdev]     [Kernel Newbies]     [Security]     [Git]     [Netfilter]     [Bugtraq]     [Yosemite News]     [MIPS Linux]     [ARM Linux]     [Linux Security]     [Device Mapper]

  Powered by Linux