| Message ID | 20200528153441.3501777-2-kbusch@kernel.org (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | [PATCHv3,1/2] blk-mq: export __blk_mq_complete_request | expand |
Still seeing a hang. Alan [ 92.034813] FAULT_INJECTION: forcing a failure. name fail_io_timeout, interval 1, probability 100, space 0, times 1000 [ 92.034816] CPU: 54 PID: 0 Comm: swapper/54 Not tainted 5.7.0-rc7+ #2 [ 92.034817] Hardware name: Oracle Corporation ORACLE SERVER X6-2/ASM,MOTHERBOARD,1U, BIOS 38050100 08/30/2016 [ 92.034818] Call Trace: [ 92.034819] <IRQ> [ 92.034827] dump_stack+0x6d/0x9a [ 92.034830] should_fail.cold.5+0x32/0x42 [ 92.034833] blk_should_fake_timeout+0x26/0x30 [ 92.034835] blk_mq_complete_request+0x15/0x30 [ 92.034840] nvme_irq+0xd9/0x1f0 [nvme] [ 92.034846] __handle_irq_event_percpu+0x44/0x190 [ 92.034848] handle_irq_event_percpu+0x32/0x80 [ 92.034849] handle_irq_event+0x3b/0x5a [ 92.034851] handle_edge_irq+0x87/0x190 [ 92.034855] do_IRQ+0x54/0xe0 [ 92.034859] common_interrupt+0xf/0xf [ 92.034859] </IRQ> [ 92.034865] RIP: 0010:cpuidle_enter_state+0xc1/0x400 [ 92.034866] Code: ff e8 e3 41 93 ff 80 7d c7 00 74 17 9c 58 0f 1f 44 00 00 f6 c4 02 0f 85 d2 02 00 00 31 ff e8 16 c3 99 ff fb 66 0f 1f 44 00 00 <45> 85 e4 0f 88 3d 02 00 00 49 63 c4 48 8d 14 40 48 8d 0c c5 00 00 [ 92.034867] RSP: 0018:ffffae4ecc6d3e40 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffdd [ 92.034869] RAX: ffff9b537fcacc40 RBX: ffffce4ebfc83200 RCX: 000000000000001f [ 92.034869] RDX: 000000156db3b7a5 RSI: 0000000031573862 RDI: 0000000000000000 [ 92.034870] RBP: ffffae4ecc6d3e80 R08: 0000000000000002 R09: 000000000002c4c0 [ 92.034871] R10: 011c6513a4e6709e R11: ffff9b537fcabb44 R12: 0000000000000002 [ 92.034871] R13: ffffffffa374c120 R14: ffffffffa374c208 R15: ffffffffa374c1f0 [ 92.034874] cpuidle_enter+0x2e/0x40 [ 92.034877] call_cpuidle+0x23/0x40 [ 92.034878] do_idle+0x230/0x270 [ 92.034880] cpu_startup_entry+0x1d/0x20 [ 92.034885] start_secondary+0x170/0x1c0 [ 92.034889] secondary_startup_64+0xb6/0xc0 [ 122.473526] nvme nvme0: I/O 384 QID 27 timeout, aborting [ 122.473586] nvme nvme0: Abort status: 0x0 [ 152.678470] nvme nvme0: I/O 384 QID 27 timeout, reset controller [ 152.697122] blk_update_request: I/O error, dev nvme0n1, sector 0 op 0x0:(READ) flags 0x80700 phys_seg 4 prio class 0 [ 152.699687] nvme nvme0: Shutdown timeout set to 10 seconds [ 152.703131] nvme nvme0: 56/0/0 default/read/poll queues [ 152.703290] FAULT_INJECTION: forcing a failure. name fail_io_timeout, interval 1, probability 100, space 0, times 999 [ 152.703293] CPU: 53 PID: 0 Comm: swapper/53 Not tainted 5.7.0-rc7+ #2 [ 152.703293] Hardware name: Oracle Corporation ORACLE SERVER X6-2/ASM,MOTHERBOARD,1U, BIOS 38050100 08/30/2016 [ 152.703294] Call Trace: [ 152.703295] <IRQ> [ 152.703301] dump_stack+0x6d/0x9a [ 152.703302] should_fail.cold.5+0x32/0x42 [ 152.703305] blk_should_fake_timeout+0x26/0x30 [ 152.703306] blk_mq_complete_request+0x15/0x30 [ 152.703311] nvme_irq+0xd9/0x1f0 [nvme] [ 152.703316] __handle_irq_event_percpu+0x44/0x190 [ 152.703317] handle_irq_event_percpu+0x32/0x80 [ 152.703319] handle_irq_event+0x3b/0x5a [ 152.703321] handle_edge_irq+0x87/0x190 [ 152.703323] do_IRQ+0x54/0xe0 [ 152.703326] common_interrupt+0xf/0xf [ 152.703327] </IRQ> [ 152.703330] RIP: 0010:cpuidle_enter_state+0xc1/0x400 [ 152.703332] Code: ff e8 e3 41 93 ff 80 7d c7 00 74 17 9c 58 0f 1f 44 00 00 f6 c4 02 0f 85 d2 02 00 00 31 ff e8 16 c3 99 ff fb 66 0f 1f 44 00 00 <45> 85 e4 0f 88 3d 02 00 00 49 63 c4 48 8d 14 40 48 8d 0c c5 00 00 [ 152.703333] RSP: 0018:ffffae4ecc6cbe40 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffdd [ 152.703334] RAX: ffff9b537fc6cc40 RBX: ffffce4ebfc43200 RCX: 000000000000001f [ 152.703334] RDX: 000000238dd33ffa RSI: 0000000031573862 RDI: 0000000000000000 [ 152.703335] RBP: ffffae4ecc6cbe80 R08: 0000000000000002 R09: 000000000002c4c0 [ 152.703336] R10: 011c653849df4957 R11: ffff9b537fc6bb44 R12: 0000000000000004 [ 152.703336] R13: ffffffffa374c120 R14: ffffffffa374c2d8 R15: ffffffffa374c2c0 [ 152.703339] cpuidle_enter+0x2e/0x40 [ 152.703342] call_cpuidle+0x23/0x40 [ 152.703343] do_idle+0x230/0x270 [ 152.703344] cpu_startup_entry+0x1d/0x20 [ 152.703348] start_secondary+0x170/0x1c0 [ 152.703352] secondary_startup_64+0xb6/0xc0 [ 182.883552] nvme nvme0: I/O 960 QID 26 timeout, aborting [ 182.883608] nvme nvme0: Abort status: 0x0 [ 213.088659] nvme nvme0: I/O 960 QID 26 timeout, reset controller [ 213.109414] nvme nvme0: Shutdown timeout set to 10 seconds [ 213.112785] nvme nvme0: 56/0/0 default/read/poll queues [ 213.112880] FAULT_INJECTION: forcing a failure. name fail_io_timeout, interval 1, probability 100, space 0, times 998 [ 213.112882] CPU: 53 PID: 0 Comm: swapper/53 Not tainted 5.7.0-rc7+ #2 [ 213.112883] Hardware name: Oracle Corporation ORACLE SERVER X6-2/ASM,MOTHERBOARD,1U, BIOS 38050100 08/30/2016 [ 213.112883] Call Trace: [ 213.112884] <IRQ> [ 213.112887] dump_stack+0x6d/0x9a [ 213.112888] should_fail.cold.5+0x32/0x42 [ 213.112889] blk_should_fake_timeout+0x26/0x30 [ 213.112890] blk_mq_complete_request+0x15/0x30 [ 213.112893] nvme_irq+0xd9/0x1f0 [nvme] [ 213.112896] __handle_irq_event_percpu+0x44/0x190 [ 213.112897] handle_irq_event_percpu+0x32/0x80 [ 213.112898] handle_irq_event+0x3b/0x5a [ 213.112900] handle_edge_irq+0x87/0x190 [ 213.112901] do_IRQ+0x54/0xe0 [ 213.112903] common_interrupt+0xf/0xf [ 213.112903] </IRQ> [ 213.112905] RIP: 0010:cpuidle_enter_state+0xc1/0x400 [ 213.112906] Code: ff e8 e3 41 93 ff 80 7d c7 00 74 17 9c 58 0f 1f 44 00 00 f6 c4 02 0f 85 d2 02 00 00 31 ff e8 16 c3 99 ff fb 66 0f 1f 44 00 00 <45> 85 e4 0f 88 3d 02 00 00 49 63 c4 48 8d 14 40 48 8d 0c c5 00 00 [ 213.112907] RSP: 0018:ffffae4ecc6cbe40 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffdd [ 213.112908] RAX: ffff9b537fc6cc40 RBX: ffffce4ebfc43200 RCX: 000000000000001f [ 213.112909] RDX: 000000319e847448 RSI: 0000000031573862 RDI: 0000000000000000 [ 213.112909] RBP: ffffae4ecc6cbe80 R08: 0000000000000002 R09: 000000000002c4c0 [ 213.112910] R10: 011c655cc6d029f4 R11: ffff9b537fc6bb44 R12: 0000000000000002 [ 213.112911] R13: ffffffffa374c120 R14: ffffffffa374c208 R15: ffffffffa374c1f0 [ 213.112913] cpuidle_enter+0x2e/0x40 [ 213.112915] call_cpuidle+0x23/0x40 [ 213.112916] do_idle+0x230/0x270 [ 213.112917] cpu_startup_entry+0x1d/0x20 [ 213.112919] start_secondary+0x170/0x1c0 [ 213.112920] secondary_startup_64+0xb6/0xc0 [ 243.293996] nvme nvme0: I/O 960 QID 26 timeout, aborting [ 243.294050] nvme nvme0: Abort status: 0x0 [ 273.498939] nvme nvme0: I/O 960 QID 26 timeout, reset controller [ 273.509832] nvme nvme0: new error during reset [ 273.519648] nvme nvme0: Shutdown timeout set to 10 seconds [ 273.523310] nvme nvme0: 56/0/0 default/read/poll queues [ 273.523397] FAULT_INJECTION: forcing a failure. name fail_io_timeout, interval 1, probability 100, space 0, times 997 [ 273.523399] CPU: 53 PID: 0 Comm: swapper/53 Not tainted 5.7.0-rc7+ #2 [ 273.523400] Hardware name: Oracle Corporation ORACLE SERVER X6-2/ASM,MOTHERBOARD,1U, BIOS 38050100 08/30/2016 [ 273.523400] Call Trace: [ 273.523401] <IRQ> [ 273.523404] dump_stack+0x6d/0x9a [ 273.523405] should_fail.cold.5+0x32/0x42 [ 273.523406] blk_should_fake_timeout+0x26/0x30 [ 273.523407] blk_mq_complete_request+0x15/0x30 [ 273.523410] nvme_irq+0xd9/0x1f0 [nvme] [ 273.523412] __handle_irq_event_percpu+0x44/0x190 [ 273.523413] handle_irq_event_percpu+0x32/0x80 [ 273.523415] handle_irq_event+0x3b/0x5a [ 273.523416] handle_edge_irq+0x87/0x190 [ 273.523417] do_IRQ+0x54/0xe0 [ 273.523419] common_interrupt+0xf/0xf [ 273.523420] </IRQ> [ 273.523422] RIP: 0010:cpuidle_enter_state+0xc1/0x400 [ 273.523423] Code: ff e8 e3 41 93 ff 80 7d c7 00 74 17 9c 58 0f 1f 44 00 00 f6 c4 02 0f 85 d2 02 00 00 31 ff e8 16 c3 99 ff fb 66 0f 1f 44 00 00 <45> 85 e4 0f 88 3d 02 00 00 49 63 c4 48 8d 14 40 48 8d 0c c5 00 00 [ 273.523424] RSP: 0018:ffffae4ecc6cbe40 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffdd [ 273.523425] RAX: ffff9b537fc6cc40 RBX: ffffce4ebfc43200 RCX: 000000000000001f [ 273.523425] RDX: 0000003faf43ca28 RSI: 0000000031573862 RDI: 0000000000000000 [ 273.523426] RBP: ffffae4ecc6cbe80 R08: 0000000000000002 R09: 000000000002c4c0 [ 273.523426] R10: 011c658143e5b34c R11: ffff9b537fc6bb44 R12: 0000000000000002 [ 273.523427] R13: ffffffffa374c120 R14: ffffffffa374c208 R15: ffffffffa374c1f0 [ 273.523429] cpuidle_enter+0x2e/0x40 [ 273.523431] call_cpuidle+0x23/0x40 [ 273.523432] do_idle+0x230/0x270 [ 273.523433] cpu_startup_entry+0x1d/0x20 [ 273.523435] start_secondary+0x170/0x1c0 [ 273.523436] secondary_startup_64+0xb6/0xc0 [ 303.704204] nvme nvme0: I/O 960 QID 26 timeout, aborting [ 303.704245] nvme nvme0: Abort status: 0x0 [ 333.909140] nvme nvme0: I/O 960 QID 26 timeout, reset controller [ 333.928010] nvme nvme0: new error during reset [ 333.934087] nvme nvme0: Shutdown timeout set to 10 seconds [ 333.937470] nvme nvme0: 56/0/0 default/read/poll queues [ 333.937571] FAULT_INJECTION: forcing a failure. name fail_io_timeout, interval 1, probability 100, space 0, times 996 [ 333.937588] CPU: 53 PID: 0 Comm: swapper/53 Not tainted 5.7.0-rc7+ #2 [ 333.937588] Hardware name: Oracle Corporation ORACLE SERVER X6-2/ASM,MOTHERBOARD,1U, BIOS 38050100 08/30/2016 [ 333.937589] Call Trace: [ 333.937590] <IRQ> [ 333.937592] dump_stack+0x6d/0x9a [ 333.937593] should_fail.cold.5+0x32/0x42 [ 333.937594] blk_should_fake_timeout+0x26/0x30 [ 333.937595] blk_mq_complete_request+0x15/0x30 [ 333.937598] nvme_irq+0xd9/0x1f0 [nvme] [ 333.937600] __handle_irq_event_percpu+0x44/0x190 [ 333.937602] handle_irq_event_percpu+0x32/0x80 [ 333.937603] handle_irq_event+0x3b/0x5a [ 333.937604] handle_edge_irq+0x87/0x190 [ 333.937606] do_IRQ+0x54/0xe0 [ 333.937607] common_interrupt+0xf/0xf [ 333.937608] </IRQ> [ 333.937610] RIP: 0010:cpuidle_enter_state+0xc1/0x400 [ 333.937611] Code: ff e8 e3 41 93 ff 80 7d c7 00 74 17 9c 58 0f 1f 44 00 00 f6 c4 02 0f 85 d2 02 00 00 31 ff e8 16 c3 99 ff fb 66 0f 1f 44 00 00 <45> 85 e4 0f 88 3d 02 00 00 49 63 c4 48 8d 14 40 48 8d 0c c5 00 00 [ 333.937612] RSP: 0018:ffffae4ecc6cbe40 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffdd [ 333.937613] RAX: ffff9b537fc6cc40 RBX: ffffce4ebfc43200 RCX: 000000000000001f [ 333.937613] RDX: 0000004dc03adbda RSI: 0000000031573862 RDI: 0000000000000000 [ 333.937614] RBP: ffffae4ecc6cbe80 R08: 0000000000000002 R09: 000000000002c4c0 [ 333.937615] R10: 011c65a5c18bd252 R11: ffff9b537fc6bb44 R12: 0000000000000002 [ 333.937615] R13: ffffffffa374c120 R14: ffffffffa374c208 R15: ffffffffa374c1f0 [ 333.937617] cpuidle_enter+0x2e/0x40 [ 333.937619] call_cpuidle+0x23/0x40 [ 333.937620] do_idle+0x230/0x270 [ 333.937621] cpu_startup_entry+0x1d/0x20 [ 333.937623] start_secondary+0x170/0x1c0 [ 333.937624] secondary_startup_64+0xb6/0xc0 [ 364.114200] nvme nvme0: I/O 960 QID 26 timeout, aborting [ 364.114241] nvme nvme0: Abort status: 0x0 [ 369.745713] INFO: task kworker/u114:2:1182 blocked for more than 122 seconds. [ 369.745758] Not tainted 5.7.0-rc7+ #2 [ 369.745787] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 369.745808] kworker/u114:2 D 0 1182 2 0x80004000 [ 369.745817] Workqueue: nvme-wq nvme_scan_work [nvme_core] [ 369.745818] Call Trace: [ 369.745823] __schedule+0x2dc/0x710 [ 369.745828] ? __kfifo_to_user_r+0x90/0x90 [ 369.745829] schedule+0x44/0xb0 [ 369.745831] blk_mq_freeze_queue_wait+0x4b/0xb0 [ 369.745833] ? finish_wait+0x80/0x80 [ 369.745834] blk_mq_freeze_queue+0x1a/0x20 [ 369.745837] nvme_update_disk_info+0x62/0x3b0 [nvme_core] [ 369.745839] __nvme_revalidate_disk+0x8d/0x140 [nvme_core] [ 369.745842] nvme_revalidate_disk+0xa4/0x140 [nvme_core] [ 369.745843] ? blk_mq_run_hw_queue+0xba/0x100 [ 369.745847] revalidate_disk+0x2b/0xa0 [ 369.745850] nvme_validate_ns+0x46/0x5b0 [nvme_core] [ 369.745852] ? __nvme_submit_sync_cmd+0xe0/0x1b0 [nvme_core] [ 369.745855] nvme_scan_work+0x25a/0x310 [nvme_core] [ 369.745859] process_one_work+0x1ab/0x380 [ 369.745861] worker_thread+0x37/0x3b0 [ 369.745862] kthread+0x120/0x140 [ 369.745863] ? create_worker+0x1b0/0x1b0 [ 369.745864] ? kthread_park+0x90/0x90 [ 369.745867] ret_from_fork+0x35/0x40 On 5/28/20 8:34 AM, Keith Busch wrote: > Once the driver decides to cancel requests, the concept of those > requests timing out ceases to exist. Use __blk_mq_complete_request() to > bypass fake timeout error injection so that request reclaim may > proceed. > > Reviewed-by: Johannes Thumshirn <johannes.thumshirn@wdc.com> > Signed-off-by: Keith Busch <kbusch@kernel.org> > --- > drivers/nvme/host/core.c | 2 +- > 1 file changed, 1 insertion(+), 1 deletion(-) > > diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c > index ba860efd250d..f65a0b6cd988 100644 > --- a/drivers/nvme/host/core.c > +++ b/drivers/nvme/host/core.c > @@ -310,7 +310,7 @@ bool nvme_cancel_request(struct request *req, void *data, bool reserved) > return true; > > nvme_req(req)->status = NVME_SC_HOST_ABORTED_CMD; > - blk_mq_complete_request(req); > + __blk_mq_complete_request(req); > return true; > } > EXPORT_SYMBOL_GPL(nvme_cancel_request);
On Thu, May 28, 2020 at 11:39:10AM -0700, Alan Adamson wrote: > Still seeing a hang. Is it really stuck or are you just not waiting long enough? The default timeout is 30 seconds, and we wait that long once after submission, and again after abort for a total of 60 seconds. But then there's also the retry logic, which by default will retry a non-permanenet error 5 times (a cancelled request normally qualifies for retries). An top of all that, you have to add the time it takes to initialize your controller. Your controller appears to init quite fast, so that part is probably negligable for you. You can expect your fake timeout with 100% probablility to take 150 seconds minimum to return a retryable request. Your "stuck" task has only been waiting 122 seconds. > [ 182.883552] nvme nvme0: I/O 960 QID 26 timeout, aborting > [ 182.883608] nvme nvme0: Abort status: 0x0 > [ 213.088659] nvme nvme0: I/O 960 QID 26 timeout, reset controller > [ 213.109414] nvme nvme0: Shutdown timeout set to 10 seconds > [ 213.112785] nvme nvme0: 56/0/0 default/read/poll queues > [ 213.112880] FAULT_INJECTION: forcing a failure. > name fail_io_timeout, interval 1, probability 100, space 0, > times 998 > [ 213.112882] CPU: 53 PID: 0 Comm: swapper/53 Not tainted 5.7.0-rc7+ #2 > [ 213.112883] Hardware name: Oracle Corporation ORACLE SERVER > X6-2/ASM,MOTHERBOARD,1U, BIOS 38050100 08/30/2016 > [ 213.112883] Call Trace: > [ 213.112884] <IRQ> > [ 213.112887] dump_stack+0x6d/0x9a > [ 213.112888] should_fail.cold.5+0x32/0x42 > [ 213.112889] blk_should_fake_timeout+0x26/0x30 > [ 213.112890] blk_mq_complete_request+0x15/0x30 > [ 213.112893] nvme_irq+0xd9/0x1f0 [nvme] > [ 213.112896] __handle_irq_event_percpu+0x44/0x190 > [ 213.112897] handle_irq_event_percpu+0x32/0x80 > [ 213.112898] handle_irq_event+0x3b/0x5a > [ 213.112900] handle_edge_irq+0x87/0x190 > [ 213.112901] do_IRQ+0x54/0xe0 > [ 213.112903] common_interrupt+0xf/0xf > [ 213.112903] </IRQ> > [ 213.112905] RIP: 0010:cpuidle_enter_state+0xc1/0x400 > [ 213.112906] Code: ff e8 e3 41 93 ff 80 7d c7 00 74 17 9c 58 0f 1f 44 00 > 00 f6 c4 02 0f 85 d2 02 00 00 31 ff e8 16 c3 99 ff fb 66 0f 1f 44 00 00 <45> > 85 e4 0f 88 3d 02 00 00 49 63 c4 48 8d 14 40 48 8d 0c c5 00 00 > [ 213.112907] RSP: 0018:ffffae4ecc6cbe40 EFLAGS: 00000246 ORIG_RAX: > ffffffffffffffdd > [ 213.112908] RAX: ffff9b537fc6cc40 RBX: ffffce4ebfc43200 RCX: > 000000000000001f > [ 213.112909] RDX: 000000319e847448 RSI: 0000000031573862 RDI: > 0000000000000000 > [ 213.112909] RBP: ffffae4ecc6cbe80 R08: 0000000000000002 R09: > 000000000002c4c0 > [ 213.112910] R10: 011c655cc6d029f4 R11: ffff9b537fc6bb44 R12: > 0000000000000002 > [ 213.112911] R13: ffffffffa374c120 R14: ffffffffa374c208 R15: > ffffffffa374c1f0 > [ 213.112913] cpuidle_enter+0x2e/0x40 > [ 213.112915] call_cpuidle+0x23/0x40 > [ 213.112916] do_idle+0x230/0x270 > [ 213.112917] cpu_startup_entry+0x1d/0x20 > [ 213.112919] start_secondary+0x170/0x1c0 > [ 213.112920] secondary_startup_64+0xb6/0xc0 > [ 243.293996] nvme nvme0: I/O 960 QID 26 timeout, aborting > [ 243.294050] nvme nvme0: Abort status: 0x0 > [ 273.498939] nvme nvme0: I/O 960 QID 26 timeout, reset controller > [ 273.509832] nvme nvme0: new error during reset > [ 273.519648] nvme nvme0: Shutdown timeout set to 10 seconds > [ 273.523310] nvme nvme0: 56/0/0 default/read/poll queues > [ 273.523397] FAULT_INJECTION: forcing a failure. > name fail_io_timeout, interval 1, probability 100, space 0, > times 997 > [ 273.523399] CPU: 53 PID: 0 Comm: swapper/53 Not tainted 5.7.0-rc7+ #2 > [ 273.523400] Hardware name: Oracle Corporation ORACLE SERVER > X6-2/ASM,MOTHERBOARD,1U, BIOS 38050100 08/30/2016 > [ 273.523400] Call Trace: > [ 273.523401] <IRQ> > [ 273.523404] dump_stack+0x6d/0x9a > [ 273.523405] should_fail.cold.5+0x32/0x42 > [ 273.523406] blk_should_fake_timeout+0x26/0x30 > [ 273.523407] blk_mq_complete_request+0x15/0x30 > [ 273.523410] nvme_irq+0xd9/0x1f0 [nvme] > [ 273.523412] __handle_irq_event_percpu+0x44/0x190 > [ 273.523413] handle_irq_event_percpu+0x32/0x80 > [ 273.523415] handle_irq_event+0x3b/0x5a > [ 273.523416] handle_edge_irq+0x87/0x190 > [ 273.523417] do_IRQ+0x54/0xe0 > [ 273.523419] common_interrupt+0xf/0xf > [ 273.523420] </IRQ> > [ 273.523422] RIP: 0010:cpuidle_enter_state+0xc1/0x400 > [ 273.523423] Code: ff e8 e3 41 93 ff 80 7d c7 00 74 17 9c 58 0f 1f 44 00 > 00 f6 c4 02 0f 85 d2 02 00 00 31 ff e8 16 c3 99 ff fb 66 0f 1f 44 00 00 <45> > 85 e4 0f 88 3d 02 00 00 49 63 c4 48 8d 14 40 48 8d 0c c5 00 00 > [ 273.523424] RSP: 0018:ffffae4ecc6cbe40 EFLAGS: 00000246 ORIG_RAX: > ffffffffffffffdd > [ 273.523425] RAX: ffff9b537fc6cc40 RBX: ffffce4ebfc43200 RCX: > 000000000000001f > [ 273.523425] RDX: 0000003faf43ca28 RSI: 0000000031573862 RDI: > 0000000000000000 > [ 273.523426] RBP: ffffae4ecc6cbe80 R08: 0000000000000002 R09: > 000000000002c4c0 > [ 273.523426] R10: 011c658143e5b34c R11: ffff9b537fc6bb44 R12: > 0000000000000002 > [ 273.523427] R13: ffffffffa374c120 R14: ffffffffa374c208 R15: > ffffffffa374c1f0 > [ 273.523429] cpuidle_enter+0x2e/0x40 > [ 273.523431] call_cpuidle+0x23/0x40 > [ 273.523432] do_idle+0x230/0x270 > [ 273.523433] cpu_startup_entry+0x1d/0x20 > [ 273.523435] start_secondary+0x170/0x1c0 > [ 273.523436] secondary_startup_64+0xb6/0xc0 > [ 303.704204] nvme nvme0: I/O 960 QID 26 timeout, aborting > [ 303.704245] nvme nvme0: Abort status: 0x0 > [ 333.909140] nvme nvme0: I/O 960 QID 26 timeout, reset controller > [ 333.928010] nvme nvme0: new error during reset > [ 333.934087] nvme nvme0: Shutdown timeout set to 10 seconds > [ 333.937470] nvme nvme0: 56/0/0 default/read/poll queues > [ 333.937571] FAULT_INJECTION: forcing a failure. > name fail_io_timeout, interval 1, probability 100, space 0, > times 996 > [ 333.937588] CPU: 53 PID: 0 Comm: swapper/53 Not tainted 5.7.0-rc7+ #2 > [ 333.937588] Hardware name: Oracle Corporation ORACLE SERVER > X6-2/ASM,MOTHERBOARD,1U, BIOS 38050100 08/30/2016 > [ 333.937589] Call Trace: > [ 333.937590] <IRQ> > [ 333.937592] dump_stack+0x6d/0x9a > [ 333.937593] should_fail.cold.5+0x32/0x42 > [ 333.937594] blk_should_fake_timeout+0x26/0x30 > [ 333.937595] blk_mq_complete_request+0x15/0x30 > [ 333.937598] nvme_irq+0xd9/0x1f0 [nvme] > [ 333.937600] __handle_irq_event_percpu+0x44/0x190 > [ 333.937602] handle_irq_event_percpu+0x32/0x80 > [ 333.937603] handle_irq_event+0x3b/0x5a > [ 333.937604] handle_edge_irq+0x87/0x190 > [ 333.937606] do_IRQ+0x54/0xe0 > [ 333.937607] common_interrupt+0xf/0xf > [ 333.937608] </IRQ> > [ 333.937610] RIP: 0010:cpuidle_enter_state+0xc1/0x400 > [ 333.937611] Code: ff e8 e3 41 93 ff 80 7d c7 00 74 17 9c 58 0f 1f 44 00 > 00 f6 c4 02 0f 85 d2 02 00 00 31 ff e8 16 c3 99 ff fb 66 0f 1f 44 00 00 <45> > 85 e4 0f 88 3d 02 00 00 49 63 c4 48 8d 14 40 48 8d 0c c5 00 00 > [ 333.937612] RSP: 0018:ffffae4ecc6cbe40 EFLAGS: 00000246 ORIG_RAX: > ffffffffffffffdd > [ 333.937613] RAX: ffff9b537fc6cc40 RBX: ffffce4ebfc43200 RCX: > 000000000000001f > [ 333.937613] RDX: 0000004dc03adbda RSI: 0000000031573862 RDI: > 0000000000000000 > [ 333.937614] RBP: ffffae4ecc6cbe80 R08: 0000000000000002 R09: > 000000000002c4c0 > [ 333.937615] R10: 011c65a5c18bd252 R11: ffff9b537fc6bb44 R12: > 0000000000000002 > [ 333.937615] R13: ffffffffa374c120 R14: ffffffffa374c208 R15: > ffffffffa374c1f0 > [ 333.937617] cpuidle_enter+0x2e/0x40 > [ 333.937619] call_cpuidle+0x23/0x40 > [ 333.937620] do_idle+0x230/0x270 > [ 333.937621] cpu_startup_entry+0x1d/0x20 > [ 333.937623] start_secondary+0x170/0x1c0 > [ 333.937624] secondary_startup_64+0xb6/0xc0 > [ 364.114200] nvme nvme0: I/O 960 QID 26 timeout, aborting > [ 364.114241] nvme nvme0: Abort status: 0x0 > [ 369.745713] INFO: task kworker/u114:2:1182 blocked for more than 122 > seconds. > [ 369.745758] Not tainted 5.7.0-rc7+ #2 > [ 369.745787] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables > this message. > [ 369.745808] kworker/u114:2 D 0 1182 2 0x80004000 > [ 369.745817] Workqueue: nvme-wq nvme_scan_work [nvme_core] > [ 369.745818] Call Trace: > [ 369.745823] __schedule+0x2dc/0x710 > [ 369.745828] ? __kfifo_to_user_r+0x90/0x90 > [ 369.745829] schedule+0x44/0xb0 > [ 369.745831] blk_mq_freeze_queue_wait+0x4b/0xb0 > [ 369.745833] ? finish_wait+0x80/0x80 > [ 369.745834] blk_mq_freeze_queue+0x1a/0x20 > [ 369.745837] nvme_update_disk_info+0x62/0x3b0 [nvme_core] > [ 369.745839] __nvme_revalidate_disk+0x8d/0x140 [nvme_core] > [ 369.745842] nvme_revalidate_disk+0xa4/0x140 [nvme_core] > [ 369.745843] ? blk_mq_run_hw_queue+0xba/0x100 > [ 369.745847] revalidate_disk+0x2b/0xa0 > [ 369.745850] nvme_validate_ns+0x46/0x5b0 [nvme_core] > [ 369.745852] ? __nvme_submit_sync_cmd+0xe0/0x1b0 [nvme_core] > [ 369.745855] nvme_scan_work+0x25a/0x310 [nvme_core] > [ 369.745859] process_one_work+0x1ab/0x380 > [ 369.745861] worker_thread+0x37/0x3b0 > [ 369.745862] kthread+0x120/0x140 > [ 369.745863] ? create_worker+0x1b0/0x1b0 > [ 369.745864] ? kthread_park+0x90/0x90 > [ 369.745867] ret_from_fork+0x35/0x40
On Thu, May 28, 2020 at 12:11:18PM -0700, Keith Busch wrote: > You can expect your fake timeout with 100% probablility to take 150 > seconds minimum to return a retryable request. Sorry, I should have said 300 seconds. We restart the timer for aborts, so 5 requeues * 30 seconds * 2 timer starts = 300 seconds.
It did come back. Just took a little longer. Alan [ 394.319378] nvme nvme0: I/O 960 QID 26 timeout, reset controller [ 394.334228] nvme nvme0: new error during reset [ 394.340125] nvme nvme0: Shutdown timeout set to 10 seconds [ 394.343452] nvme nvme0: 56/0/0 default/read/poll queues [ 394.343557] FAULT_INJECTION: forcing a failure. name fail_io_timeout, interval 1, probability 100, space 0, times 995 [ 394.343559] CPU: 53 PID: 0 Comm: swapper/53 Not tainted 5.7.0-rc7+ #2 [ 394.343559] Hardware name: Oracle Corporation ORACLE SERVER X6-2/ASM,MOTHERBOARD,1U, BIOS 38050100 08/30/2016 [ 394.343560] Call Trace: [ 394.343561] <IRQ> [ 394.343563] dump_stack+0x6d/0x9a [ 394.343564] should_fail.cold.5+0x32/0x42 [ 394.343566] blk_should_fake_timeout+0x26/0x30 [ 394.343566] blk_mq_complete_request+0x15/0x30 [ 394.343569] nvme_irq+0xd9/0x1f0 [nvme] [ 394.343571] __handle_irq_event_percpu+0x44/0x190 [ 394.343573] handle_irq_event_percpu+0x32/0x80 [ 394.343574] handle_irq_event+0x3b/0x5a [ 394.343575] handle_edge_irq+0x87/0x190 [ 394.343577] do_IRQ+0x54/0xe0 [ 394.343578] common_interrupt+0xf/0xf [ 394.343579] </IRQ> [ 394.343581] RIP: 0010:cpuidle_enter_state+0xc1/0x400 [ 394.343582] Code: ff e8 e3 41 93 ff 80 7d c7 00 74 17 9c 58 0f 1f 44 00 00 f6 c4 02 0f 85 d2 02 00 00 31 ff e8 16 c3 99 ff fb 66 0f 1f 44 00 00 <45> 85 e4 0f 88 3d 02 00 00 49 63 c4 48 8d 14 40 48 8d 0c c5 00 00 [ 394.343583] RSP: 0018:ffffae4ecc6cbe40 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffdd [ 394.343584] RAX: ffff9b537fc6cc40 RBX: ffffce4ebfc43200 RCX: 000000000000001f [ 394.343585] RDX: 0000005bd0b51f04 RSI: 0000000031573862 RDI: 0000000000000000 [ 394.343585] RBP: ffffae4ecc6cbe80 R08: 0000000000000002 R09: 000000000002c4c0 [ 394.343586] R10: 011c65ca3dee2b0c R11: ffff9b537fc6bb44 R12: 0000000000000002 [ 394.343586] R13: ffffffffa374c120 R14: ffffffffa374c208 R15: ffffffffa374c1f0 [ 394.343588] cpuidle_enter+0x2e/0x40 [ 394.343590] call_cpuidle+0x23/0x40 [ 394.343591] do_idle+0x230/0x270 [ 394.343592] cpu_startup_entry+0x1d/0x20 [ 394.343594] start_secondary+0x170/0x1c0 [ 394.343596] secondary_startup_64+0xb6/0xc0 [ 424.524341] nvme nvme0: I/O 960 QID 26 timeout, aborting [ 424.524389] nvme nvme0: Abort status: 0x0 [ 454.729622] nvme nvme0: I/O 960 QID 26 timeout, reset controller [ 454.740442] nvme nvme0: new error during reset [ 454.750403] nvme nvme0: Shutdown timeout set to 10 seconds [ 454.753508] nvme nvme0: 56/0/0 default/read/poll queues [ 454.753596] FAULT_INJECTION: forcing a failure. name fail_io_timeout, interval 1, probability 100, space 0, times 994 [ 454.753598] CPU: 53 PID: 0 Comm: swapper/53 Not tainted 5.7.0-rc7+ #2 [ 454.753599] Hardware name: Oracle Corporation ORACLE SERVER X6-2/ASM,MOTHERBOARD,1U, BIOS 38050100 08/30/2016 [ 454.753599] Call Trace: [ 454.753600] <IRQ> [ 454.753603] dump_stack+0x6d/0x9a [ 454.753604] should_fail.cold.5+0x32/0x42 [ 454.753605] blk_should_fake_timeout+0x26/0x30 [ 454.753606] blk_mq_complete_request+0x15/0x30 [ 454.753609] nvme_irq+0xd9/0x1f0 [nvme] [ 454.753612] __handle_irq_event_percpu+0x44/0x190 [ 454.753613] handle_irq_event_percpu+0x32/0x80 [ 454.753615] handle_irq_event+0x3b/0x5a [ 454.753616] handle_edge_irq+0x87/0x190 [ 454.753617] do_IRQ+0x54/0xe0 [ 454.753619] common_interrupt+0xf/0xf [ 454.753620] </IRQ> [ 454.753622] RIP: 0010:cpuidle_enter_state+0xc1/0x400 [ 454.753623] Code: ff e8 e3 41 93 ff 80 7d c7 00 74 17 9c 58 0f 1f 44 00 00 f6 c4 02 0f 85 d2 02 00 00 31 ff e8 16 c3 99 ff fb 66 0f 1f 44 00 00 <45> 85 e4 0f 88 3d 02 00 00 49 63 c4 48 8d 14 40 48 8d 0c c5 00 00 [ 454.753624] RSP: 0018:ffffae4ecc6cbe40 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffdd [ 454.753625] RAX: ffff9b537fc6cc40 RBX: ffffce4ebfc43200 RCX: 000000000000001f [ 454.753626] RDX: 00000069e16d295b RSI: 0000000031573862 RDI: 0000000000000000 [ 454.753626] RBP: ffffae4ecc6cbe80 R08: 0000000000000002 R09: 000000000002c4c0 [ 454.753627] R10: 011c65eebaf0c79e R11: ffff9b537fc6bb44 R12: 0000000000000002 [ 454.753627] R13: ffffffffa374c120 R14: ffffffffa374c208 R15: ffffffffa374c1f0 [ 454.753630] cpuidle_enter+0x2e/0x40 [ 454.753632] call_cpuidle+0x23/0x40 [ 454.753633] do_idle+0x230/0x270 [ 454.753634] cpu_startup_entry+0x1d/0x20 [ 454.753636] start_secondary+0x170/0x1c0 [ 454.753637] secondary_startup_64+0xb6/0xc0 [ 484.934587] nvme nvme0: I/O 960 QID 26 timeout, aborting [ 484.934641] nvme nvme0: Abort status: 0x0 [ 492.613861] INFO: task kworker/u114:2:1182 blocked for more than 245 seconds. [ 492.613884] Not tainted 5.7.0-rc7+ #2 [ 492.613912] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 492.613948] kworker/u114:2 D 0 1182 2 0x80004000 [ 492.613953] Workqueue: nvme-wq nvme_scan_work [nvme_core] [ 492.613954] Call Trace: [ 492.613956] __schedule+0x2dc/0x710 [ 492.613958] ? __kfifo_to_user_r+0x90/0x90 [ 492.613960] schedule+0x44/0xb0 [ 492.613961] blk_mq_freeze_queue_wait+0x4b/0xb0 [ 492.613962] ? finish_wait+0x80/0x80 [ 492.613963] blk_mq_freeze_queue+0x1a/0x20 [ 492.613966] nvme_update_disk_info+0x62/0x3b0 [nvme_core] [ 492.613968] __nvme_revalidate_disk+0x8d/0x140 [nvme_core] [ 492.613970] nvme_revalidate_disk+0xa4/0x140 [nvme_core] [ 492.613971] ? blk_mq_run_hw_queue+0xba/0x100 [ 492.613973] revalidate_disk+0x2b/0xa0 [ 492.613975] nvme_validate_ns+0x46/0x5b0 [nvme_core] [ 492.613978] ? __nvme_submit_sync_cmd+0xe0/0x1b0 [nvme_core] [ 492.613980] nvme_scan_work+0x25a/0x310 [nvme_core] [ 492.613983] process_one_work+0x1ab/0x380 [ 492.613984] worker_thread+0x37/0x3b0 [ 492.613985] kthread+0x120/0x140 [ 492.613990] ? create_worker+0x1b0/0x1b0 [ 492.613992] ? kthread_park+0x90/0x90 [ 492.614011] ret_from_fork+0x35/0x40 [ 515.139879] nvme nvme0: I/O 960 QID 26 timeout, reset controller [ 515.150634] nvme nvme0: new error during reset [ 515.158310] blk_update_request: I/O error, dev nvme0n1, sector 0 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0 [ 515.158346] Buffer I/O error on dev nvme0n1, logical block 0, async page read [ 515.160800] nvme nvme0: Shutdown timeout set to 10 seconds [ 515.163954] nvme nvme0: 56/0/0 default/read/poll queues [root@localhost ~]# On 5/28/20 12:14 PM, Keith Busch wrote: > On Thu, May 28, 2020 at 12:11:18PM -0700, Keith Busch wrote: >> You can expect your fake timeout with 100% probablility to take 150 >> seconds minimum to return a retryable request. > Sorry, I should have said 300 seconds. We restart the timer for aborts, > so 5 requeues * 30 seconds * 2 timer starts = 300 seconds.
On Fri, May 29, 2020 at 4:19 AM Alan Adamson <alan.adamson@oracle.com> wrote: > > It did come back. Just took a little longer. > > Alan > > [ 394.319378] nvme nvme0: I/O 960 QID 26 timeout, reset controller > [ 394.334228] nvme nvme0: new error during reset > [ 394.340125] nvme nvme0: Shutdown timeout set to 10 seconds > [ 394.343452] nvme nvme0: 56/0/0 default/read/poll queues > [ 394.343557] FAULT_INJECTION: forcing a failure. > name fail_io_timeout, interval 1, probability 100, space > 0, times 995 > [ 394.343559] CPU: 53 PID: 0 Comm: swapper/53 Not tainted 5.7.0-rc7+ #2 > [ 394.343559] Hardware name: Oracle Corporation ORACLE SERVER > X6-2/ASM,MOTHERBOARD,1U, BIOS 38050100 08/30/2016 > [ 394.343560] Call Trace: > [ 394.343561] <IRQ> > [ 394.343563] dump_stack+0x6d/0x9a > [ 394.343564] should_fail.cold.5+0x32/0x42 > [ 394.343566] blk_should_fake_timeout+0x26/0x30 > [ 394.343566] blk_mq_complete_request+0x15/0x30 > [ 394.343569] nvme_irq+0xd9/0x1f0 [nvme] > [ 394.343571] __handle_irq_event_percpu+0x44/0x190 > [ 394.343573] handle_irq_event_percpu+0x32/0x80 > [ 394.343574] handle_irq_event+0x3b/0x5a > [ 394.343575] handle_edge_irq+0x87/0x190 > [ 394.343577] do_IRQ+0x54/0xe0 > [ 394.343578] common_interrupt+0xf/0xf > [ 394.343579] </IRQ> > [ 394.343581] RIP: 0010:cpuidle_enter_state+0xc1/0x400 > [ 394.343582] Code: ff e8 e3 41 93 ff 80 7d c7 00 74 17 9c 58 0f 1f 44 > 00 00 f6 c4 02 0f 85 d2 02 00 00 31 ff e8 16 c3 99 ff fb 66 0f 1f 44 00 > 00 <45> 85 e4 0f 88 3d 02 00 00 49 63 c4 48 8d 14 40 48 8d 0c c5 00 00 > [ 394.343583] RSP: 0018:ffffae4ecc6cbe40 EFLAGS: 00000246 ORIG_RAX: > ffffffffffffffdd > [ 394.343584] RAX: ffff9b537fc6cc40 RBX: ffffce4ebfc43200 RCX: > 000000000000001f > [ 394.343585] RDX: 0000005bd0b51f04 RSI: 0000000031573862 RDI: > 0000000000000000 > [ 394.343585] RBP: ffffae4ecc6cbe80 R08: 0000000000000002 R09: > 000000000002c4c0 > [ 394.343586] R10: 011c65ca3dee2b0c R11: ffff9b537fc6bb44 R12: > 0000000000000002 > [ 394.343586] R13: ffffffffa374c120 R14: ffffffffa374c208 R15: > ffffffffa374c1f0 > [ 394.343588] cpuidle_enter+0x2e/0x40 > [ 394.343590] call_cpuidle+0x23/0x40 > [ 394.343591] do_idle+0x230/0x270 > [ 394.343592] cpu_startup_entry+0x1d/0x20 > [ 394.343594] start_secondary+0x170/0x1c0 > [ 394.343596] secondary_startup_64+0xb6/0xc0 > [ 424.524341] nvme nvme0: I/O 960 QID 26 timeout, aborting > [ 424.524389] nvme nvme0: Abort status: 0x0 > [ 454.729622] nvme nvme0: I/O 960 QID 26 timeout, reset controller > [ 454.740442] nvme nvme0: new error during reset > [ 454.750403] nvme nvme0: Shutdown timeout set to 10 seconds > [ 454.753508] nvme nvme0: 56/0/0 default/read/poll queues > [ 454.753596] FAULT_INJECTION: forcing a failure. > name fail_io_timeout, interval 1, probability 100, space > 0, times 994 > [ 454.753598] CPU: 53 PID: 0 Comm: swapper/53 Not tainted 5.7.0-rc7+ #2 > [ 454.753599] Hardware name: Oracle Corporation ORACLE SERVER > X6-2/ASM,MOTHERBOARD,1U, BIOS 38050100 08/30/2016 > [ 454.753599] Call Trace: > [ 454.753600] <IRQ> > [ 454.753603] dump_stack+0x6d/0x9a > [ 454.753604] should_fail.cold.5+0x32/0x42 > [ 454.753605] blk_should_fake_timeout+0x26/0x30 > [ 454.753606] blk_mq_complete_request+0x15/0x30 > [ 454.753609] nvme_irq+0xd9/0x1f0 [nvme] > [ 454.753612] __handle_irq_event_percpu+0x44/0x190 > [ 454.753613] handle_irq_event_percpu+0x32/0x80 > [ 454.753615] handle_irq_event+0x3b/0x5a > [ 454.753616] handle_edge_irq+0x87/0x190 > [ 454.753617] do_IRQ+0x54/0xe0 > [ 454.753619] common_interrupt+0xf/0xf > [ 454.753620] </IRQ> > [ 454.753622] RIP: 0010:cpuidle_enter_state+0xc1/0x400 > [ 454.753623] Code: ff e8 e3 41 93 ff 80 7d c7 00 74 17 9c 58 0f 1f 44 > 00 00 f6 c4 02 0f 85 d2 02 00 00 31 ff e8 16 c3 99 ff fb 66 0f 1f 44 00 > 00 <45> 85 e4 0f 88 3d 02 00 00 49 63 c4 48 8d 14 40 48 8d 0c c5 00 00 > [ 454.753624] RSP: 0018:ffffae4ecc6cbe40 EFLAGS: 00000246 ORIG_RAX: > ffffffffffffffdd > [ 454.753625] RAX: ffff9b537fc6cc40 RBX: ffffce4ebfc43200 RCX: > 000000000000001f > [ 454.753626] RDX: 00000069e16d295b RSI: 0000000031573862 RDI: > 0000000000000000 > [ 454.753626] RBP: ffffae4ecc6cbe80 R08: 0000000000000002 R09: > 000000000002c4c0 > [ 454.753627] R10: 011c65eebaf0c79e R11: ffff9b537fc6bb44 R12: > 0000000000000002 > [ 454.753627] R13: ffffffffa374c120 R14: ffffffffa374c208 R15: > ffffffffa374c1f0 > [ 454.753630] cpuidle_enter+0x2e/0x40 > [ 454.753632] call_cpuidle+0x23/0x40 > [ 454.753633] do_idle+0x230/0x270 > [ 454.753634] cpu_startup_entry+0x1d/0x20 > [ 454.753636] start_secondary+0x170/0x1c0 > [ 454.753637] secondary_startup_64+0xb6/0xc0 > [ 484.934587] nvme nvme0: I/O 960 QID 26 timeout, aborting > [ 484.934641] nvme nvme0: Abort status: 0x0 > [ 492.613861] INFO: task kworker/u114:2:1182 blocked for more than 245 > seconds. > [ 492.613884] Not tainted 5.7.0-rc7+ #2 > [ 492.613912] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [ 492.613948] kworker/u114:2 D 0 1182 2 0x80004000 > [ 492.613953] Workqueue: nvme-wq nvme_scan_work [nvme_core] > [ 492.613954] Call Trace: > [ 492.613956] __schedule+0x2dc/0x710 > [ 492.613958] ? __kfifo_to_user_r+0x90/0x90 > [ 492.613960] schedule+0x44/0xb0 > [ 492.613961] blk_mq_freeze_queue_wait+0x4b/0xb0 > [ 492.613962] ? finish_wait+0x80/0x80 > [ 492.613963] blk_mq_freeze_queue+0x1a/0x20 > [ 492.613966] nvme_update_disk_info+0x62/0x3b0 [nvme_core] > [ 492.613968] __nvme_revalidate_disk+0x8d/0x140 [nvme_core] > [ 492.613970] nvme_revalidate_disk+0xa4/0x140 [nvme_core] > [ 492.613971] ? blk_mq_run_hw_queue+0xba/0x100 > [ 492.613973] revalidate_disk+0x2b/0xa0 > [ 492.613975] nvme_validate_ns+0x46/0x5b0 [nvme_core] > [ 492.613978] ? __nvme_submit_sync_cmd+0xe0/0x1b0 [nvme_core] > [ 492.613980] nvme_scan_work+0x25a/0x310 [nvme_core] > [ 492.613983] process_one_work+0x1ab/0x380 > [ 492.613984] worker_thread+0x37/0x3b0 > [ 492.613985] kthread+0x120/0x140 > [ 492.613990] ? create_worker+0x1b0/0x1b0 > [ 492.613992] ? kthread_park+0x90/0x90 > [ 492.614011] ret_from_fork+0x35/0x40 > [ 515.139879] nvme nvme0: I/O 960 QID 26 timeout, reset controller > [ 515.150634] nvme nvme0: new error during reset Looks your kernel has applied patchset of '[PATCH 0/3] blk-mq/nvme: improve nvme-pci reset handler', and seems it works well. > [ 515.158310] blk_update_request: I/O error, dev nvme0n1, sector 0 op > 0x0:(READ) flags 0x0 phys_seg 1 prio class 0 > [ 515.158346] Buffer I/O error on dev nvme0n1, logical block 0, async > page read > [ 515.160800] nvme nvme0: Shutdown timeout set to 10 seconds > [ 515.163954] nvme nvme0: 56/0/0 default/read/poll queues The controller is reset to normal state even though timeout is triggered during reset. The hang from scan work context just means that blk_mq_freeze_queue() waits for too long(245sec) becuase IO request times out and is retried for 5 times, and that may not be avoided if you fail all IO requets for 1000 times. As I suggested to you in another thread, if you stop to fail IO requests after injecting failure for some time, the scan work will run to end and everything will be fine. That said NVMe's error handling becomes better after applying the patchs of '[PATCH 0/3] blk-mq/nvme: improve nvme-pci reset handler'. Thanks, Ming Lei
On Thu, May 28, 2020 at 11:35 PM Keith Busch <kbusch@kernel.org> wrote: > > Once the driver decides to cancel requests, the concept of those > requests timing out ceases to exist. Use __blk_mq_complete_request() to > bypass fake timeout error injection so that request reclaim may > proceed. > > Reviewed-by: Johannes Thumshirn <johannes.thumshirn@wdc.com> > Signed-off-by: Keith Busch <kbusch@kernel.org> > --- > drivers/nvme/host/core.c | 2 +- > 1 file changed, 1 insertion(+), 1 deletion(-) > > diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c > index ba860efd250d..f65a0b6cd988 100644 > --- a/drivers/nvme/host/core.c > +++ b/drivers/nvme/host/core.c > @@ -310,7 +310,7 @@ bool nvme_cancel_request(struct request *req, void *data, bool reserved) > return true; > > nvme_req(req)->status = NVME_SC_HOST_ABORTED_CMD; > - blk_mq_complete_request(req); > + __blk_mq_complete_request(req); > return true; > } > EXPORT_SYMBOL_GPL(nvme_cancel_request); Looks reaonable, Reviewed-by: Ming Lei <ming.lei@redhat.com>
On Fri, May 29, 2020 at 11:39:46AM +0800, Ming Lei wrote: > On Fri, May 29, 2020 at 4:19 AM Alan Adamson <alan.adamson@oracle.com> wrote: > That said NVMe's > error handling becomes better after applying the patchs of '[PATCH > 0/3] blk-mq/nvme: improve > nvme-pci reset handler'. I think that's a bit debatable. Alan is synthesizing a truly broken controller. The current code will abandon this controller after about 30 seconds. Your series will reset that broken controller indefinitely. Which of those options is better? I think degrading to an admin-only mode at some point would be preferable.
On Fri, May 29, 2020 at 9:22 PM Keith Busch <kbusch@kernel.org> wrote: > > On Fri, May 29, 2020 at 11:39:46AM +0800, Ming Lei wrote: > > On Fri, May 29, 2020 at 4:19 AM Alan Adamson <alan.adamson@oracle.com> wrote: > > That said NVMe's > > error handling becomes better after applying the patchs of '[PATCH > > 0/3] blk-mq/nvme: improve > > nvme-pci reset handler'. > > I think that's a bit debatable. Alan is synthesizing a truly broken > controller. The current code will abandon this controller after about 30 Not sure it can be thought as a truly broken controller. When waiting on nvme_wait_freeze() during reset, the controller has been in normal state. There is still chance to trigger timeout by any occasional event, just like any other timeout, which isn't special enough for us to have to kill the controller. > seconds. Your series will reset that broken controller indefinitely. > Which of those options is better? Removing controller is very horrible, because it becomes a brick basically, together with data loss. And we should retry enough before killing the controller. Mys series doesn't reset indefinitely since every request is just retried limited times(default is 5), at least chance should be provided to retry claimed times for IO requests. > > I think degrading to an admin-only mode at some point would be preferable. If the timeout event is occasional, this way gives up too early and doesn't retry claimed times, then peopele may complain for data loss. Thanks, Ming Lei
On Sat, May 30, 2020 at 06:23:08AM +0800, Ming Lei wrote: > On Fri, May 29, 2020 at 9:22 PM Keith Busch <kbusch@kernel.org> wrote: > > seconds. Your series will reset that broken controller indefinitely. > > Which of those options is better? > > Removing controller is very horrible, because it becomes a brick > basically, together > with data loss. And we should retry enough before killing the controller. > > Mys series doesn't reset indefinitely since every request is just > retried limited > times(default is 5), at least chance should be provided to retry > claimed times for IO > requests. Once the 5th retry is abandoned for all IO in the scheduled scan_work, the reset will succeed and schedule scan_work, which will revalidate disks, which will send new IO, which will timeout, then reset and repeat...
On Sat, May 30, 2020 at 6:32 AM Keith Busch <kbusch@kernel.org> wrote: > > On Sat, May 30, 2020 at 06:23:08AM +0800, Ming Lei wrote: > > On Fri, May 29, 2020 at 9:22 PM Keith Busch <kbusch@kernel.org> wrote: > > > seconds. Your series will reset that broken controller indefinitely. > > > Which of those options is better? > > > > Removing controller is very horrible, because it becomes a brick > > basically, together > > with data loss. And we should retry enough before killing the controller. > > > > Mys series doesn't reset indefinitely since every request is just > > retried limited > > times(default is 5), at least chance should be provided to retry > > claimed times for IO > > requests. > > Once the 5th retry is abandoned for all IO in the scheduled scan_work, > the reset will succeed and schedule scan_work, which will revalidate > disks, which will send new IO, which will timeout, then reset and > repeat... Firstly, we can recoganize this situation easily during reset, and give up after we have retried claimed times, will do that in V2. Secondly, not sure revalidate will send new IO since all previous IOs have been failed. Thanks, Ming Lei
diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c index ba860efd250d..f65a0b6cd988 100644 --- a/drivers/nvme/host/core.c +++ b/drivers/nvme/host/core.c @@ -310,7 +310,7 @@ bool nvme_cancel_request(struct request *req, void *data, bool reserved) return true; nvme_req(req)->status = NVME_SC_HOST_ABORTED_CMD; - blk_mq_complete_request(req); + __blk_mq_complete_request(req); return true; } EXPORT_SYMBOL_GPL(nvme_cancel_request);