* [Bug] block/for-next: IO hang in rq_qos_throttle
@ 2018-07-21 23:22 Ming Lei
2018-07-22 2:15 ` Josef Bacik
0 siblings, 1 reply; 8+ messages in thread
From: Ming Lei @ 2018-07-21 23:22 UTC (permalink / raw)
To: linux-block, Josef Bacik; +Cc: Ming Lei
Hi,
The following IO hang is triggered on dbench test on xfs/usb-storage,
and the test
is run on the latest for-next/block(commit 93d8cf625a32).
[ 497.775475] ================start test sanity/006================
[ 497.793059] sd 8:0:0:0: [sdd] Synchronizing SCSI cache
[ 499.658244] scsi host8: scsi_debug: version 0188 [20180128]
[ 499.658244] dev_size_mb=1024, opts=0x0, submit_queues=1, statistics=0
[ 499.660292] scsi 8:0:0:0: Direct-Access Linux scsi_debug
0188 PQ: 0 ANSI: 7
[ 499.661405] sd 8:0:0:0: Power-on or device reset occurred
[ 499.664165] sd 8:0:0:0: [sdd] 2097152 512-byte logical blocks:
(1.07 GB/1.00 GiB)
[ 499.666017] sd 8:0:0:0: [sdd] Write Protect is off
[ 499.666645] sd 8:0:0:0: [sdd] Mode Sense: 73 00 10 08
[ 499.669315] sd 8:0:0:0: [sdd] Write cache: enabled, read cache:
enabled, supports DPO and FUA
[ 499.693097] sd 8:0:0:0: [sdd] Attached SCSI disk
[ 500.538241] EXT4-fs (sdc): mounted filesystem with ordered data
mode. Opts: (null)
[ 525.642527] EXT4-fs (sdc): mounted filesystem with ordered data
mode. Opts: (null)
[ 550.256595] EXT4-fs (sdc): mounted filesystem with ordered data
mode. Opts: (null)
[ 574.781686] EXT4-fs (sdc): mounted filesystem with ordered data
mode. Opts: (null)
[ 609.888137] usb 1-1: reset high-speed USB device number 2 using ehci-pci
[ 640.608104] usb 1-1: reset high-speed USB device number 2 using ehci-pci
[ 641.765877] SGI XFS with ACLs, security attributes, realtime,
scrub, no debug enabled
[ 641.775402] XFS (sdc): Mounting V5 Filesystem
[ 641.880050] XFS (sdc): Ending clean mount
[ 666.193467] XFS (sdc): Unmounting Filesystem
[ 666.351521] XFS (sdc): Mounting V5 Filesystem
[ 666.409923] XFS (sdc): Ending clean mount
[ 690.848609] XFS (sdc): Unmounting Filesystem
[ 691.030587] XFS (sdc): Mounting V5 Filesystem
[ 691.487377] XFS (sdc): Ending clean mount
[ 861.151076] INFO: task kworker/3:0:28321 blocked for more than 120 seconds.
[ 861.152024] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
[ 861.152808] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 861.153802] kworker/3:0 D 0 28321 2 0x80000000
[ 861.154799] Workqueue: xfs-sync/sdc xfs_log_worker [xfs]
[ 861.155481] Call Trace:
[ 861.155811] ? __schedule+0x71e/0x783
[ 861.156281] schedule+0x7e/0x99
[ 861.156685] io_schedule+0x12/0x33
[ 861.157131] wbt_wait+0x23a/0x283
[ 861.157558] ? wait_woken+0x6d/0x6d
[ 861.158017] rq_qos_throttle+0x31/0x3c
[ 861.158520] blk_mq_make_request+0xe8/0x513
[ 861.159063] generic_make_request+0x1bc/0x328
[ 861.159631] ? xlog_bdstrat+0x15/0x4f [xfs]
[ 861.161486] ? submit_bio+0x103/0x11f
[ 861.161982] submit_bio+0x103/0x11f
[ 861.162591] ? bio_add_page+0x41/0x4a
[ 861.163191] _xfs_buf_ioapply+0x35c/0x3ee [xfs]
[ 861.163828] ? xlog_bdstrat+0x4a/0x4f [xfs]
[ 861.164571] ? xfs_buf_submit+0x177/0x1e8 [xfs]
[ 861.165294] ? xlog_bdstrat+0x4a/0x4f [xfs]
[ 861.165866] xfs_buf_submit+0x177/0x1e8 [xfs]
[ 861.166610] xlog_bdstrat+0x4a/0x4f [xfs]
[ 861.167268] xlog_sync+0x34a/0x450 [xfs]
[ 861.167813] xfs_log_force+0x16b/0x286 [xfs]
[ 861.168523] ? _raw_spin_unlock_irq+0x1d/0x2e
[ 861.169193] ? finish_task_switch+0x16d/0x21f
[ 861.169788] xfs_log_worker+0xdd/0xf4 [xfs]
[ 861.170503] process_one_work+0x1c9/0x2f6
[ 861.171118] ? rescuer_thread+0x282/0x282
[ 861.171653] worker_thread+0x1ca/0x295
[ 861.172297] kthread+0x115/0x11d
[ 861.172722] ? kthread_flush_work_fn+0xe/0xe
[ 861.173433] ret_from_fork+0x35/0x40
[ 861.173911] INFO: task dbench:28467 blocked for more than 120 seconds.
[ 861.174891] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
[ 861.175760] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 861.176832] dbench D 0 28467 28466 0x00000000
[ 861.177618] Call Trace:
[ 861.177941] ? __schedule+0x71e/0x783
[ 861.178542] schedule+0x7e/0x99
[ 861.178925] io_schedule+0x12/0x33
[ 861.179420] wbt_wait+0x23a/0x283
[ 861.179796] ? wait_woken+0x6d/0x6d
[ 861.180304] rq_qos_throttle+0x31/0x3c
[ 861.180736] blk_mq_make_request+0xe8/0x513
[ 861.181325] generic_make_request+0x1bc/0x328
[ 861.181811] ? submit_bio+0x103/0x11f
[ 861.182340] submit_bio+0x103/0x11f
[ 861.182762] ? xfs_setfilesize_trans_alloc+0x41/0x8c [xfs]
[ 861.183532] xfs_submit_ioend+0x111/0x11c [xfs]
[ 861.184150] xfs_vm_writepages+0x75/0x95 [xfs]
[ 861.184641] do_writepages+0x2d/0x51
[ 861.185191] __filemap_fdatawrite_range+0xc3/0xf1
[ 861.185713] file_write_and_wait_range+0x3e/0x6b
[ 861.186461] xfs_file_fsync+0xb9/0x1ef [xfs]
[ 861.187119] ? iomap_write_end+0x5d/0x5d
[ 861.187605] xfs_file_buffered_aio_write+0x28e/0x2bc [xfs]
[ 861.188346] __vfs_write+0x113/0x150
[ 861.188750] vfs_write+0xc8/0x16b
[ 861.189261] ksys_pwrite64+0x60/0x7d
[ 861.189659] do_syscall_64+0x84/0x13f
[ 861.190210] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 861.190784] RIP: 0033:0x7ff85f202e83
[ 861.191306] Code: Bad RIP value.
[ 861.191668] RSP: 002b:00007ffe90c48bf8 EFLAGS: 00000246 ORIG_RAX:
0000000000000012
[ 861.192619] RAX: ffffffffffffffda RBX: 0000000001ca8900 RCX: 00007ff85f202e83
[ 861.193470] RDX: 0000000000010000 RSI: 0000000001cbb2b0 RDI: 0000000000000005
[ 861.194367] RBP: 00000000000026d2 R08: 0000000000010000 R09: 0000000000000079
[ 861.195377] R10: 0000000000070000 R11: 0000000000000246 R12: 00007ff85f8f0000
[ 861.196230] R13: 0000000000010000 R14: 0000000000010000 R15: 0000000001cbb2b0
[ 861.197080] INFO: task dbench:28468 blocked for more than 120 seconds.
[ 861.197790] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
[ 861.198581] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 861.199496] dbench D 0 28468 28466 0x00000000
[ 861.200178] Call Trace:
[ 861.200458] ? __schedule+0x71e/0x783
[ 861.200878] schedule+0x7e/0x99
[ 861.201415] io_schedule+0x12/0x33
[ 861.201801] wbt_wait+0x23a/0x283
[ 861.202356] ? wait_woken+0x6d/0x6d
[ 861.202751] rq_qos_throttle+0x31/0x3c
[ 861.203297] blk_mq_make_request+0xe8/0x513
[ 861.203764] generic_make_request+0x1bc/0x328
[ 861.204369] ? submit_bio+0x103/0x11f
[ 861.204778] submit_bio+0x103/0x11f
[ 861.205313] ? xfs_setfilesize_trans_alloc+0x41/0x8c [xfs]
[ 861.205942] xfs_submit_ioend+0x111/0x11c [xfs]
[ 861.206629] xfs_vm_writepages+0x75/0x95 [xfs]
[ 861.207305] do_writepages+0x2d/0x51
[ 861.207701] __filemap_fdatawrite_range+0xc3/0xf1
[ 861.208340] file_write_and_wait_range+0x3e/0x6b
[ 861.208877] xfs_file_fsync+0xb9/0x1ef [xfs]
[ 861.209486] ? iomap_write_end+0x5d/0x5d
[ 861.209952] xfs_file_buffered_aio_write+0x28e/0x2bc [xfs]
[ 861.210757] __vfs_write+0x113/0x150
[ 861.211234] vfs_write+0xc8/0x16b
[ 861.211603] ksys_pwrite64+0x60/0x7d
[ 861.212129] do_syscall_64+0x84/0x13f
[ 861.212535] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 861.213217] RIP: 0033:0x7ff85f202e83
[ 861.213610] Code: Bad RIP value.
[ 861.213975] RSP: 002b:00007ffe90c48bf8 EFLAGS: 00000246 ORIG_RAX:
0000000000000012
[ 861.215138] RAX: ffffffffffffffda RBX: 0000000001ca8900 RCX: 00007ff85f202e83
[ 861.215940] RDX: 0000000000010000 RSI: 0000000001cbb2b0 RDI: 0000000000000005
[ 861.216834] RBP: 00000000000026d2 R08: 0000000000010000 R09: 0000000000000079
[ 861.217708] R10: 0000000000070000 R11: 0000000000000246 R12: 00007ff85f8f0228
[ 861.218658] R13: 0000000000010000 R14: 0000000000010000 R15: 0000000001cbb2b0
[ 861.219519] INFO: task dbench:28469 blocked for more than 120 seconds.
[ 861.220298] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
[ 861.220980] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 861.221950] dbench D 0 28469 28466 0x00000000
[ 861.222616] Call Trace:
[ 861.222903] ? __schedule+0x71e/0x783
[ 861.223449] schedule+0x7e/0x99
[ 861.223809] io_schedule+0x12/0x33
[ 861.224311] wbt_wait+0x23a/0x283
[ 861.224681] ? wait_woken+0x6d/0x6d
[ 861.225198] rq_qos_throttle+0x31/0x3c
[ 861.225612] blk_mq_make_request+0xe8/0x513
[ 861.226232] generic_make_request+0x1bc/0x328
[ 861.226715] ? _raw_spin_lock_irqsave+0x25/0x46
[ 861.227431] ? submit_bio+0x103/0x11f
[ 861.227841] submit_bio+0x103/0x11f
[ 861.228341] ? bio_alloc_bioset+0x10d/0x1d8
[ 861.228805] submit_bio_wait+0x53/0x7f
[ 861.229348] blkdev_issue_flush+0x81/0xa5
[ 861.229826] xfs_file_fsync+0x1c2/0x1ef [xfs]
[ 861.230446] ? iomap_write_end+0x5d/0x5d
[ 861.230922] xfs_file_buffered_aio_write+0x28e/0x2bc [xfs]
[ 861.231643] __vfs_write+0x113/0x150
[ 861.232121] vfs_write+0xc8/0x16b
[ 861.232489] ksys_pwrite64+0x60/0x7d
[ 861.232888] do_syscall_64+0x84/0x13f
[ 861.233480] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 861.234110] RIP: 0033:0x7ff85f202e83
[ 861.234583] Code: Bad RIP value.
[ 861.235152] RSP: 002b:00007ffe90c48bf8 EFLAGS: 00000246 ORIG_RAX:
0000000000000012
[ 861.235992] RAX: ffffffffffffffda RBX: 0000000001ca8900 RCX: 00007ff85f202e83
[ 861.236895] RDX: 0000000000010000 RSI: 0000000001cbb2b0 RDI: 0000000000000005
[ 861.237776] RBP: 00000000000026d2 R08: 0000000000010000 R09: 0000000000000079
[ 861.238764] R10: 0000000000040000 R11: 0000000000000246 R12: 00007ff85f8f0450
[ 861.239682] R13: 0000000000010000 R14: 0000000000010000 R15: 0000000001cbb2b0
[ 861.240534] INFO: task dbench:28470 blocked for more than 120 seconds.
[ 861.241407] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
[ 861.242244] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 861.243247] dbench D 0 28470 28466 0x00000000
[ 861.243843] Call Trace:
[ 861.244125] ? __schedule+0x71e/0x783
[ 861.244561] schedule+0x7e/0x99
[ 861.245007] __xfs_log_force_lsn+0x13d/0x283 [xfs]
[ 861.245624] ? wake_up_q+0x4d/0x4d
[ 861.246033] ? xfs_file_fsync+0x16d/0x1ef [xfs]
[ 861.246639] xfs_log_force_lsn+0xf7/0x12a [xfs]
[ 861.247254] xfs_file_fsync+0x16d/0x1ef [xfs]
[ 861.247817] ? iomap_write_end+0x5d/0x5d
[ 861.248321] xfs_file_buffered_aio_write+0x28e/0x2bc [xfs]
[ 861.248917] __vfs_write+0x113/0x150
[ 861.249314] vfs_write+0xc8/0x16b
[ 861.249678] ksys_pwrite64+0x60/0x7d
[ 861.250090] do_syscall_64+0x84/0x13f
[ 861.250569] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 861.251216] RIP: 0033:0x7ff85f202e83
[ 861.251619] Code: Bad RIP value.
[ 861.251981] RSP: 002b:00007ffe90c48bf8 EFLAGS: 00000246 ORIG_RAX:
0000000000000012
[ 861.252795] RAX: ffffffffffffffda RBX: 0000000001ca8900 RCX: 00007ff85f202e83
[ 861.253564] RDX: 0000000000010000 RSI: 0000000001cbb2b0 RDI: 0000000000000005
[ 861.254399] RBP: 00000000000026d2 R08: 0000000000010000 R09: 0000000000000079
[ 861.255301] R10: 0000000000050000 R11: 0000000000000246 R12: 00007ff85f8f0678
[ 861.256141] R13: 0000000000010000 R14: 0000000000010000 R15: 0000000001cbb2b0
[ 861.256913] INFO: task dbench:28471 blocked for more than 120 seconds.
[ 861.257721] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
[ 861.258503] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 861.259463] dbench D 0 28471 28466 0x00000000
[ 861.260066] Call Trace:
[ 861.260349] ? __schedule+0x71e/0x783
[ 861.260754] schedule+0x7e/0x99
[ 861.261105] io_schedule+0x12/0x33
[ 861.261477] blk_mq_get_tag+0x153/0x279
[ 861.261899] ? wait_woken+0x6d/0x6d
[ 861.262336] blk_mq_get_request+0x105/0x37e
[ 861.262876] blk_mq_make_request+0x171/0x513
[ 861.263410] generic_make_request+0x1bc/0x328
[ 861.263887] ? _raw_spin_lock_irqsave+0x25/0x46
[ 861.264391] ? submit_bio+0x103/0x11f
[ 861.264834] submit_bio+0x103/0x11f
[ 861.265287] ? bio_alloc_bioset+0x10d/0x1d8
[ 861.265827] submit_bio_wait+0x53/0x7f
[ 861.266279] blkdev_issue_flush+0x81/0xa5
[ 861.266821] xfs_file_fsync+0x1c2/0x1ef [xfs]
[ 861.267411] ? iomap_write_end+0x5d/0x5d
[ 861.267948] xfs_file_buffered_aio_write+0x28e/0x2bc [xfs]
[ 861.268612] __vfs_write+0x113/0x150
[ 861.269017] vfs_write+0xc8/0x16b
[ 861.269382] ksys_pwrite64+0x60/0x7d
[ 861.269806] do_syscall_64+0x84/0x13f
[ 861.270280] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 861.270926] RIP: 0033:0x7ff85f202e83
[ 861.271378] Code: Bad RIP value.
[ 861.271739] RSP: 002b:00007ffe90c48bf8 EFLAGS: 00000246 ORIG_RAX:
0000000000000012
[ 861.272554] RAX: ffffffffffffffda RBX: 0000000001ca8900 RCX: 00007ff85f202e83
[ 861.273417] RDX: 0000000000010000 RSI: 0000000001cbb2b0 RDI: 0000000000000005
[ 861.274322] RBP: 00000000000026d2 R08: 0000000000010000 R09: 0000000000000079
[ 861.275228] R10: 0000000000070000 R11: 0000000000000246 R12: 00007ff85f8f08a0
[ 861.276122] R13: 0000000000010000 R14: 0000000000010000 R15: 0000000001cbb2b0
[ 861.276895] INFO: task dbench:28472 blocked for more than 120 seconds.
[ 861.277697] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
[ 861.278495] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 861.279462] dbench D 0 28472 28466 0x00000000
[ 861.280067] Call Trace:
[ 861.280346] ? __schedule+0x71e/0x783
[ 861.280753] schedule+0x7e/0x99
[ 861.281105] schedule_timeout+0x3a/0x340
[ 861.281535] ? blk_queue_exit+0x5c/0x5e
[ 861.281959] ? generic_make_request+0x283/0x328
[ 861.282529] io_schedule_timeout+0x20/0x3d
[ 861.283065] wait_for_common_io.constprop.2+0x9d/0x120
[ 861.283657] ? wake_up_q+0x4d/0x4d
[ 861.284040] submit_bio_wait+0x5b/0x7f
[ 861.284452] blkdev_issue_flush+0x81/0xa5
[ 861.284972] xfs_file_fsync+0x1c2/0x1ef [xfs]
[ 861.285531] ? iomap_write_end+0x5d/0x5d
[ 861.286074] xfs_file_buffered_aio_write+0x28e/0x2bc [xfs]
[ 861.286783] __vfs_write+0x113/0x150
[ 861.287258] vfs_write+0xc8/0x16b
[ 861.287665] ksys_pwrite64+0x60/0x7d
[ 861.288137] do_syscall_64+0x84/0x13f
[ 861.288612] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 861.289168] RIP: 0033:0x7ff85f202e83
[ 861.289561] Code: Bad RIP value.
[ 861.289976] RSP: 002b:00007ffe90c48bf8 EFLAGS: 00000246 ORIG_RAX:
0000000000000012
[ 861.290927] RAX: ffffffffffffffda RBX: 0000000001ca8900 RCX: 00007ff85f202e83
[ 861.291750] RDX: 0000000000010000 RSI: 0000000001cbb2b0 RDI: 0000000000000005
[ 861.292514] RBP: 00000000000026d2 R08: 0000000000010000 R09: 0000000000000079
[ 861.293286] R10: 0000000000040000 R11: 0000000000000246 R12: 00007ff85f8f0ac8
[ 861.294059] R13: 0000000000010000 R14: 0000000000010000 R15: 0000000001cbb2b0
[ 861.294960] INFO: task dbench:28473 blocked for more than 120 seconds.
[ 861.295783] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
[ 861.296504] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 861.297352] dbench D 0 28473 28466 0x00000000
[ 861.298040] Call Trace:
[ 861.298360] ? __schedule+0x71e/0x783
[ 861.298834] schedule+0x7e/0x99
[ 861.299247] io_schedule+0x12/0x33
[ 861.299621] wbt_wait+0x23a/0x283
[ 861.299991] ? wait_woken+0x6d/0x6d
[ 861.300380] rq_qos_throttle+0x31/0x3c
[ 861.300795] blk_mq_make_request+0xe8/0x513
[ 861.301257] generic_make_request+0x1bc/0x328
[ 861.301761] ? xlog_bdstrat+0x15/0x4f [xfs]
[ 861.302256] ? submit_bio+0x103/0x11f
[ 861.302731] submit_bio+0x103/0x11f
[ 861.303183] ? bio_add_page+0x41/0x4a
[ 861.303624] _xfs_buf_ioapply+0x35c/0x3ee [xfs]
[ 861.304128] ? __kernel_fpu_end+0x61/0x7b
[ 861.304593] ? xlog_bdstrat+0x4a/0x4f [xfs]
[ 861.305092] ? xfs_buf_submit+0x177/0x1e8 [xfs]
[ 861.305716] xfs_buf_submit+0x177/0x1e8 [xfs]
[ 861.306307] xlog_bdstrat+0x4a/0x4f [xfs]
[ 861.306853] xlog_sync+0x34a/0x450 [xfs]
[ 861.307378] __xfs_log_force_lsn+0x17b/0x283 [xfs]
[ 861.307979] ? xfs_file_fsync+0x16d/0x1ef [xfs]
[ 861.308585] xfs_file_fsync+0x16d/0x1ef [xfs]
[ 861.309153] ? iomap_write_end+0x5d/0x5d
[ 861.309668] xfs_file_buffered_aio_write+0x28e/0x2bc [xfs]
[ 861.310322] __vfs_write+0x113/0x150
[ 861.310792] vfs_write+0xc8/0x16b
[ 861.311222] ksys_pwrite64+0x60/0x7d
[ 861.311627] do_syscall_64+0x84/0x13f
[ 861.312038] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 861.312586] RIP: 0033:0x7ff85f202e83
[ 861.313049] Code: Bad RIP value.
[ 861.313463] RSP: 002b:00007ffe90c48bf8 EFLAGS: 00000246 ORIG_RAX:
0000000000000012
[ 861.314416] RAX: ffffffffffffffda RBX: 0000000001ca8900 RCX: 00007ff85f202e83
[ 861.315344] RDX: 0000000000010000 RSI: 0000000001cbb2b0 RDI: 0000000000000005
[ 861.316260] RBP: 00000000000026d2 R08: 0000000000010000 R09: 0000000000000079
[ 861.317116] R10: 0000000000070000 R11: 0000000000000246 R12: 00007ff85f8f0cf0
[ 861.317919] R13: 0000000000010000 R14: 0000000000010000 R15: 0000000001cbb2b0
[ 861.318819] INFO: task dbench:28474 blocked for more than 120 seconds.
[ 861.319643] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
[ 861.320347] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 861.321198] dbench D 0 28474 28466 0x00000000
[ 861.321795] Call Trace:
[ 861.322076] ? __schedule+0x71e/0x783
[ 861.322552] schedule+0x7e/0x99
[ 861.322959] io_schedule+0x12/0x33
[ 861.323387] wbt_wait+0x23a/0x283
[ 861.323759] ? wait_woken+0x6d/0x6d
[ 861.324149] rq_qos_throttle+0x31/0x3c
[ 861.324558] blk_mq_make_request+0xe8/0x513
[ 861.325033] generic_make_request+0x1bc/0x328
[ 861.325547] ? submit_bio+0x103/0x11f
[ 861.326025] submit_bio+0x103/0x11f
[ 861.326471] ? bio_alloc_bioset+0x10d/0x1d8
[ 861.327014] submit_bio_wait+0x53/0x7f
[ 861.327464] blkdev_issue_flush+0x81/0xa5
[ 861.327928] xfs_file_fsync+0x1c2/0x1ef [xfs]
[ 861.328496] ? iomap_write_end+0x5d/0x5d
[ 861.329036] xfs_file_buffered_aio_write+0x28e/0x2bc [xfs]
[ 861.329642] __vfs_write+0x113/0x150
[ 861.330044] vfs_write+0xc8/0x16b
[ 861.330475] ksys_pwrite64+0x60/0x7d
[ 861.330938] do_syscall_64+0x84/0x13f
[ 861.331398] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 861.331950] RIP: 0033:0x7ff85f202e83
[ 861.332344] Code: Bad RIP value.
[ 861.332700] RSP: 002b:00007ffe90c48bf8 EFLAGS: 00000246 ORIG_RAX:
0000000000000012
[ 861.333519] RAX: ffffffffffffffda RBX: 0000000001ca8900 RCX: 00007ff85f202e83
[ 861.334338] RDX: 0000000000010000 RSI: 0000000001cbb2b0 RDI: 0000000000000005
[ 861.335253] RBP: 00000000000026d2 R08: 0000000000010000 R09: 0000000000000079
[ 861.336135] R10: 0000000000060000 R11: 0000000000000246 R12: 00007ff85f8f0f18
[ 861.336976] R13: 0000000000010000 R14: 0000000000010000 R15: 0000000001cbb2b0
[ 861.337752] INFO: task dbench:28475 blocked for more than 120 seconds.
[ 861.338534] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
[ 861.339318] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 861.340227] dbench D 0 28475 28466 0x00000000
[ 861.340927] Call Trace:
[ 861.341252] ? __schedule+0x71e/0x783
[ 861.341726] schedule+0x7e/0x99
[ 861.342124] io_schedule+0x12/0x33
[ 861.342560] wbt_wait+0x23a/0x283
[ 861.342991] ? wait_woken+0x6d/0x6d
[ 861.343418] rq_qos_throttle+0x31/0x3c
[ 861.343834] blk_mq_make_request+0xe8/0x513
[ 861.344297] generic_make_request+0x1bc/0x328
[ 861.344794] ? submit_bio+0x103/0x11f
[ 861.345199] submit_bio+0x103/0x11f
[ 861.345631] ? xfs_setfilesize_trans_alloc+0x41/0x8c [xfs]
[ 861.346362] xfs_submit_ioend+0x111/0x11c [xfs]
[ 861.346970] xfs_vm_writepages+0x75/0x95 [xfs]
[ 861.347506] do_writepages+0x2d/0x51
[ 861.347904] __filemap_fdatawrite_range+0xc3/0xf1
[ 861.348471] file_write_and_wait_range+0x3e/0x6b
[ 861.349105] xfs_file_fsync+0xb9/0x1ef [xfs]
[ 861.349611] ? iomap_write_end+0x5d/0x5d
[ 861.350074] xfs_file_buffered_aio_write+0x28e/0x2bc [xfs]
[ 861.350783] __vfs_write+0x113/0x150
[ 861.351257] vfs_write+0xc8/0x16b
[ 861.351622] ksys_pwrite64+0x60/0x7d
[ 861.352033] do_syscall_64+0x84/0x13f
[ 861.352434] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 861.352993] RIP: 0033:0x7ff85f202e83
[ 861.353388] Code: Bad RIP value.
[ 861.353748] RSP: 002b:00007ffe90c48bf8 EFLAGS: 00000246 ORIG_RAX:
0000000000000012
[ 861.354665] RAX: ffffffffffffffda RBX: 0000000001ca8900 RCX: 00007ff85f202e83
[ 861.355531] RDX: 0000000000010000 RSI: 0000000001cbb2b0 RDI: 0000000000000005
[ 861.356423] RBP: 00000000000026d2 R08: 0000000000010000 R09: 0000000000000079
[ 861.357267] R10: 0000000000080000 R11: 0000000000000246 R12: 00007ff85f8f1140
[ 861.358045] R13: 0000000000010000 R14: 0000000000010000 R15: 0000000001cbb2b0
[ 869.362143] ================end test sanity/006: (HANG, -1)================
[
--
Ming Lei
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: [Bug] block/for-next: IO hang in rq_qos_throttle
2018-07-21 23:22 [Bug] block/for-next: IO hang in rq_qos_throttle Ming Lei
@ 2018-07-22 2:15 ` Josef Bacik
2018-07-22 7:28 ` Ming Lei
0 siblings, 1 reply; 8+ messages in thread
From: Josef Bacik @ 2018-07-22 2:15 UTC (permalink / raw)
To: Ming Lei; +Cc: linux-block, Ming Lei
Yup I sent a patch for this on Thursday, sorry about that,
Josef
Sent from my iPhone
> On Jul 21, 2018, at 7:22 PM, Ming Lei <tom.leiming@gmail.com> wrote:
>=20
> Hi,
>=20
> The following IO hang is triggered on dbench test on xfs/usb-storage,
> and the test
> is run on the latest for-next/block(commit 93d8cf625a32).
>=20
>=20
> [ 497.775475] =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3Dstart test=
sanity/006=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
> [ 497.793059] sd 8:0:0:0: [sdd] Synchronizing SCSI cache
> [ 499.658244] scsi host8: scsi_debug: version 0188 [20180128]
> [ 499.658244] dev_size_mb=3D1024, opts=3D0x0, submit_queues=3D1, stati=
stics=3D0
> [ 499.660292] scsi 8:0:0:0: Direct-Access Linux scsi_debug
> 0188 PQ: 0 ANSI: 7
> [ 499.661405] sd 8:0:0:0: Power-on or device reset occurred
> [ 499.664165] sd 8:0:0:0: [sdd] 2097152 512-byte logical blocks:
> (1.07 GB/1.00 GiB)
> [ 499.666017] sd 8:0:0:0: [sdd] Write Protect is off
> [ 499.666645] sd 8:0:0:0: [sdd] Mode Sense: 73 00 10 08
> [ 499.669315] sd 8:0:0:0: [sdd] Write cache: enabled, read cache:
> enabled, supports DPO and FUA
> [ 499.693097] sd 8:0:0:0: [sdd] Attached SCSI disk
> [ 500.538241] EXT4-fs (sdc): mounted filesystem with ordered data
> mode. Opts: (null)
> [ 525.642527] EXT4-fs (sdc): mounted filesystem with ordered data
> mode. Opts: (null)
> [ 550.256595] EXT4-fs (sdc): mounted filesystem with ordered data
> mode. Opts: (null)
> [ 574.781686] EXT4-fs (sdc): mounted filesystem with ordered data
> mode. Opts: (null)
> [ 609.888137] usb 1-1: reset high-speed USB device number 2 using ehci-p=
ci
> [ 640.608104] usb 1-1: reset high-speed USB device number 2 using ehci-p=
ci
> [ 641.765877] SGI XFS with ACLs, security attributes, realtime,
> scrub, no debug enabled
> [ 641.775402] XFS (sdc): Mounting V5 Filesystem
> [ 641.880050] XFS (sdc): Ending clean mount
> [ 666.193467] XFS (sdc): Unmounting Filesystem
> [ 666.351521] XFS (sdc): Mounting V5 Filesystem
> [ 666.409923] XFS (sdc): Ending clean mount
> [ 690.848609] XFS (sdc): Unmounting Filesystem
> [ 691.030587] XFS (sdc): Mounting V5 Filesystem
> [ 691.487377] XFS (sdc): Ending clean mount
> [ 861.151076] INFO: task kworker/3:0:28321 blocked for more than 120 sec=
onds.
> [ 861.152024] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
> [ 861.152808] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 861.153802] kworker/3:0 D 0 28321 2 0x80000000
> [ 861.154799] Workqueue: xfs-sync/sdc xfs_log_worker [xfs]
> [ 861.155481] Call Trace:
> [ 861.155811] ? __schedule+0x71e/0x783
> [ 861.156281] schedule+0x7e/0x99
> [ 861.156685] io_schedule+0x12/0x33
> [ 861.157131] wbt_wait+0x23a/0x283
> [ 861.157558] ? wait_woken+0x6d/0x6d
> [ 861.158017] rq_qos_throttle+0x31/0x3c
> [ 861.158520] blk_mq_make_request+0xe8/0x513
> [ 861.159063] generic_make_request+0x1bc/0x328
> [ 861.159631] ? xlog_bdstrat+0x15/0x4f [xfs]
> [ 861.161486] ? submit_bio+0x103/0x11f
> [ 861.161982] submit_bio+0x103/0x11f
> [ 861.162591] ? bio_add_page+0x41/0x4a
> [ 861.163191] _xfs_buf_ioapply+0x35c/0x3ee [xfs]
> [ 861.163828] ? xlog_bdstrat+0x4a/0x4f [xfs]
> [ 861.164571] ? xfs_buf_submit+0x177/0x1e8 [xfs]
> [ 861.165294] ? xlog_bdstrat+0x4a/0x4f [xfs]
> [ 861.165866] xfs_buf_submit+0x177/0x1e8 [xfs]
> [ 861.166610] xlog_bdstrat+0x4a/0x4f [xfs]
> [ 861.167268] xlog_sync+0x34a/0x450 [xfs]
> [ 861.167813] xfs_log_force+0x16b/0x286 [xfs]
> [ 861.168523] ? _raw_spin_unlock_irq+0x1d/0x2e
> [ 861.169193] ? finish_task_switch+0x16d/0x21f
> [ 861.169788] xfs_log_worker+0xdd/0xf4 [xfs]
> [ 861.170503] process_one_work+0x1c9/0x2f6
> [ 861.171118] ? rescuer_thread+0x282/0x282
> [ 861.171653] worker_thread+0x1ca/0x295
> [ 861.172297] kthread+0x115/0x11d
> [ 861.172722] ? kthread_flush_work_fn+0xe/0xe
> [ 861.173433] ret_from_fork+0x35/0x40
> [ 861.173911] INFO: task dbench:28467 blocked for more than 120 seconds.
> [ 861.174891] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
> [ 861.175760] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 861.176832] dbench D 0 28467 28466 0x00000000
> [ 861.177618] Call Trace:
> [ 861.177941] ? __schedule+0x71e/0x783
> [ 861.178542] schedule+0x7e/0x99
> [ 861.178925] io_schedule+0x12/0x33
> [ 861.179420] wbt_wait+0x23a/0x283
> [ 861.179796] ? wait_woken+0x6d/0x6d
> [ 861.180304] rq_qos_throttle+0x31/0x3c
> [ 861.180736] blk_mq_make_request+0xe8/0x513
> [ 861.181325] generic_make_request+0x1bc/0x328
> [ 861.181811] ? submit_bio+0x103/0x11f
> [ 861.182340] submit_bio+0x103/0x11f
> [ 861.182762] ? xfs_setfilesize_trans_alloc+0x41/0x8c [xfs]
> [ 861.183532] xfs_submit_ioend+0x111/0x11c [xfs]
> [ 861.184150] xfs_vm_writepages+0x75/0x95 [xfs]
> [ 861.184641] do_writepages+0x2d/0x51
> [ 861.185191] __filemap_fdatawrite_range+0xc3/0xf1
> [ 861.185713] file_write_and_wait_range+0x3e/0x6b
> [ 861.186461] xfs_file_fsync+0xb9/0x1ef [xfs]
> [ 861.187119] ? iomap_write_end+0x5d/0x5d
> [ 861.187605] xfs_file_buffered_aio_write+0x28e/0x2bc [xfs]
> [ 861.188346] __vfs_write+0x113/0x150
> [ 861.188750] vfs_write+0xc8/0x16b
> [ 861.189261] ksys_pwrite64+0x60/0x7d
> [ 861.189659] do_syscall_64+0x84/0x13f
> [ 861.190210] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [ 861.190784] RIP: 0033:0x7ff85f202e83
> [ 861.191306] Code: Bad RIP value.
> [ 861.191668] RSP: 002b:00007ffe90c48bf8 EFLAGS: 00000246 ORIG_RAX:
> 0000000000000012
> [ 861.192619] RAX: ffffffffffffffda RBX: 0000000001ca8900 RCX: 00007ff85=
f202e83
> [ 861.193470] RDX: 0000000000010000 RSI: 0000000001cbb2b0 RDI: 000000000=
0000005
> [ 861.194367] RBP: 00000000000026d2 R08: 0000000000010000 R09: 000000000=
0000079
> [ 861.195377] R10: 0000000000070000 R11: 0000000000000246 R12: 00007ff85=
f8f0000
> [ 861.196230] R13: 0000000000010000 R14: 0000000000010000 R15: 000000000=
1cbb2b0
> [ 861.197080] INFO: task dbench:28468 blocked for more than 120 seconds.
> [ 861.197790] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
> [ 861.198581] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 861.199496] dbench D 0 28468 28466 0x00000000
> [ 861.200178] Call Trace:
> [ 861.200458] ? __schedule+0x71e/0x783
> [ 861.200878] schedule+0x7e/0x99
> [ 861.201415] io_schedule+0x12/0x33
> [ 861.201801] wbt_wait+0x23a/0x283
> [ 861.202356] ? wait_woken+0x6d/0x6d
> [ 861.202751] rq_qos_throttle+0x31/0x3c
> [ 861.203297] blk_mq_make_request+0xe8/0x513
> [ 861.203764] generic_make_request+0x1bc/0x328
> [ 861.204369] ? submit_bio+0x103/0x11f
> [ 861.204778] submit_bio+0x103/0x11f
> [ 861.205313] ? xfs_setfilesize_trans_alloc+0x41/0x8c [xfs]
> [ 861.205942] xfs_submit_ioend+0x111/0x11c [xfs]
> [ 861.206629] xfs_vm_writepages+0x75/0x95 [xfs]
> [ 861.207305] do_writepages+0x2d/0x51
> [ 861.207701] __filemap_fdatawrite_range+0xc3/0xf1
> [ 861.208340] file_write_and_wait_range+0x3e/0x6b
> [ 861.208877] xfs_file_fsync+0xb9/0x1ef [xfs]
> [ 861.209486] ? iomap_write_end+0x5d/0x5d
> [ 861.209952] xfs_file_buffered_aio_write+0x28e/0x2bc [xfs]
> [ 861.210757] __vfs_write+0x113/0x150
> [ 861.211234] vfs_write+0xc8/0x16b
> [ 861.211603] ksys_pwrite64+0x60/0x7d
> [ 861.212129] do_syscall_64+0x84/0x13f
> [ 861.212535] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [ 861.213217] RIP: 0033:0x7ff85f202e83
> [ 861.213610] Code: Bad RIP value.
> [ 861.213975] RSP: 002b:00007ffe90c48bf8 EFLAGS: 00000246 ORIG_RAX:
> 0000000000000012
> [ 861.215138] RAX: ffffffffffffffda RBX: 0000000001ca8900 RCX: 00007ff85=
f202e83
> [ 861.215940] RDX: 0000000000010000 RSI: 0000000001cbb2b0 RDI: 000000000=
0000005
> [ 861.216834] RBP: 00000000000026d2 R08: 0000000000010000 R09: 000000000=
0000079
> [ 861.217708] R10: 0000000000070000 R11: 0000000000000246 R12: 00007ff85=
f8f0228
> [ 861.218658] R13: 0000000000010000 R14: 0000000000010000 R15: 000000000=
1cbb2b0
> [ 861.219519] INFO: task dbench:28469 blocked for more than 120 seconds.
> [ 861.220298] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
> [ 861.220980] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 861.221950] dbench D 0 28469 28466 0x00000000
> [ 861.222616] Call Trace:
> [ 861.222903] ? __schedule+0x71e/0x783
> [ 861.223449] schedule+0x7e/0x99
> [ 861.223809] io_schedule+0x12/0x33
> [ 861.224311] wbt_wait+0x23a/0x283
> [ 861.224681] ? wait_woken+0x6d/0x6d
> [ 861.225198] rq_qos_throttle+0x31/0x3c
> [ 861.225612] blk_mq_make_request+0xe8/0x513
> [ 861.226232] generic_make_request+0x1bc/0x328
> [ 861.226715] ? _raw_spin_lock_irqsave+0x25/0x46
> [ 861.227431] ? submit_bio+0x103/0x11f
> [ 861.227841] submit_bio+0x103/0x11f
> [ 861.228341] ? bio_alloc_bioset+0x10d/0x1d8
> [ 861.228805] submit_bio_wait+0x53/0x7f
> [ 861.229348] blkdev_issue_flush+0x81/0xa5
> [ 861.229826] xfs_file_fsync+0x1c2/0x1ef [xfs]
> [ 861.230446] ? iomap_write_end+0x5d/0x5d
> [ 861.230922] xfs_file_buffered_aio_write+0x28e/0x2bc [xfs]
> [ 861.231643] __vfs_write+0x113/0x150
> [ 861.232121] vfs_write+0xc8/0x16b
> [ 861.232489] ksys_pwrite64+0x60/0x7d
> [ 861.232888] do_syscall_64+0x84/0x13f
> [ 861.233480] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [ 861.234110] RIP: 0033:0x7ff85f202e83
> [ 861.234583] Code: Bad RIP value.
> [ 861.235152] RSP: 002b:00007ffe90c48bf8 EFLAGS: 00000246 ORIG_RAX:
> 0000000000000012
> [ 861.235992] RAX: ffffffffffffffda RBX: 0000000001ca8900 RCX: 00007ff85=
f202e83
> [ 861.236895] RDX: 0000000000010000 RSI: 0000000001cbb2b0 RDI: 000000000=
0000005
> [ 861.237776] RBP: 00000000000026d2 R08: 0000000000010000 R09: 000000000=
0000079
> [ 861.238764] R10: 0000000000040000 R11: 0000000000000246 R12: 00007ff85=
f8f0450
> [ 861.239682] R13: 0000000000010000 R14: 0000000000010000 R15: 000000000=
1cbb2b0
> [ 861.240534] INFO: task dbench:28470 blocked for more than 120 seconds.
> [ 861.241407] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
> [ 861.242244] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 861.243247] dbench D 0 28470 28466 0x00000000
> [ 861.243843] Call Trace:
> [ 861.244125] ? __schedule+0x71e/0x783
> [ 861.244561] schedule+0x7e/0x99
> [ 861.245007] __xfs_log_force_lsn+0x13d/0x283 [xfs]
> [ 861.245624] ? wake_up_q+0x4d/0x4d
> [ 861.246033] ? xfs_file_fsync+0x16d/0x1ef [xfs]
> [ 861.246639] xfs_log_force_lsn+0xf7/0x12a [xfs]
> [ 861.247254] xfs_file_fsync+0x16d/0x1ef [xfs]
> [ 861.247817] ? iomap_write_end+0x5d/0x5d
> [ 861.248321] xfs_file_buffered_aio_write+0x28e/0x2bc [xfs]
> [ 861.248917] __vfs_write+0x113/0x150
> [ 861.249314] vfs_write+0xc8/0x16b
> [ 861.249678] ksys_pwrite64+0x60/0x7d
> [ 861.250090] do_syscall_64+0x84/0x13f
> [ 861.250569] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [ 861.251216] RIP: 0033:0x7ff85f202e83
> [ 861.251619] Code: Bad RIP value.
> [ 861.251981] RSP: 002b:00007ffe90c48bf8 EFLAGS: 00000246 ORIG_RAX:
> 0000000000000012
> [ 861.252795] RAX: ffffffffffffffda RBX: 0000000001ca8900 RCX: 00007ff85=
f202e83
> [ 861.253564] RDX: 0000000000010000 RSI: 0000000001cbb2b0 RDI: 000000000=
0000005
> [ 861.254399] RBP: 00000000000026d2 R08: 0000000000010000 R09: 000000000=
0000079
> [ 861.255301] R10: 0000000000050000 R11: 0000000000000246 R12: 00007ff85=
f8f0678
> [ 861.256141] R13: 0000000000010000 R14: 0000000000010000 R15: 000000000=
1cbb2b0
> [ 861.256913] INFO: task dbench:28471 blocked for more than 120 seconds.
> [ 861.257721] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
> [ 861.258503] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 861.259463] dbench D 0 28471 28466 0x00000000
> [ 861.260066] Call Trace:
> [ 861.260349] ? __schedule+0x71e/0x783
> [ 861.260754] schedule+0x7e/0x99
> [ 861.261105] io_schedule+0x12/0x33
> [ 861.261477] blk_mq_get_tag+0x153/0x279
> [ 861.261899] ? wait_woken+0x6d/0x6d
> [ 861.262336] blk_mq_get_request+0x105/0x37e
> [ 861.262876] blk_mq_make_request+0x171/0x513
> [ 861.263410] generic_make_request+0x1bc/0x328
> [ 861.263887] ? _raw_spin_lock_irqsave+0x25/0x46
> [ 861.264391] ? submit_bio+0x103/0x11f
> [ 861.264834] submit_bio+0x103/0x11f
> [ 861.265287] ? bio_alloc_bioset+0x10d/0x1d8
> [ 861.265827] submit_bio_wait+0x53/0x7f
> [ 861.266279] blkdev_issue_flush+0x81/0xa5
> [ 861.266821] xfs_file_fsync+0x1c2/0x1ef [xfs]
> [ 861.267411] ? iomap_write_end+0x5d/0x5d
> [ 861.267948] xfs_file_buffered_aio_write+0x28e/0x2bc [xfs]
> [ 861.268612] __vfs_write+0x113/0x150
> [ 861.269017] vfs_write+0xc8/0x16b
> [ 861.269382] ksys_pwrite64+0x60/0x7d
> [ 861.269806] do_syscall_64+0x84/0x13f
> [ 861.270280] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [ 861.270926] RIP: 0033:0x7ff85f202e83
> [ 861.271378] Code: Bad RIP value.
> [ 861.271739] RSP: 002b:00007ffe90c48bf8 EFLAGS: 00000246 ORIG_RAX:
> 0000000000000012
> [ 861.272554] RAX: ffffffffffffffda RBX: 0000000001ca8900 RCX: 00007ff85=
f202e83
> [ 861.273417] RDX: 0000000000010000 RSI: 0000000001cbb2b0 RDI: 000000000=
0000005
> [ 861.274322] RBP: 00000000000026d2 R08: 0000000000010000 R09: 000000000=
0000079
> [ 861.275228] R10: 0000000000070000 R11: 0000000000000246 R12: 00007ff85=
f8f08a0
> [ 861.276122] R13: 0000000000010000 R14: 0000000000010000 R15: 000000000=
1cbb2b0
> [ 861.276895] INFO: task dbench:28472 blocked for more than 120 seconds.
> [ 861.277697] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
> [ 861.278495] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 861.279462] dbench D 0 28472 28466 0x00000000
> [ 861.280067] Call Trace:
> [ 861.280346] ? __schedule+0x71e/0x783
> [ 861.280753] schedule+0x7e/0x99
> [ 861.281105] schedule_timeout+0x3a/0x340
> [ 861.281535] ? blk_queue_exit+0x5c/0x5e
> [ 861.281959] ? generic_make_request+0x283/0x328
> [ 861.282529] io_schedule_timeout+0x20/0x3d
> [ 861.283065] wait_for_common_io.constprop.2+0x9d/0x120
> [ 861.283657] ? wake_up_q+0x4d/0x4d
> [ 861.284040] submit_bio_wait+0x5b/0x7f
> [ 861.284452] blkdev_issue_flush+0x81/0xa5
> [ 861.284972] xfs_file_fsync+0x1c2/0x1ef [xfs]
> [ 861.285531] ? iomap_write_end+0x5d/0x5d
> [ 861.286074] xfs_file_buffered_aio_write+0x28e/0x2bc [xfs]
> [ 861.286783] __vfs_write+0x113/0x150
> [ 861.287258] vfs_write+0xc8/0x16b
> [ 861.287665] ksys_pwrite64+0x60/0x7d
> [ 861.288137] do_syscall_64+0x84/0x13f
> [ 861.288612] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [ 861.289168] RIP: 0033:0x7ff85f202e83
> [ 861.289561] Code: Bad RIP value.
> [ 861.289976] RSP: 002b:00007ffe90c48bf8 EFLAGS: 00000246 ORIG_RAX:
> 0000000000000012
> [ 861.290927] RAX: ffffffffffffffda RBX: 0000000001ca8900 RCX: 00007ff85=
f202e83
> [ 861.291750] RDX: 0000000000010000 RSI: 0000000001cbb2b0 RDI: 000000000=
0000005
> [ 861.292514] RBP: 00000000000026d2 R08: 0000000000010000 R09: 000000000=
0000079
> [ 861.293286] R10: 0000000000040000 R11: 0000000000000246 R12: 00007ff85=
f8f0ac8
> [ 861.294059] R13: 0000000000010000 R14: 0000000000010000 R15: 000000000=
1cbb2b0
> [ 861.294960] INFO: task dbench:28473 blocked for more than 120 seconds.
> [ 861.295783] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
> [ 861.296504] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 861.297352] dbench D 0 28473 28466 0x00000000
> [ 861.298040] Call Trace:
> [ 861.298360] ? __schedule+0x71e/0x783
> [ 861.298834] schedule+0x7e/0x99
> [ 861.299247] io_schedule+0x12/0x33
> [ 861.299621] wbt_wait+0x23a/0x283
> [ 861.299991] ? wait_woken+0x6d/0x6d
> [ 861.300380] rq_qos_throttle+0x31/0x3c
> [ 861.300795] blk_mq_make_request+0xe8/0x513
> [ 861.301257] generic_make_request+0x1bc/0x328
> [ 861.301761] ? xlog_bdstrat+0x15/0x4f [xfs]
> [ 861.302256] ? submit_bio+0x103/0x11f
> [ 861.302731] submit_bio+0x103/0x11f
> [ 861.303183] ? bio_add_page+0x41/0x4a
> [ 861.303624] _xfs_buf_ioapply+0x35c/0x3ee [xfs]
> [ 861.304128] ? __kernel_fpu_end+0x61/0x7b
> [ 861.304593] ? xlog_bdstrat+0x4a/0x4f [xfs]
> [ 861.305092] ? xfs_buf_submit+0x177/0x1e8 [xfs]
> [ 861.305716] xfs_buf_submit+0x177/0x1e8 [xfs]
> [ 861.306307] xlog_bdstrat+0x4a/0x4f [xfs]
> [ 861.306853] xlog_sync+0x34a/0x450 [xfs]
> [ 861.307378] __xfs_log_force_lsn+0x17b/0x283 [xfs]
> [ 861.307979] ? xfs_file_fsync+0x16d/0x1ef [xfs]
> [ 861.308585] xfs_file_fsync+0x16d/0x1ef [xfs]
> [ 861.309153] ? iomap_write_end+0x5d/0x5d
> [ 861.309668] xfs_file_buffered_aio_write+0x28e/0x2bc [xfs]
> [ 861.310322] __vfs_write+0x113/0x150
> [ 861.310792] vfs_write+0xc8/0x16b
> [ 861.311222] ksys_pwrite64+0x60/0x7d
> [ 861.311627] do_syscall_64+0x84/0x13f
> [ 861.312038] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [ 861.312586] RIP: 0033:0x7ff85f202e83
> [ 861.313049] Code: Bad RIP value.
> [ 861.313463] RSP: 002b:00007ffe90c48bf8 EFLAGS: 00000246 ORIG_RAX:
> 0000000000000012
> [ 861.314416] RAX: ffffffffffffffda RBX: 0000000001ca8900 RCX: 00007ff85=
f202e83
> [ 861.315344] RDX: 0000000000010000 RSI: 0000000001cbb2b0 RDI: 000000000=
0000005
> [ 861.316260] RBP: 00000000000026d2 R08: 0000000000010000 R09: 000000000=
0000079
> [ 861.317116] R10: 0000000000070000 R11: 0000000000000246 R12: 00007ff85=
f8f0cf0
> [ 861.317919] R13: 0000000000010000 R14: 0000000000010000 R15: 000000000=
1cbb2b0
> [ 861.318819] INFO: task dbench:28474 blocked for more than 120 seconds.
> [ 861.319643] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
> [ 861.320347] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 861.321198] dbench D 0 28474 28466 0x00000000
> [ 861.321795] Call Trace:
> [ 861.322076] ? __schedule+0x71e/0x783
> [ 861.322552] schedule+0x7e/0x99
> [ 861.322959] io_schedule+0x12/0x33
> [ 861.323387] wbt_wait+0x23a/0x283
> [ 861.323759] ? wait_woken+0x6d/0x6d
> [ 861.324149] rq_qos_throttle+0x31/0x3c
> [ 861.324558] blk_mq_make_request+0xe8/0x513
> [ 861.325033] generic_make_request+0x1bc/0x328
> [ 861.325547] ? submit_bio+0x103/0x11f
> [ 861.326025] submit_bio+0x103/0x11f
> [ 861.326471] ? bio_alloc_bioset+0x10d/0x1d8
> [ 861.327014] submit_bio_wait+0x53/0x7f
> [ 861.327464] blkdev_issue_flush+0x81/0xa5
> [ 861.327928] xfs_file_fsync+0x1c2/0x1ef [xfs]
> [ 861.328496] ? iomap_write_end+0x5d/0x5d
> [ 861.329036] xfs_file_buffered_aio_write+0x28e/0x2bc [xfs]
> [ 861.329642] __vfs_write+0x113/0x150
> [ 861.330044] vfs_write+0xc8/0x16b
> [ 861.330475] ksys_pwrite64+0x60/0x7d
> [ 861.330938] do_syscall_64+0x84/0x13f
> [ 861.331398] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [ 861.331950] RIP: 0033:0x7ff85f202e83
> [ 861.332344] Code: Bad RIP value.
> [ 861.332700] RSP: 002b:00007ffe90c48bf8 EFLAGS: 00000246 ORIG_RAX:
> 0000000000000012
> [ 861.333519] RAX: ffffffffffffffda RBX: 0000000001ca8900 RCX: 00007ff85=
f202e83
> [ 861.334338] RDX: 0000000000010000 RSI: 0000000001cbb2b0 RDI: 000000000=
0000005
> [ 861.335253] RBP: 00000000000026d2 R08: 0000000000010000 R09: 000000000=
0000079
> [ 861.336135] R10: 0000000000060000 R11: 0000000000000246 R12: 00007ff85=
f8f0f18
> [ 861.336976] R13: 0000000000010000 R14: 0000000000010000 R15: 000000000=
1cbb2b0
> [ 861.337752] INFO: task dbench:28475 blocked for more than 120 seconds.
> [ 861.338534] Not tainted 4.18.0-rc4_93d8cf625a32_for-next+ #1
> [ 861.339318] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 861.340227] dbench D 0 28475 28466 0x00000000
> [ 861.340927] Call Trace:
> [ 861.341252] ? __schedule+0x71e/0x783
> [ 861.341726] schedule+0x7e/0x99
> [ 861.342124] io_schedule+0x12/0x33
> [ 861.342560] wbt_wait+0x23a/0x283
> [ 861.342991] ? wait_woken+0x6d/0x6d
> [ 861.343418] rq_qos_throttle+0x31/0x3c
> [ 861.343834] blk_mq_make_request+0xe8/0x513
> [ 861.344297] generic_make_request+0x1bc/0x328
> [ 861.344794] ? submit_bio+0x103/0x11f
> [ 861.345199] submit_bio+0x103/0x11f
> [ 861.345631] ? xfs_setfilesize_trans_alloc+0x41/0x8c [xfs]
> [ 861.346362] xfs_submit_ioend+0x111/0x11c [xfs]
> [ 861.346970] xfs_vm_writepages+0x75/0x95 [xfs]
> [ 861.347506] do_writepages+0x2d/0x51
> [ 861.347904] __filemap_fdatawrite_range+0xc3/0xf1
> [ 861.348471] file_write_and_wait_range+0x3e/0x6b
> [ 861.349105] xfs_file_fsync+0xb9/0x1ef [xfs]
> [ 861.349611] ? iomap_write_end+0x5d/0x5d
> [ 861.350074] xfs_file_buffered_aio_write+0x28e/0x2bc [xfs]
> [ 861.350783] __vfs_write+0x113/0x150
> [ 861.351257] vfs_write+0xc8/0x16b
> [ 861.351622] ksys_pwrite64+0x60/0x7d
> [ 861.352033] do_syscall_64+0x84/0x13f
> [ 861.352434] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [ 861.352993] RIP: 0033:0x7ff85f202e83
> [ 861.353388] Code: Bad RIP value.
> [ 861.353748] RSP: 002b:00007ffe90c48bf8 EFLAGS: 00000246 ORIG_RAX:
> 0000000000000012
> [ 861.354665] RAX: ffffffffffffffda RBX: 0000000001ca8900 RCX: 00007ff85=
f202e83
> [ 861.355531] RDX: 0000000000010000 RSI: 0000000001cbb2b0 RDI: 000000000=
0000005
> [ 861.356423] RBP: 00000000000026d2 R08: 0000000000010000 R09: 000000000=
0000079
> [ 861.357267] R10: 0000000000080000 R11: 0000000000000246 R12: 00007ff85=
f8f1140
> [ 861.358045] R13: 0000000000010000 R14: 0000000000010000 R15: 000000000=
1cbb2b0
> [ 869.362143] =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3Dend test s=
anity/006: (HANG, -1)=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
> [
>=20
>=20
>=20
> --=20
> Ming Lei
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: [Bug] block/for-next: IO hang in rq_qos_throttle
2018-07-22 2:15 ` Josef Bacik
@ 2018-07-22 7:28 ` Ming Lei
2018-07-22 12:24 ` Josef Bacik
2018-07-27 15:47 ` Josef Bacik
0 siblings, 2 replies; 8+ messages in thread
From: Ming Lei @ 2018-07-22 7:28 UTC (permalink / raw)
To: Josef Bacik; +Cc: Ming Lei, linux-block
On Sun, Jul 22, 2018 at 02:15:38AM +0000, Josef Bacik wrote:
> Yup I sent a patch for this on Thursday, sorry about that,
>
I just applied the patch of 'blk-rq-qos: make depth comparisons unsigned',
looks the same IO hang can be triggered too.
Thanks,
Ming
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: [Bug] block/for-next: IO hang in rq_qos_throttle
2018-07-22 7:28 ` Ming Lei
@ 2018-07-22 12:24 ` Josef Bacik
2018-07-27 15:47 ` Josef Bacik
1 sibling, 0 replies; 8+ messages in thread
From: Josef Bacik @ 2018-07-22 12:24 UTC (permalink / raw)
To: Ming Lei; +Cc: Ming Lei, linux-block
VWdoIGNyYXAgaXTigJlzIGluIHdidC4gIEnigJlsbCB0YWtlIGEgbG9vayB3aGVuIEnigJltIGJh
Y2sgZnJvbSB2YWNhdGlvbi4gIFRoYW5rcywNCg0KSm9zZWYNCg0KU2VudCBmcm9tIG15IGlQaG9u
ZQ0KDQo+IE9uIEp1bCAyMiwgMjAxOCwgYXQgMzoyOCBBTSwgTWluZyBMZWkgPG1pbmcubGVpQHJl
ZGhhdC5jb20+IHdyb3RlOg0KPiANCj4+IE9uIFN1biwgSnVsIDIyLCAyMDE4IGF0IDAyOjE1OjM4
QU0gKzAwMDAsIEpvc2VmIEJhY2lrIHdyb3RlOg0KPj4gWXVwIEkgc2VudCBhIHBhdGNoIGZvciB0
aGlzIG9uIFRodXJzZGF5LCBzb3JyeSBhYm91dCB0aGF0LA0KPj4gDQo+IA0KPiBJIGp1c3QgYXBw
bGllZCB0aGUgcGF0Y2ggb2YgJ2Jsay1ycS1xb3M6IG1ha2UgZGVwdGggY29tcGFyaXNvbnMgdW5z
aWduZWQnLA0KPiBsb29rcyB0aGUgc2FtZSBJTyBoYW5nIGNhbiBiZSB0cmlnZ2VyZWQgdG9vLg0K
PiANCj4gVGhhbmtzLA0KPiBNaW5nDQo=
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: [Bug] block/for-next: IO hang in rq_qos_throttle
2018-07-22 7:28 ` Ming Lei
2018-07-22 12:24 ` Josef Bacik
@ 2018-07-27 15:47 ` Josef Bacik
2018-07-28 12:11 ` Ming Lei
1 sibling, 1 reply; 8+ messages in thread
From: Josef Bacik @ 2018-07-27 15:47 UTC (permalink / raw)
To: Ming Lei; +Cc: Josef Bacik, Ming Lei, linux-block
On Sun, Jul 22, 2018 at 03:28:05PM +0800, Ming Lei wrote:
> On Sun, Jul 22, 2018 at 02:15:38AM +0000, Josef Bacik wrote:
> > Yup I sent a patch for this on Thursday, sorry about that,
> >
>
> I just applied the patch of 'blk-rq-qos: make depth comparisons unsigned',
> looks the same IO hang can be triggered too.
Ok I'm back from vacation and I'm trying to reproduce but it's not happening for
me. What testing infrastructure is this? blktests and xfstests don't have a
sanity/ in their test suites. I'm wondering if there's something else about the
test that I'm missing. Thanks,
Josef
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: [Bug] block/for-next: IO hang in rq_qos_throttle
2018-07-27 15:47 ` Josef Bacik
@ 2018-07-28 12:11 ` Ming Lei
2018-07-28 15:08 ` Jens Axboe
2018-07-31 16:41 ` Josef Bacik
0 siblings, 2 replies; 8+ messages in thread
From: Ming Lei @ 2018-07-28 12:11 UTC (permalink / raw)
To: Josef Bacik; +Cc: Ming Lei, Josef Bacik, linux-block
On Fri, Jul 27, 2018 at 11:47 PM, Josef Bacik <josef@toxicpanda.com> wrote:
> On Sun, Jul 22, 2018 at 03:28:05PM +0800, Ming Lei wrote:
>> On Sun, Jul 22, 2018 at 02:15:38AM +0000, Josef Bacik wrote:
>> > Yup I sent a patch for this on Thursday, sorry about that,
>> >
>>
>> I just applied the patch of 'blk-rq-qos: make depth comparisons unsigned',
>> looks the same IO hang can be triggered too.
>
> Ok I'm back from vacation and I'm trying to reproduce but it's not happening for
> me. What testing infrastructure is this? blktests and xfstests don't have a
> sanity/ in their test suites. I'm wondering if there's something else about the
> test that I'm missing. Thanks,
As I mentioned,
The following IO hang is triggered on dbench test on xfs/usb-storage:
dbench -t 20 -s 64
thanks,
Ming Lei
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: [Bug] block/for-next: IO hang in rq_qos_throttle
2018-07-28 12:11 ` Ming Lei
@ 2018-07-28 15:08 ` Jens Axboe
2018-07-31 16:41 ` Josef Bacik
1 sibling, 0 replies; 8+ messages in thread
From: Jens Axboe @ 2018-07-28 15:08 UTC (permalink / raw)
To: Ming Lei, Josef Bacik; +Cc: Ming Lei, Josef Bacik, linux-block
On 7/28/18 6:11 AM, Ming Lei wrote:
> On Fri, Jul 27, 2018 at 11:47 PM, Josef Bacik <josef@toxicpanda.com> wrote:
>> On Sun, Jul 22, 2018 at 03:28:05PM +0800, Ming Lei wrote:
>>> On Sun, Jul 22, 2018 at 02:15:38AM +0000, Josef Bacik wrote:
>>>> Yup I sent a patch for this on Thursday, sorry about that,
>>>>
>>>
>>> I just applied the patch of 'blk-rq-qos: make depth comparisons unsigned',
>>> looks the same IO hang can be triggered too.
>>
>> Ok I'm back from vacation and I'm trying to reproduce but it's not happening for
>> me. What testing infrastructure is this? blktests and xfstests don't have a
>> sanity/ in their test suites. I'm wondering if there's something else about the
>> test that I'm missing. Thanks,
>
> As I mentioned,
>
> The following IO hang is triggered on dbench test on xfs/usb-storage:
>
> dbench -t 20 -s 64
Josef, the key here is likely a queue depth of 1. So if you're running on
sata, then just limit the device depth to 1.
--
Jens Axboe
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: [Bug] block/for-next: IO hang in rq_qos_throttle
2018-07-28 12:11 ` Ming Lei
2018-07-28 15:08 ` Jens Axboe
@ 2018-07-31 16:41 ` Josef Bacik
1 sibling, 0 replies; 8+ messages in thread
From: Josef Bacik @ 2018-07-31 16:41 UTC (permalink / raw)
To: Ming Lei; +Cc: Josef Bacik, Ming Lei, Josef Bacik, linux-block
On Sat, Jul 28, 2018 at 08:11:33PM +0800, Ming Lei wrote:
> On Fri, Jul 27, 2018 at 11:47 PM, Josef Bacik <josef@toxicpanda.com> wrote:
> > On Sun, Jul 22, 2018 at 03:28:05PM +0800, Ming Lei wrote:
> >> On Sun, Jul 22, 2018 at 02:15:38AM +0000, Josef Bacik wrote:
> >> > Yup I sent a patch for this on Thursday, sorry about that,
> >> >
> >>
> >> I just applied the patch of 'blk-rq-qos: make depth comparisons unsigned',
> >> looks the same IO hang can be triggered too.
> >
> > Ok I'm back from vacation and I'm trying to reproduce but it's not happening for
> > me. What testing infrastructure is this? blktests and xfstests don't have a
> > sanity/ in their test suites. I'm wondering if there's something else about the
> > test that I'm missing. Thanks,
>
> As I mentioned,
>
> The following IO hang is triggered on dbench test on xfs/usb-storage:
>
> dbench -t 20 -s 64
>
Yup I just wasnt sure if there was something else about the test that was making
things different between our two setups. I cannot reproduce with any variation.
I've tried longer dbench runs, I've put dm-delay in front of my usb stick to
artificially increase the io latency, nothing seems to trigger it for me. Could
you run this debug patch and give me the output? Thanks,
Josef
diff --git a/block/blk-wbt.c b/block/blk-wbt.c
index 461a9af11efe..36950ba5288d 100644
--- a/block/blk-wbt.c
+++ b/block/blk-wbt.c
@@ -520,6 +520,8 @@ static void __wbt_wait(struct rq_wb *rwb, enum wbt_flags wb_acct,
if (may_queue(rwb, rqw, &wait, rw))
break;
+ printk(KERN_ERR "queueing, inflight %d, limit %u\n",
+ atomic_read(&rqw->inflight), get_limit(rwb, rw));
if (lock) {
spin_unlock_irq(lock);
io_schedule();
^ permalink raw reply related [flat|nested] 8+ messages in thread
end of thread, other threads:[~2018-07-31 18:22 UTC | newest]
Thread overview: 8+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2018-07-21 23:22 [Bug] block/for-next: IO hang in rq_qos_throttle Ming Lei
2018-07-22 2:15 ` Josef Bacik
2018-07-22 7:28 ` Ming Lei
2018-07-22 12:24 ` Josef Bacik
2018-07-27 15:47 ` Josef Bacik
2018-07-28 12:11 ` Ming Lei
2018-07-28 15:08 ` Jens Axboe
2018-07-31 16:41 ` Josef Bacik
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox