* 6.13/regression/bisected - new nvme timeout errors
@ 2025-01-14 21:58 Mikhail Gavrilov
2025-02-10 8:47 ` Mikhail Gavrilov
2025-03-06 15:19 ` Keith Busch
0 siblings, 2 replies; 6+ messages in thread
From: Mikhail Gavrilov @ 2025-01-14 21:58 UTC (permalink / raw)
To: Christoph Hellwig, axboe, linux-nvme, Linux List Kernel Mailing,
Linux regressions mailing list
[-- Attachment #1: Type: text/plain, Size: 11966 bytes --]
Hi,
During 6.13 development cycle I spotted strange new nvme errors in the
log which I never seen before.
[87774.010474] nvme nvme1: I/O tag 0 (3000) opcode 0x1 (I/O Cmd) QID 1
timeout, aborting req_op:WRITE(1) size:131072
[87774.010502] nvme nvme1: I/O tag 1 (d001) opcode 0x1 (I/O Cmd) QID 1
timeout, aborting req_op:WRITE(1) size:131072
[87774.010507] nvme nvme1: I/O tag 2 (4002) opcode 0x1 (I/O Cmd) QID 1
timeout, aborting req_op:WRITE(1) size:131072
[87774.010513] nvme nvme1: I/O tag 3 (e003) opcode 0x1 (I/O Cmd) QID 1
timeout, aborting req_op:WRITE(1) size:131072
[87774.010525] nvme nvme1: Abort status: 0x0
[87774.010535] nvme nvme1: I/O tag 21 (a015) opcode 0x1 (I/O Cmd) QID
1 timeout, aborting req_op:WRITE(1) size:131072
[87774.010535] nvme nvme1: Abort status: 0x0
[87774.010538] nvme nvme1: I/O tag 22 (3016) opcode 0x1 (I/O Cmd) QID
1 timeout, aborting req_op:WRITE(1) size:32768
[87774.010539] nvme nvme1: Abort status: 0x0
[87774.010542] nvme nvme1: Abort status: 0x0
[87774.010545] nvme nvme1: Abort status: 0x0
[87774.010548] nvme nvme1: I/O tag 384 (7180) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:131072
[87774.010553] nvme nvme1: I/O tag 385 (b181) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:131072
[87774.010554] nvme nvme1: Abort status: 0x0
[87774.010557] nvme nvme1: I/O tag 386 (8182) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:131072
[87774.010561] nvme nvme1: I/O tag 387 (5183) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:131072
[87774.010562] nvme nvme1: Abort status: 0x0
[87774.010564] nvme nvme1: I/O tag 388 (6184) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:131072
[87774.010570] nvme nvme1: Abort status: 0x0
[87774.010573] nvme nvme1: I/O tag 393 (5189) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:131072
[87774.010578] nvme nvme1: Abort status: 0x0
[87774.010581] nvme nvme1: I/O tag 398 (718e) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:131072
[87774.010586] nvme nvme1: Abort status: 0x0
[87774.010589] nvme nvme1: I/O tag 403 (a193) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:61440
[87774.010593] nvme nvme1: Abort status: 0x0
[87774.010595] nvme nvme1: I/O tag 406 (0196) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:131072
[87774.010601] nvme nvme1: Abort status: 0x0
[87774.010604] nvme nvme1: I/O tag 411 (419b) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:40960
[87774.010608] nvme nvme1: Abort status: 0x0
[87774.010612] nvme nvme1: I/O tag 416 (91a0) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:131072
[87774.010616] nvme nvme1: Abort status: 0x0
[87774.010619] nvme nvme1: I/O tag 420 (f1a4) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:131072
[87774.010624] nvme nvme1: Abort status: 0x0
[87774.010627] nvme nvme1: I/O tag 425 (51a9) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:131072
[87774.010632] nvme nvme1: Abort status: 0x0
[87774.010634] nvme nvme1: I/O tag 429 (11ad) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:98304
[87774.010639] nvme nvme1: Abort status: 0x0
[87774.010641] nvme nvme1: I/O tag 433 (11b1) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:131072
[87774.010647] nvme nvme1: Abort status: 0x0
[87774.010650] nvme nvme1: I/O tag 438 (c1b6) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:131072
[87774.010654] nvme nvme1: Abort status: 0x0
[87774.010657] nvme nvme1: I/O tag 442 (91ba) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:131072
[87774.010662] nvme nvme1: Abort status: 0x0
[87774.010664] nvme nvme1: I/O tag 446 (d1be) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:32768
[87774.010670] nvme nvme1: Abort status: 0x0
[87774.010674] nvme nvme1: I/O tag 452 (f1c4) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:131072
[87774.010678] nvme nvme1: Abort status: 0x0
[87774.010681] nvme nvme1: I/O tag 456 (a1c8) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:131072
[87774.010686] nvme nvme1: Abort status: 0x0
[87774.010689] nvme nvme1: I/O tag 461 (31cd) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:90112
[87774.010694] nvme nvme1: Abort status: 0x0
[87774.010697] nvme nvme1: I/O tag 466 (51d2) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:8192
[87774.010702] nvme nvme1: Abort status: 0x0
[87774.010704] nvme nvme1: I/O tag 470 (e1d6) opcode 0x1 (I/O Cmd) QID
17 timeout, aborting req_op:WRITE(1) size:131072
[87774.010709] nvme nvme1: Abort status: 0x0
[87774.010717] nvme nvme1: Abort status: 0x0
[87774.010725] nvme nvme1: Abort status: 0x0
[87774.010732] nvme nvme1: Abort status: 0x0
[87774.034477] nvme nvme1: I/O tag 1 (a001) opcode 0x1 (I/O Cmd) QID
29 timeout, aborting req_op:WRITE(1) size:131072
[87774.034487] nvme nvme1: I/O tag 2 (0002) opcode 0x1 (I/O Cmd) QID
29 timeout, aborting req_op:WRITE(1) size:131072
[87774.034492] nvme nvme1: I/O tag 3 (d003) opcode 0x1 (I/O Cmd) QID
29 timeout, aborting req_op:WRITE(1) size:131072
[87774.034496] nvme nvme1: I/O tag 4 (b004) opcode 0x1 (I/O Cmd) QID
29 timeout, aborting req_op:WRITE(1) size:90112
[87774.034512] nvme nvme1: Abort status: 0x0
[87774.034524] nvme nvme1: Abort status: 0x0
[87774.034533] nvme nvme1: Abort status: 0x0
[87774.034537] nvme nvme1: Abort status: 0x0
[87774.051474] nvme nvme1: I/O tag 0 (1000) opcode 0x1 (I/O Cmd) QID
29 timeout, aborting req_op:WRITE(1) size:81920
[87774.051484] nvme nvme1: I/O tag 5 (e005) opcode 0x1 (I/O Cmd) QID
29 timeout, aborting req_op:WRITE(1) size:131072
[87774.051489] nvme nvme1: I/O tag 6 (a006) opcode 0x1 (I/O Cmd) QID
29 timeout, aborting req_op:WRITE(1) size:131072
[87774.051493] nvme nvme1: I/O tag 7 (7007) opcode 0x1 (I/O Cmd) QID
29 timeout, aborting req_op:WRITE(1) size:131072
[87774.051496] nvme nvme1: Abort status: 0x0
[87774.051514] nvme nvme1: I/O tag 25 (a019) opcode 0x1 (I/O Cmd) QID
29 timeout, aborting req_op:WRITE(1) size:131072
[87774.051518] nvme nvme1: Abort status: 0x0
[87774.051523] nvme nvme1: Abort status: 0x0
[87774.051523] nvme nvme1: I/O tag 31 (601f) opcode 0x1 (I/O Cmd) QID
29 timeout, aborting req_op:WRITE(1) size:131072
[87774.051527] nvme nvme1: Abort status: 0x0
[87774.051528] nvme nvme1: I/O tag 32 (c020) opcode 0x1 (I/O Cmd) QID
29 timeout, aborting req_op:WRITE(1) size:131072
[87774.051532] nvme nvme1: I/O tag 33 (4021) opcode 0x1 (I/O Cmd) QID
29 timeout, aborting req_op:WRITE(1) size:131072
[87774.051535] nvme nvme1: Abort status: 0x0
[87774.051539] nvme nvme1: I/O tag 37 (4025) opcode 0x1 (I/O Cmd) QID
29 timeout, aborting req_op:WRITE(1) size:131072
[87774.051540] nvme nvme1: Abort status: 0x0
[87774.051544] nvme nvme1: I/O tag 38 (0026) opcode 0x1 (I/O Cmd) QID
29 timeout, aborting req_op:WRITE(1) size:131072
[87774.051550] nvme nvme1: Abort status: 0x0
[87774.051559] nvme nvme1: Abort status: 0x0
[87774.051559] nvme nvme1: I/O tag 512 (f200) opcode 0x1 (I/O Cmd) QID
32 timeout, aborting req_op:WRITE(1) size:131072
[87774.051562] nvme nvme1: Abort status: 0x0
[87774.051564] nvme nvme1: I/O tag 513 (a201) opcode 0x1 (I/O Cmd) QID
32 timeout, aborting req_op:WRITE(1) size:131072
[87774.051568] nvme nvme1: I/O tag 514 (4202) opcode 0x1 (I/O Cmd) QID
32 timeout, aborting req_op:WRITE(1) size:131072
[87774.051570] nvme nvme1: Abort status: 0x0
[87774.051573] nvme nvme1: I/O tag 516 (d204) opcode 0x1 (I/O Cmd) QID
32 timeout, aborting req_op:WRITE(1) size:131072
[87774.051576] nvme nvme1: Abort status: 0x0
[87774.051579] nvme nvme1: I/O tag 520 (b208) opcode 0x1 (I/O Cmd) QID
32 timeout, aborting req_op:WRITE(1) size:131072
[87774.051583] nvme nvme1: Abort status: 0x0
[87774.051586] nvme nvme1: I/O tag 524 (f20c) opcode 0x1 (I/O Cmd) QID
32 timeout, aborting req_op:WRITE(1) size:131072
[87774.051592] nvme nvme1: Abort status: 0x0
[87774.051594] nvme nvme1: I/O tag 529 (f211) opcode 0x1 (I/O Cmd) QID
32 timeout, aborting req_op:WRITE(1) size:131072
[87774.051599] nvme nvme1: Abort status: 0x0
[87774.051601] nvme nvme1: I/O tag 533 (6215) opcode 0x1 (I/O Cmd) QID
32 timeout, aborting req_op:WRITE(1) size:131072
[87774.051607] nvme nvme1: Abort status: 0x0
[87774.051609] nvme nvme1: I/O tag 538 (121a) opcode 0x1 (I/O Cmd) QID
32 timeout, aborting req_op:WRITE(1) size:131072
[87774.051615] nvme nvme1: Abort status: 0x0
[87774.051628] nvme nvme1: Abort status: 0x0
[87774.051632] nvme nvme1: Abort status: 0x0
[87774.051642] nvme nvme1: Abort status: 0x0
[87775.490533] nvme nvme1: I/O tag 542 (021e) opcode 0x2 (I/O Cmd) QID
32 timeout, aborting req_op:READ(0) size:16384
[87775.490568] nvme nvme1: Abort status: 0x0
[87778.435607] nvme nvme1: I/O tag 543 (e21f) opcode 0x9 (I/O Cmd) QID
32 timeout, aborting req_op:DISCARD(3) size:45056
[87778.435643] nvme nvme1: Abort status: 0x0
[87801.658089] nvme nvme1: I/O tag 23 (7017) opcode 0x2 (I/O Cmd) QID
1 timeout, aborting req_op:READ(0) size:16384
[87801.658159] nvme nvme1: Abort status: 0x0
[87804.019139] nvme nvme1: I/O tag 0 (3000) opcode 0x1 (I/O Cmd) QID 1
timeout, reset controller
[87804.064993] nvme nvme1: 32/0/0 default/read/poll queues
I still haven't found a stable way to reproduce this.
But I'm pretty sure that if this error don't appearing within two
days, then we can assume that the kernel isn't affected by the
problem.
So I made bisection with above assumption and found this commit:
beadf0088501d9dcf2454b05d90d5d31ea3ba55f is the first bad commit
commit beadf0088501d9dcf2454b05d90d5d31ea3ba55f
Author: Christoph Hellwig <hch@lst.de>
Date: Wed Nov 13 16:20:41 2024 +0100
nvme-pci: reverse request order in nvme_queue_rqs
blk_mq_flush_plug_list submits requests in the reverse order that they
were submitted, which leads to a rather suboptimal I/O pattern especially
in rotational devices. Fix this by rewriting nvme_queue_rqs so that it
always pops the requests from the passed in request list, and then adds
them to the head of a local submit list. This actually simplifies the
code a bit as it removes the complicated list splicing, at the cost of
extra updates of the rq_next pointer. As that should be cache hot
anyway it should be an easy price to pay.
Fixes: d62cbcf62f2f ("nvme: add support for mq_ops->queue_rqs()")
Signed-off-by: Christoph Hellwig <hch@lst.de>
Link: https://lore.kernel.org/r/20241113152050.157179-2-hch@lst.de
Signed-off-by: Jens Axboe <axboe@kernel.dk>
drivers/nvme/host/pci.c | 39 +++++++++++++++++----------------------
1 file changed, 17 insertions(+), 22 deletions(-)
Christoph can you look into it, please?
My machine specs: https://linux-hardware.org/?probe=a4003b140c
Hiding under nvme1 is INTEL SSDPF2NV307TZ (ACV10340)
# nvme smart-log /dev/nvme1
Smart Log for NVME device:nvme1 namespace-id:ffffffff
critical_warning : 0
temperature : 98 °F (310 K)
available_spare : 100%
available_spare_threshold : 10%
percentage_used : 1%
endurance group critical warning summary: 0
Data Units Read : 694928083 (355.80 TB)
Data Units Written : 861761625 (441.22 TB)
host_read_commands : 6389380673
host_write_commands : 11970151442
controller_busy_time : 147
power_cycles : 474
power_on_hours : 17268
unsafe_shutdowns : 307
media_errors : 0
num_err_log_entries : 111
Warning Temperature Time : 566
Critical Composite Temperature Time : 0
Thermal Management T1 Trans Count : 0
Thermal Management T2 Trans Count : 0
Thermal Management T1 Total Time : 0
Thermal Management T2 Total Time : 0
I attached below build config and full kernel log.
--
Best Regards,
Mike Gavrilov.
[-- Attachment #2: .config.zip --]
[-- Type: application/zip, Size: 67405 bytes --]
[-- Attachment #3: dmesg-6.13.0-rc6-b62cef9a5c67.zip --]
[-- Type: application/zip, Size: 59451 bytes --]
^ permalink raw reply [flat|nested] 6+ messages in thread* Re: 6.13/regression/bisected - new nvme timeout errors
2025-01-14 21:58 6.13/regression/bisected - new nvme timeout errors Mikhail Gavrilov
@ 2025-02-10 8:47 ` Mikhail Gavrilov
2025-03-05 22:44 ` Mikhail Gavrilov
2025-03-06 15:19 ` Keith Busch
1 sibling, 1 reply; 6+ messages in thread
From: Mikhail Gavrilov @ 2025-02-10 8:47 UTC (permalink / raw)
To: Christoph Hellwig, axboe, linux-nvme, Linux List Kernel Mailing,
Linux regressions mailing list
[-- Attachment #1: Type: text/plain, Size: 12697 bytes --]
On Wed, Jan 15, 2025 at 2:58 AM Mikhail Gavrilov
<mikhail.v.gavrilov@gmail.com> wrote:
>
> Hi,
> During 6.13 development cycle I spotted strange new nvme errors in the
> log which I never seen before.
>
> [87774.010474] nvme nvme1: I/O tag 0 (3000) opcode 0x1 (I/O Cmd) QID 1
> timeout, aborting req_op:WRITE(1) size:131072
> [87774.010502] nvme nvme1: I/O tag 1 (d001) opcode 0x1 (I/O Cmd) QID 1
> timeout, aborting req_op:WRITE(1) size:131072
> [87774.010507] nvme nvme1: I/O tag 2 (4002) opcode 0x1 (I/O Cmd) QID 1
> timeout, aborting req_op:WRITE(1) size:131072
> [87774.010513] nvme nvme1: I/O tag 3 (e003) opcode 0x1 (I/O Cmd) QID 1
> timeout, aborting req_op:WRITE(1) size:131072
> [87774.010525] nvme nvme1: Abort status: 0x0
> [87774.010535] nvme nvme1: I/O tag 21 (a015) opcode 0x1 (I/O Cmd) QID
> 1 timeout, aborting req_op:WRITE(1) size:131072
> [87774.010535] nvme nvme1: Abort status: 0x0
> [87774.010538] nvme nvme1: I/O tag 22 (3016) opcode 0x1 (I/O Cmd) QID
> 1 timeout, aborting req_op:WRITE(1) size:32768
> [87774.010539] nvme nvme1: Abort status: 0x0
> [87774.010542] nvme nvme1: Abort status: 0x0
> [87774.010545] nvme nvme1: Abort status: 0x0
> [87774.010548] nvme nvme1: I/O tag 384 (7180) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:131072
> [87774.010553] nvme nvme1: I/O tag 385 (b181) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:131072
> [87774.010554] nvme nvme1: Abort status: 0x0
> [87774.010557] nvme nvme1: I/O tag 386 (8182) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:131072
> [87774.010561] nvme nvme1: I/O tag 387 (5183) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:131072
> [87774.010562] nvme nvme1: Abort status: 0x0
> [87774.010564] nvme nvme1: I/O tag 388 (6184) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:131072
> [87774.010570] nvme nvme1: Abort status: 0x0
> [87774.010573] nvme nvme1: I/O tag 393 (5189) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:131072
> [87774.010578] nvme nvme1: Abort status: 0x0
> [87774.010581] nvme nvme1: I/O tag 398 (718e) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:131072
> [87774.010586] nvme nvme1: Abort status: 0x0
> [87774.010589] nvme nvme1: I/O tag 403 (a193) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:61440
> [87774.010593] nvme nvme1: Abort status: 0x0
> [87774.010595] nvme nvme1: I/O tag 406 (0196) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:131072
> [87774.010601] nvme nvme1: Abort status: 0x0
> [87774.010604] nvme nvme1: I/O tag 411 (419b) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:40960
> [87774.010608] nvme nvme1: Abort status: 0x0
> [87774.010612] nvme nvme1: I/O tag 416 (91a0) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:131072
> [87774.010616] nvme nvme1: Abort status: 0x0
> [87774.010619] nvme nvme1: I/O tag 420 (f1a4) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:131072
> [87774.010624] nvme nvme1: Abort status: 0x0
> [87774.010627] nvme nvme1: I/O tag 425 (51a9) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:131072
> [87774.010632] nvme nvme1: Abort status: 0x0
> [87774.010634] nvme nvme1: I/O tag 429 (11ad) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:98304
> [87774.010639] nvme nvme1: Abort status: 0x0
> [87774.010641] nvme nvme1: I/O tag 433 (11b1) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:131072
> [87774.010647] nvme nvme1: Abort status: 0x0
> [87774.010650] nvme nvme1: I/O tag 438 (c1b6) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:131072
> [87774.010654] nvme nvme1: Abort status: 0x0
> [87774.010657] nvme nvme1: I/O tag 442 (91ba) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:131072
> [87774.010662] nvme nvme1: Abort status: 0x0
> [87774.010664] nvme nvme1: I/O tag 446 (d1be) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:32768
> [87774.010670] nvme nvme1: Abort status: 0x0
> [87774.010674] nvme nvme1: I/O tag 452 (f1c4) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:131072
> [87774.010678] nvme nvme1: Abort status: 0x0
> [87774.010681] nvme nvme1: I/O tag 456 (a1c8) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:131072
> [87774.010686] nvme nvme1: Abort status: 0x0
> [87774.010689] nvme nvme1: I/O tag 461 (31cd) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:90112
> [87774.010694] nvme nvme1: Abort status: 0x0
> [87774.010697] nvme nvme1: I/O tag 466 (51d2) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:8192
> [87774.010702] nvme nvme1: Abort status: 0x0
> [87774.010704] nvme nvme1: I/O tag 470 (e1d6) opcode 0x1 (I/O Cmd) QID
> 17 timeout, aborting req_op:WRITE(1) size:131072
> [87774.010709] nvme nvme1: Abort status: 0x0
> [87774.010717] nvme nvme1: Abort status: 0x0
> [87774.010725] nvme nvme1: Abort status: 0x0
> [87774.010732] nvme nvme1: Abort status: 0x0
> [87774.034477] nvme nvme1: I/O tag 1 (a001) opcode 0x1 (I/O Cmd) QID
> 29 timeout, aborting req_op:WRITE(1) size:131072
> [87774.034487] nvme nvme1: I/O tag 2 (0002) opcode 0x1 (I/O Cmd) QID
> 29 timeout, aborting req_op:WRITE(1) size:131072
> [87774.034492] nvme nvme1: I/O tag 3 (d003) opcode 0x1 (I/O Cmd) QID
> 29 timeout, aborting req_op:WRITE(1) size:131072
> [87774.034496] nvme nvme1: I/O tag 4 (b004) opcode 0x1 (I/O Cmd) QID
> 29 timeout, aborting req_op:WRITE(1) size:90112
> [87774.034512] nvme nvme1: Abort status: 0x0
> [87774.034524] nvme nvme1: Abort status: 0x0
> [87774.034533] nvme nvme1: Abort status: 0x0
> [87774.034537] nvme nvme1: Abort status: 0x0
> [87774.051474] nvme nvme1: I/O tag 0 (1000) opcode 0x1 (I/O Cmd) QID
> 29 timeout, aborting req_op:WRITE(1) size:81920
> [87774.051484] nvme nvme1: I/O tag 5 (e005) opcode 0x1 (I/O Cmd) QID
> 29 timeout, aborting req_op:WRITE(1) size:131072
> [87774.051489] nvme nvme1: I/O tag 6 (a006) opcode 0x1 (I/O Cmd) QID
> 29 timeout, aborting req_op:WRITE(1) size:131072
> [87774.051493] nvme nvme1: I/O tag 7 (7007) opcode 0x1 (I/O Cmd) QID
> 29 timeout, aborting req_op:WRITE(1) size:131072
> [87774.051496] nvme nvme1: Abort status: 0x0
> [87774.051514] nvme nvme1: I/O tag 25 (a019) opcode 0x1 (I/O Cmd) QID
> 29 timeout, aborting req_op:WRITE(1) size:131072
> [87774.051518] nvme nvme1: Abort status: 0x0
> [87774.051523] nvme nvme1: Abort status: 0x0
> [87774.051523] nvme nvme1: I/O tag 31 (601f) opcode 0x1 (I/O Cmd) QID
> 29 timeout, aborting req_op:WRITE(1) size:131072
> [87774.051527] nvme nvme1: Abort status: 0x0
> [87774.051528] nvme nvme1: I/O tag 32 (c020) opcode 0x1 (I/O Cmd) QID
> 29 timeout, aborting req_op:WRITE(1) size:131072
> [87774.051532] nvme nvme1: I/O tag 33 (4021) opcode 0x1 (I/O Cmd) QID
> 29 timeout, aborting req_op:WRITE(1) size:131072
> [87774.051535] nvme nvme1: Abort status: 0x0
> [87774.051539] nvme nvme1: I/O tag 37 (4025) opcode 0x1 (I/O Cmd) QID
> 29 timeout, aborting req_op:WRITE(1) size:131072
> [87774.051540] nvme nvme1: Abort status: 0x0
> [87774.051544] nvme nvme1: I/O tag 38 (0026) opcode 0x1 (I/O Cmd) QID
> 29 timeout, aborting req_op:WRITE(1) size:131072
> [87774.051550] nvme nvme1: Abort status: 0x0
> [87774.051559] nvme nvme1: Abort status: 0x0
> [87774.051559] nvme nvme1: I/O tag 512 (f200) opcode 0x1 (I/O Cmd) QID
> 32 timeout, aborting req_op:WRITE(1) size:131072
> [87774.051562] nvme nvme1: Abort status: 0x0
> [87774.051564] nvme nvme1: I/O tag 513 (a201) opcode 0x1 (I/O Cmd) QID
> 32 timeout, aborting req_op:WRITE(1) size:131072
> [87774.051568] nvme nvme1: I/O tag 514 (4202) opcode 0x1 (I/O Cmd) QID
> 32 timeout, aborting req_op:WRITE(1) size:131072
> [87774.051570] nvme nvme1: Abort status: 0x0
> [87774.051573] nvme nvme1: I/O tag 516 (d204) opcode 0x1 (I/O Cmd) QID
> 32 timeout, aborting req_op:WRITE(1) size:131072
> [87774.051576] nvme nvme1: Abort status: 0x0
> [87774.051579] nvme nvme1: I/O tag 520 (b208) opcode 0x1 (I/O Cmd) QID
> 32 timeout, aborting req_op:WRITE(1) size:131072
> [87774.051583] nvme nvme1: Abort status: 0x0
> [87774.051586] nvme nvme1: I/O tag 524 (f20c) opcode 0x1 (I/O Cmd) QID
> 32 timeout, aborting req_op:WRITE(1) size:131072
> [87774.051592] nvme nvme1: Abort status: 0x0
> [87774.051594] nvme nvme1: I/O tag 529 (f211) opcode 0x1 (I/O Cmd) QID
> 32 timeout, aborting req_op:WRITE(1) size:131072
> [87774.051599] nvme nvme1: Abort status: 0x0
> [87774.051601] nvme nvme1: I/O tag 533 (6215) opcode 0x1 (I/O Cmd) QID
> 32 timeout, aborting req_op:WRITE(1) size:131072
> [87774.051607] nvme nvme1: Abort status: 0x0
> [87774.051609] nvme nvme1: I/O tag 538 (121a) opcode 0x1 (I/O Cmd) QID
> 32 timeout, aborting req_op:WRITE(1) size:131072
> [87774.051615] nvme nvme1: Abort status: 0x0
> [87774.051628] nvme nvme1: Abort status: 0x0
> [87774.051632] nvme nvme1: Abort status: 0x0
> [87774.051642] nvme nvme1: Abort status: 0x0
> [87775.490533] nvme nvme1: I/O tag 542 (021e) opcode 0x2 (I/O Cmd) QID
> 32 timeout, aborting req_op:READ(0) size:16384
> [87775.490568] nvme nvme1: Abort status: 0x0
> [87778.435607] nvme nvme1: I/O tag 543 (e21f) opcode 0x9 (I/O Cmd) QID
> 32 timeout, aborting req_op:DISCARD(3) size:45056
> [87778.435643] nvme nvme1: Abort status: 0x0
> [87801.658089] nvme nvme1: I/O tag 23 (7017) opcode 0x2 (I/O Cmd) QID
> 1 timeout, aborting req_op:READ(0) size:16384
> [87801.658159] nvme nvme1: Abort status: 0x0
> [87804.019139] nvme nvme1: I/O tag 0 (3000) opcode 0x1 (I/O Cmd) QID 1
> timeout, reset controller
> [87804.064993] nvme nvme1: 32/0/0 default/read/poll queues
>
> I still haven't found a stable way to reproduce this.
> But I'm pretty sure that if this error don't appearing within two
> days, then we can assume that the kernel isn't affected by the
> problem.
> So I made bisection with above assumption and found this commit:
>
> beadf0088501d9dcf2454b05d90d5d31ea3ba55f is the first bad commit
> commit beadf0088501d9dcf2454b05d90d5d31ea3ba55f
> Author: Christoph Hellwig <hch@lst.de>
> Date: Wed Nov 13 16:20:41 2024 +0100
>
> nvme-pci: reverse request order in nvme_queue_rqs
>
> blk_mq_flush_plug_list submits requests in the reverse order that they
> were submitted, which leads to a rather suboptimal I/O pattern especially
> in rotational devices. Fix this by rewriting nvme_queue_rqs so that it
> always pops the requests from the passed in request list, and then adds
> them to the head of a local submit list. This actually simplifies the
> code a bit as it removes the complicated list splicing, at the cost of
> extra updates of the rq_next pointer. As that should be cache hot
> anyway it should be an easy price to pay.
>
> Fixes: d62cbcf62f2f ("nvme: add support for mq_ops->queue_rqs()")
> Signed-off-by: Christoph Hellwig <hch@lst.de>
> Link: https://lore.kernel.org/r/20241113152050.157179-2-hch@lst.de
> Signed-off-by: Jens Axboe <axboe@kernel.dk>
>
> drivers/nvme/host/pci.c | 39 +++++++++++++++++----------------------
> 1 file changed, 17 insertions(+), 22 deletions(-)
>
> Christoph can you look into it, please?
>
> My machine specs: https://linux-hardware.org/?probe=a4003b140c
> Hiding under nvme1 is INTEL SSDPF2NV307TZ (ACV10340)
>
> # nvme smart-log /dev/nvme1
> Smart Log for NVME device:nvme1 namespace-id:ffffffff
> critical_warning : 0
> temperature : 98 °F (310 K)
> available_spare : 100%
> available_spare_threshold : 10%
> percentage_used : 1%
> endurance group critical warning summary: 0
> Data Units Read : 694928083 (355.80 TB)
> Data Units Written : 861761625 (441.22 TB)
> host_read_commands : 6389380673
> host_write_commands : 11970151442
> controller_busy_time : 147
> power_cycles : 474
> power_on_hours : 17268
> unsafe_shutdowns : 307
> media_errors : 0
> num_err_log_entries : 111
> Warning Temperature Time : 566
> Critical Composite Temperature Time : 0
> Thermal Management T1 Trans Count : 0
> Thermal Management T2 Trans Count : 0
> Thermal Management T1 Total Time : 0
> Thermal Management T2 Total Time : 0
>
> I attached below build config and full kernel log.
>
> --
> Best Regards,
> Mike Gavrilov.
Hi again.
So no one looked at this?
Unfornitally this issue is still happening in 6.14-rc1 :(
I attached a fresh kernel log here.
--
Best Regards,
Mike Gavrilov.
[-- Attachment #2: dmesg-6.14.0-rc1-8f6629c004b1.zip --]
[-- Type: application/zip, Size: 55213 bytes --]
^ permalink raw reply [flat|nested] 6+ messages in thread* Re: 6.13/regression/bisected - new nvme timeout errors
2025-02-10 8:47 ` Mikhail Gavrilov
@ 2025-03-05 22:44 ` Mikhail Gavrilov
0 siblings, 0 replies; 6+ messages in thread
From: Mikhail Gavrilov @ 2025-03-05 22:44 UTC (permalink / raw)
To: Christoph Hellwig, axboe, linux-nvme, Linux List Kernel Mailing,
Linux regressions mailing list, axboe, Keith Busch, sagi
[-- Attachment #1: Type: text/plain, Size: 14244 bytes --]
On Mon, Feb 10, 2025 at 1:47 PM Mikhail Gavrilov
<mikhail.v.gavrilov@gmail.com> wrote:
>
> On Wed, Jan 15, 2025 at 2:58 AM Mikhail Gavrilov
> <mikhail.v.gavrilov@gmail.com> wrote:
> >
> > Hi,
> > During 6.13 development cycle I spotted strange new nvme errors in the
> > log which I never seen before.
> >
> > [87774.010474] nvme nvme1: I/O tag 0 (3000) opcode 0x1 (I/O Cmd) QID 1
> > timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010502] nvme nvme1: I/O tag 1 (d001) opcode 0x1 (I/O Cmd) QID 1
> > timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010507] nvme nvme1: I/O tag 2 (4002) opcode 0x1 (I/O Cmd) QID 1
> > timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010513] nvme nvme1: I/O tag 3 (e003) opcode 0x1 (I/O Cmd) QID 1
> > timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010525] nvme nvme1: Abort status: 0x0
> > [87774.010535] nvme nvme1: I/O tag 21 (a015) opcode 0x1 (I/O Cmd) QID
> > 1 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010535] nvme nvme1: Abort status: 0x0
> > [87774.010538] nvme nvme1: I/O tag 22 (3016) opcode 0x1 (I/O Cmd) QID
> > 1 timeout, aborting req_op:WRITE(1) size:32768
> > [87774.010539] nvme nvme1: Abort status: 0x0
> > [87774.010542] nvme nvme1: Abort status: 0x0
> > [87774.010545] nvme nvme1: Abort status: 0x0
> > [87774.010548] nvme nvme1: I/O tag 384 (7180) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010553] nvme nvme1: I/O tag 385 (b181) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010554] nvme nvme1: Abort status: 0x0
> > [87774.010557] nvme nvme1: I/O tag 386 (8182) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010561] nvme nvme1: I/O tag 387 (5183) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010562] nvme nvme1: Abort status: 0x0
> > [87774.010564] nvme nvme1: I/O tag 388 (6184) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010570] nvme nvme1: Abort status: 0x0
> > [87774.010573] nvme nvme1: I/O tag 393 (5189) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010578] nvme nvme1: Abort status: 0x0
> > [87774.010581] nvme nvme1: I/O tag 398 (718e) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010586] nvme nvme1: Abort status: 0x0
> > [87774.010589] nvme nvme1: I/O tag 403 (a193) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:61440
> > [87774.010593] nvme nvme1: Abort status: 0x0
> > [87774.010595] nvme nvme1: I/O tag 406 (0196) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010601] nvme nvme1: Abort status: 0x0
> > [87774.010604] nvme nvme1: I/O tag 411 (419b) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:40960
> > [87774.010608] nvme nvme1: Abort status: 0x0
> > [87774.010612] nvme nvme1: I/O tag 416 (91a0) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010616] nvme nvme1: Abort status: 0x0
> > [87774.010619] nvme nvme1: I/O tag 420 (f1a4) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010624] nvme nvme1: Abort status: 0x0
> > [87774.010627] nvme nvme1: I/O tag 425 (51a9) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010632] nvme nvme1: Abort status: 0x0
> > [87774.010634] nvme nvme1: I/O tag 429 (11ad) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:98304
> > [87774.010639] nvme nvme1: Abort status: 0x0
> > [87774.010641] nvme nvme1: I/O tag 433 (11b1) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010647] nvme nvme1: Abort status: 0x0
> > [87774.010650] nvme nvme1: I/O tag 438 (c1b6) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010654] nvme nvme1: Abort status: 0x0
> > [87774.010657] nvme nvme1: I/O tag 442 (91ba) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010662] nvme nvme1: Abort status: 0x0
> > [87774.010664] nvme nvme1: I/O tag 446 (d1be) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:32768
> > [87774.010670] nvme nvme1: Abort status: 0x0
> > [87774.010674] nvme nvme1: I/O tag 452 (f1c4) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010678] nvme nvme1: Abort status: 0x0
> > [87774.010681] nvme nvme1: I/O tag 456 (a1c8) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010686] nvme nvme1: Abort status: 0x0
> > [87774.010689] nvme nvme1: I/O tag 461 (31cd) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:90112
> > [87774.010694] nvme nvme1: Abort status: 0x0
> > [87774.010697] nvme nvme1: I/O tag 466 (51d2) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:8192
> > [87774.010702] nvme nvme1: Abort status: 0x0
> > [87774.010704] nvme nvme1: I/O tag 470 (e1d6) opcode 0x1 (I/O Cmd) QID
> > 17 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.010709] nvme nvme1: Abort status: 0x0
> > [87774.010717] nvme nvme1: Abort status: 0x0
> > [87774.010725] nvme nvme1: Abort status: 0x0
> > [87774.010732] nvme nvme1: Abort status: 0x0
> > [87774.034477] nvme nvme1: I/O tag 1 (a001) opcode 0x1 (I/O Cmd) QID
> > 29 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.034487] nvme nvme1: I/O tag 2 (0002) opcode 0x1 (I/O Cmd) QID
> > 29 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.034492] nvme nvme1: I/O tag 3 (d003) opcode 0x1 (I/O Cmd) QID
> > 29 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.034496] nvme nvme1: I/O tag 4 (b004) opcode 0x1 (I/O Cmd) QID
> > 29 timeout, aborting req_op:WRITE(1) size:90112
> > [87774.034512] nvme nvme1: Abort status: 0x0
> > [87774.034524] nvme nvme1: Abort status: 0x0
> > [87774.034533] nvme nvme1: Abort status: 0x0
> > [87774.034537] nvme nvme1: Abort status: 0x0
> > [87774.051474] nvme nvme1: I/O tag 0 (1000) opcode 0x1 (I/O Cmd) QID
> > 29 timeout, aborting req_op:WRITE(1) size:81920
> > [87774.051484] nvme nvme1: I/O tag 5 (e005) opcode 0x1 (I/O Cmd) QID
> > 29 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.051489] nvme nvme1: I/O tag 6 (a006) opcode 0x1 (I/O Cmd) QID
> > 29 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.051493] nvme nvme1: I/O tag 7 (7007) opcode 0x1 (I/O Cmd) QID
> > 29 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.051496] nvme nvme1: Abort status: 0x0
> > [87774.051514] nvme nvme1: I/O tag 25 (a019) opcode 0x1 (I/O Cmd) QID
> > 29 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.051518] nvme nvme1: Abort status: 0x0
> > [87774.051523] nvme nvme1: Abort status: 0x0
> > [87774.051523] nvme nvme1: I/O tag 31 (601f) opcode 0x1 (I/O Cmd) QID
> > 29 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.051527] nvme nvme1: Abort status: 0x0
> > [87774.051528] nvme nvme1: I/O tag 32 (c020) opcode 0x1 (I/O Cmd) QID
> > 29 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.051532] nvme nvme1: I/O tag 33 (4021) opcode 0x1 (I/O Cmd) QID
> > 29 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.051535] nvme nvme1: Abort status: 0x0
> > [87774.051539] nvme nvme1: I/O tag 37 (4025) opcode 0x1 (I/O Cmd) QID
> > 29 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.051540] nvme nvme1: Abort status: 0x0
> > [87774.051544] nvme nvme1: I/O tag 38 (0026) opcode 0x1 (I/O Cmd) QID
> > 29 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.051550] nvme nvme1: Abort status: 0x0
> > [87774.051559] nvme nvme1: Abort status: 0x0
> > [87774.051559] nvme nvme1: I/O tag 512 (f200) opcode 0x1 (I/O Cmd) QID
> > 32 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.051562] nvme nvme1: Abort status: 0x0
> > [87774.051564] nvme nvme1: I/O tag 513 (a201) opcode 0x1 (I/O Cmd) QID
> > 32 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.051568] nvme nvme1: I/O tag 514 (4202) opcode 0x1 (I/O Cmd) QID
> > 32 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.051570] nvme nvme1: Abort status: 0x0
> > [87774.051573] nvme nvme1: I/O tag 516 (d204) opcode 0x1 (I/O Cmd) QID
> > 32 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.051576] nvme nvme1: Abort status: 0x0
> > [87774.051579] nvme nvme1: I/O tag 520 (b208) opcode 0x1 (I/O Cmd) QID
> > 32 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.051583] nvme nvme1: Abort status: 0x0
> > [87774.051586] nvme nvme1: I/O tag 524 (f20c) opcode 0x1 (I/O Cmd) QID
> > 32 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.051592] nvme nvme1: Abort status: 0x0
> > [87774.051594] nvme nvme1: I/O tag 529 (f211) opcode 0x1 (I/O Cmd) QID
> > 32 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.051599] nvme nvme1: Abort status: 0x0
> > [87774.051601] nvme nvme1: I/O tag 533 (6215) opcode 0x1 (I/O Cmd) QID
> > 32 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.051607] nvme nvme1: Abort status: 0x0
> > [87774.051609] nvme nvme1: I/O tag 538 (121a) opcode 0x1 (I/O Cmd) QID
> > 32 timeout, aborting req_op:WRITE(1) size:131072
> > [87774.051615] nvme nvme1: Abort status: 0x0
> > [87774.051628] nvme nvme1: Abort status: 0x0
> > [87774.051632] nvme nvme1: Abort status: 0x0
> > [87774.051642] nvme nvme1: Abort status: 0x0
> > [87775.490533] nvme nvme1: I/O tag 542 (021e) opcode 0x2 (I/O Cmd) QID
> > 32 timeout, aborting req_op:READ(0) size:16384
> > [87775.490568] nvme nvme1: Abort status: 0x0
> > [87778.435607] nvme nvme1: I/O tag 543 (e21f) opcode 0x9 (I/O Cmd) QID
> > 32 timeout, aborting req_op:DISCARD(3) size:45056
> > [87778.435643] nvme nvme1: Abort status: 0x0
> > [87801.658089] nvme nvme1: I/O tag 23 (7017) opcode 0x2 (I/O Cmd) QID
> > 1 timeout, aborting req_op:READ(0) size:16384
> > [87801.658159] nvme nvme1: Abort status: 0x0
> > [87804.019139] nvme nvme1: I/O tag 0 (3000) opcode 0x1 (I/O Cmd) QID 1
> > timeout, reset controller
> > [87804.064993] nvme nvme1: 32/0/0 default/read/poll queues
> >
> > I still haven't found a stable way to reproduce this.
> > But I'm pretty sure that if this error don't appearing within two
> > days, then we can assume that the kernel isn't affected by the
> > problem.
> > So I made bisection with above assumption and found this commit:
> >
> > beadf0088501d9dcf2454b05d90d5d31ea3ba55f is the first bad commit
> > commit beadf0088501d9dcf2454b05d90d5d31ea3ba55f
> > Author: Christoph Hellwig <hch@lst.de>
> > Date: Wed Nov 13 16:20:41 2024 +0100
> >
> > nvme-pci: reverse request order in nvme_queue_rqs
> >
> > blk_mq_flush_plug_list submits requests in the reverse order that they
> > were submitted, which leads to a rather suboptimal I/O pattern especially
> > in rotational devices. Fix this by rewriting nvme_queue_rqs so that it
> > always pops the requests from the passed in request list, and then adds
> > them to the head of a local submit list. This actually simplifies the
> > code a bit as it removes the complicated list splicing, at the cost of
> > extra updates of the rq_next pointer. As that should be cache hot
> > anyway it should be an easy price to pay.
> >
> > Fixes: d62cbcf62f2f ("nvme: add support for mq_ops->queue_rqs()")
> > Signed-off-by: Christoph Hellwig <hch@lst.de>
> > Link: https://lore.kernel.org/r/20241113152050.157179-2-hch@lst.de
> > Signed-off-by: Jens Axboe <axboe@kernel.dk>
> >
> > drivers/nvme/host/pci.c | 39 +++++++++++++++++----------------------
> > 1 file changed, 17 insertions(+), 22 deletions(-)
> >
> > Christoph can you look into it, please?
> >
> > My machine specs: https://linux-hardware.org/?probe=a4003b140c
> > Hiding under nvme1 is INTEL SSDPF2NV307TZ (ACV10340)
> >
> > # nvme smart-log /dev/nvme1
> > Smart Log for NVME device:nvme1 namespace-id:ffffffff
> > critical_warning : 0
> > temperature : 98 °F (310 K)
> > available_spare : 100%
> > available_spare_threshold : 10%
> > percentage_used : 1%
> > endurance group critical warning summary: 0
> > Data Units Read : 694928083 (355.80 TB)
> > Data Units Written : 861761625 (441.22 TB)
> > host_read_commands : 6389380673
> > host_write_commands : 11970151442
> > controller_busy_time : 147
> > power_cycles : 474
> > power_on_hours : 17268
> > unsafe_shutdowns : 307
> > media_errors : 0
> > num_err_log_entries : 111
> > Warning Temperature Time : 566
> > Critical Composite Temperature Time : 0
> > Thermal Management T1 Trans Count : 0
> > Thermal Management T2 Trans Count : 0
> > Thermal Management T1 Total Time : 0
> > Thermal Management T2 Total Time : 0
> >
> > I attached below build config and full kernel log.
> >
> > --
> > Best Regards,
> > Mike Gavrilov.
>
> Hi again.
> So no one looked at this?
> Unfornitally this issue is still happening in 6.14-rc1 :(
> I attached a fresh kernel log here.
>
> --
> Best Regards,
> Mike Gavrilov.
Hi,
Has anyone tried to dig into it yet?
I have again tested two commits (beadf0088501) and (e559ee022658).
And ensure that issue with nvme:
I/O tag 448 (d1c0) opcode 0x1 (I/O Cmd) QID 22 timeout, aborting
req_op:WRITE(1) size:131072
definitely happens after a short period of time (~3990 seconds) if
kernel build at commit (beadf0088501) .
The problem is usually triggered by updating containers (podman pull ...).
Apparently this makes a lot of stress on my nvme SSD.
And if the kernel is built at commit (e559ee022658) it does not happen
even after 4 days of uptime (I checked it several times).
Bad news - on the kernel 6.14 rc5 (7eb172143d55) it still happens and
quite often.
Below I have attached three kernel logs.
One for the commit (beadf0088501) the second for the commit
(e559ee022658) and the third for 6.14 rc5 (7eb172143d55)
Please help fix it.
I'm ready to test any patches.
--
Best Regards,
Mike Gavrilov.
[-- Attachment #2: dmesg-6.12.0-rc4-10-beadf0088501d9dcf2454b05d90d5d31ea3ba55f-3.zip --]
[-- Type: application/zip, Size: 55828 bytes --]
[-- Attachment #3: dmesg-6.12.0-rc4-11-e559ee022658c70bdc07c4846bf279f5a5abc494-4.zip --]
[-- Type: application/zip, Size: 67018 bytes --]
[-- Attachment #4: dmesg-6.14.0-rc5-7eb172143d55.zip --]
[-- Type: application/zip, Size: 62027 bytes --]
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: 6.13/regression/bisected - new nvme timeout errors
2025-01-14 21:58 6.13/regression/bisected - new nvme timeout errors Mikhail Gavrilov
2025-02-10 8:47 ` Mikhail Gavrilov
@ 2025-03-06 15:19 ` Keith Busch
2025-03-23 9:49 ` Mikhail Gavrilov
1 sibling, 1 reply; 6+ messages in thread
From: Keith Busch @ 2025-03-06 15:19 UTC (permalink / raw)
To: Mikhail Gavrilov
Cc: Christoph Hellwig, axboe, linux-nvme, Linux List Kernel Mailing,
Linux regressions mailing list
On Wed, Jan 15, 2025 at 02:58:04AM +0500, Mikhail Gavrilov wrote:
> Hi,
> During 6.13 development cycle I spotted strange new nvme errors in the
> log which I never seen before.
>
> [87774.010474] nvme nvme1: I/O tag 0 (3000) opcode 0x1 (I/O Cmd) QID 1 timeout, aborting req_op:WRITE(1) size:131072
...
> I still haven't found a stable way to reproduce this.
> But I'm pretty sure that if this error don't appearing within two
> days, then we can assume that the kernel isn't affected by the
> problem.
> So I made bisection with above assumption and found this commit:
>
> beadf0088501d9dcf2454b05d90d5d31ea3ba55f is the first bad commit
> commit beadf0088501d9dcf2454b05d90d5d31ea3ba55f
> Author: Christoph Hellwig <hch@lst.de>
> Date: Wed Nov 13 16:20:41 2024 +0100
>
> nvme-pci: reverse request order in nvme_queue_rqs
The patch here uses the order recieved to dispatch commands in
consequetive submission queue entries, which is supposed to be the
desired behavior for any device. I did some testing on mailine, and it
sure looks like the order the driver does this is optimal, so I'm not
sure what's going on with your observation.
Do you have a scheduler enabled on your device?
How are you generating IO? Is it a pattern I should be able to replicate
with 'fio'?
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: 6.13/regression/bisected - new nvme timeout errors
2025-03-06 15:19 ` Keith Busch
@ 2025-03-23 9:49 ` Mikhail Gavrilov
2025-03-24 10:48 ` Maurizio Lombardi
0 siblings, 1 reply; 6+ messages in thread
From: Mikhail Gavrilov @ 2025-03-23 9:49 UTC (permalink / raw)
To: Keith Busch, mlombard
Cc: Christoph Hellwig, axboe, linux-nvme, Linux List Kernel Mailing,
Linux regressions mailing list
On Thu, Mar 6, 2025 at 8:19 PM Keith Busch <kbusch@kernel.org> wrote:
>
> On Wed, Jan 15, 2025 at 02:58:04AM +0500, Mikhail Gavrilov wrote:
> > Hi,
> > During 6.13 development cycle I spotted strange new nvme errors in the
> > log which I never seen before.
> >
> > [87774.010474] nvme nvme1: I/O tag 0 (3000) opcode 0x1 (I/O Cmd) QID 1 timeout, aborting req_op:WRITE(1) size:131072
>
> ...
>
> > I still haven't found a stable way to reproduce this.
> > But I'm pretty sure that if this error don't appearing within two
> > days, then we can assume that the kernel isn't affected by the
> > problem.
> > So I made bisection with above assumption and found this commit:
> >
> > beadf0088501d9dcf2454b05d90d5d31ea3ba55f is the first bad commit
> > commit beadf0088501d9dcf2454b05d90d5d31ea3ba55f
> > Author: Christoph Hellwig <hch@lst.de>
> > Date: Wed Nov 13 16:20:41 2024 +0100
> >
> > nvme-pci: reverse request order in nvme_queue_rqs
>
> The patch here uses the order recieved to dispatch commands in
> consequetive submission queue entries, which is supposed to be the
> desired behavior for any device. I did some testing on mailine, and it
> sure looks like the order the driver does this is optimal, so I'm not
> sure what's going on with your observation.
>
> Do you have a scheduler enabled on your device?
>
> How are you generating IO? Is it a pattern I should be able to replicate
> with 'fio'?
Sorry for not answering for a long time, but all because I was testing
the off-list patch that was sent to me by Maurizio Lombardi.
diff --git a/drivers/nvme/host/pci.c b/drivers/nvme/host/pci.c
index 950289405ef2..990d9ef1eef9 100644
--- a/drivers/nvme/host/pci.c
+++ b/drivers/nvme/host/pci.c
@@ -989,6 +989,9 @@ static void nvme_submit_cmds(struct nvme_queue
*nvmeq, struct rq_list *rqlist)
{
struct request *req;
+ if (rq_list_empty(rqlist))
+ return;
+
spin_lock(&nvmeq->sq_lock);
while ((req = rq_list_pop(rqlist))) {
struct nvme_iod *iod = blk_mq_rq_to_pdu(req);
And I want to say right away that this patch solved my problem. I
double checked, and both times the system worked for 4 days without
errors:
nvme nvme0: I/O tag 960 (33c0) opcode 0x2 (I/O Cmd) QID 7 timeout,
aborting req_op:READ(0) size:16384
nvme nvme0: I/O tag 961 (33c1) opcode 0x2 (I/O Cmd) QID 7 timeout,
aborting req_op:READ(0) size:8192
nvme nvme0: Abort status: 0x0
* * *
nvme nvme0: I/O tag 960 (33c0) opcode 0x2 (I/O Cmd) QID 7 timeout,
reset controller
and subsequent freezing of some applications.
> Do you have a scheduler enabled on your device?
No. nvme0 is server-tire 30TB SSD.
> head /sys/block/*/queue/scheduler
==> /sys/block/nvme0n1/queue/scheduler <==
[none] mq-deadline kyber bfq
==> /sys/block/nvme1n1/queue/scheduler <==
[none] mq-deadline kyber bfq
==> /sys/block/sda/queue/scheduler <==
none mq-deadline kyber [bfq]
==> /sys/block/sdb/queue/scheduler <==
none mq-deadline kyber [bfq]
> How are you generating IO? Is it a pattern I should be able to replicate with 'fio'?
It's very complicated. Because it happens only when I update (podman
pull) a large (16 GB) Docker container.
$ podman images
REPOSITORY TAG
IMAGE ID CREATED SIZE
dev-image-store.my-company.com/local-stand/service 25.2100-latest
513139713b48 19 hours ago 16.5 GB
dev-image-store.my-company.com/local-stand/service 25.1220-latest
920708d4b3dc 9 days ago 16.8 GB
dev-image-store.my-company.com/local-stand/service 25.1220
67d2af91f323 10 days ago 16.8 GB
dev-image-store.my-company.com/local-stand/service 25.2100
24e6817bff52 3 weeks ago 16.4 GB
Podman stores its images on the 30TB BTRFS partition located in /home.
--
Best Regards,
Mike Gavrilov.
^ permalink raw reply related [flat|nested] 6+ messages in thread* Re: 6.13/regression/bisected - new nvme timeout errors
2025-03-23 9:49 ` Mikhail Gavrilov
@ 2025-03-24 10:48 ` Maurizio Lombardi
0 siblings, 0 replies; 6+ messages in thread
From: Maurizio Lombardi @ 2025-03-24 10:48 UTC (permalink / raw)
To: Mikhail Gavrilov, Keith Busch
Cc: Christoph Hellwig, axboe, linux-nvme, Linux List Kernel Mailing,
Linux regressions mailing list
On Sun Mar 23, 2025 at 10:49 AM CET, Mikhail Gavrilov wrote:
> On Thu, Mar 6, 2025 at 8:19 PM Keith Busch <kbusch@kernel.org> wrote:
>>
>> >
>> > nvme-pci: reverse request order in nvme_queue_rqs
>>
>> The patch here uses the order recieved to dispatch commands in
>> consequetive submission queue entries, which is supposed to be the
>> desired behavior for any device. I did some testing on mailine, and it
>> sure looks like the order the driver does this is optimal, so I'm not
>> sure what's going on with your observation.
>>
>> Do you have a scheduler enabled on your device?
>>
>> How are you generating IO? Is it a pattern I should be able to replicate
>> with 'fio'?
>
> Sorry for not answering for a long time, but all because I was testing
> the off-list patch that was sent to me by Maurizio Lombardi.
>
> diff --git a/drivers/nvme/host/pci.c b/drivers/nvme/host/pci.c
> index 950289405ef2..990d9ef1eef9 100644
> --- a/drivers/nvme/host/pci.c
> +++ b/drivers/nvme/host/pci.c
> @@ -989,6 +989,9 @@ static void nvme_submit_cmds(struct nvme_queue
> *nvmeq, struct rq_list *rqlist)
> {
> struct request *req;
>
> + if (rq_list_empty(rqlist))
> + return;
> +
> spin_lock(&nvmeq->sq_lock);
> while ((req = rq_list_pop(rqlist))) {
> struct nvme_iod *iod = blk_mq_rq_to_pdu(req);
>
> And I want to say right away that this patch solved my problem. I
> double checked, and both times the system worked for 4 days without
> errors:
>
Glad to hear it worked!
Keith, I think the problem here is simply that nvme_write_sq_db() ends up
being called even when the rqlist is empty and this couldn't happen before
the changes introduced by commit "nvme-pci: reverse request order in
nvme_queue_rqs".
If you say that this change makes sense I can submit a formal patch.
Maurizio
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2025-03-24 11:15 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2025-01-14 21:58 6.13/regression/bisected - new nvme timeout errors Mikhail Gavrilov
2025-02-10 8:47 ` Mikhail Gavrilov
2025-03-05 22:44 ` Mikhail Gavrilov
2025-03-06 15:19 ` Keith Busch
2025-03-23 9:49 ` Mikhail Gavrilov
2025-03-24 10:48 ` Maurizio Lombardi
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox