linux-block.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* [bug report] Hang on sync after dd
@ 2020-11-30 11:22 John Garry
  2020-12-01 10:26 ` Kashyap Desai
  2020-12-01 12:34 ` Ming Lei
  0 siblings, 2 replies; 9+ messages in thread
From: John Garry @ 2020-11-30 11:22 UTC (permalink / raw)
  To: Hannes Reinecke, Ming Lei, Sumit Saxena, Kashyap Desai,
	Sumit Saxena, Bart Van Assche
  Cc: chenxiang, linux-scsi@vger.kernel.org,
	linux-block@vger.kernel.org, Ewan Milne, Long Li,
	Martin K . Petersen

Hi all,

Some guys internally upgraded to v5.10-rcX and start to see a hang after 
dd + sync for a large file:
- mount /dev/sda1 (ext4 filesystem) to directory /mnt;
- run "if=/dev/zero of=test1 bs=1M count=2000" on directory /mnt;
- run "sync"

and get:

[  367.912761] INFO: task jbd2/sdb1-8:3602 blocked for more than 120
seconds.
[  367.919618]       Not tainted 5.10.0-rc1-109488-g32ded76956b6 #948
[  367.925776] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[  367.933579] task:jbd2/sdb1-8     state:D stack:    0 pid: 3602
ppid:     2 flags:0x00000028
[  367.941901] Call trace:
[  367.944351] __switch_to+0xb8/0x168
[  367.947840] __schedule+0x30c/0x670
[  367.951326] schedule+0x70/0x108
[  367.954550] io_schedule+0x1c/0xe8
[  367.957948] bit_wait_io+0x18/0x68
[  367.961346] __wait_on_bit+0x78/0xf0
[  367.964919] out_of_line_wait_on_bit+0x8c/0xb0
[  367.969356] __wait_on_buffer+0x30/0x40
[  367.973188] jbd2_journal_commit_transaction+0x1370/0x1958
[  367.978661] kjournald2+0xcc/0x260
[  367.982061] kthread+0x150/0x158
[  367.985288] ret_from_fork+0x10/0x34
[  367.988860] INFO: task sync:3823 blocked for more than 120 seconds.
[  367.995102]       Not tainted 5.10.0-rc1-109488-g32ded76956b6 #948
[  368.001265] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[  368.009067] task:sync            state:D stack:    0 pid: 3823 ppid:
3450 flags:0x00000009
[  368.017397] Call trace:
[  368.019841] __switch_to+0xb8/0x168
[  368.023320] __schedule+0x30c/0x670
[  368.026804] schedule+0x70/0x108
[  368.030025] jbd2_log_wait_commit+0xbc/0x158
[  368.034290] ext4_sync_fs+0x188/0x1c8
[  368.037947] sync_fs_one_sb+0x30/0x40
[  368.041606] iterate_supers+0x9c/0x138
[  368.045350] ksys_sync+0x64/0xc0
[  368.048569] __arm64_sys_sync+0x10/0x20
[  368.052398] el0_svc_common.constprop.3+0x68/0x170
[  368.057177] do_el0_svc+0x24/0x90
[  368.060482] el0_sync_handler+0x118/0x168
[  368.064478]  el0_sync+0x158/0x180

The issue was reported here originally:
https://lore.kernel.org/linux-ext4/4d18326e-9ca2-d0cb-7cb8-cb56981280da@hisilicon.com/

But it looks like issue related to recent work for SCSI MQ.

They can only create with hisi_sas v3 hw. I could not create with 
megaraid sas on the same dev platform or hisi_sas on a similar dev board.

Reverting "scsi: core: Only re-run queue in scsi_end_request() if device 
queue is busy" seems solve the issue. Also, checking out to patch prior 
to "scsi: hisi_sas: Switch v3 hw to MQ" seems to not have the issue.

It occurs on SATA disks only, rather than SAS disks also, it seems. 
Maybe related to IO depth being smaller on SATA disk (32 vs 64), which 
can cause budget fail.

"mq-deadline" and "none" schedulers look to have the issue.

@Kashyap, have you guys tested megaraid sas much for this?

Thanks,
John


Block debugfs info is as follows:

estuary:/sys/kernel/debug/block/sda/hctx8$ cat
active cpu101/ cpu96/ cpu99/ dispatch_busy io_poll sched_tags tags
busy cpu102/ cpu97/ ctx_map dispatched queued sched_tags_bitmap tags_bitmap
cpu100/ cpu103/ cpu98/ dispatch flags run state type
estuary:/sys/kernel/debug/block/sda/hctx8$ cat cpu
cpu100/ cpu101/ cpu102/ cpu103/ cpu96/ cpu97/ cpu98/ cpu99/
estuary:/sys/kernel/debug/block/sda/hctx8$ cat cpu
cpu100/ cpu101/ cpu102/ cpu103/ cpu96/ cpu97/ cpu98/ cpu99/
estuary:/sys/kernel/debug/block/sda/hctx8$ cat cpu96/
completed default_rq_list dispatched merged poll_rq_list read_rq_list
estuary:/sys/kernel/debug/block/sda/hctx8$ cat cpu96/dispatched
0 0
estuary:/sys/kernel/debug/block/sda/hctx8$ cat cpu97/dispatched
0 0
estuary:/sys/kernel/debug/block/sda/hctx8$ cat cpu98/dispatched
0 0
estuary:/sys/kernel/debug/block/sda/hctx8$ cat cpu99/dispatched
0 0
estuary:/sys/kernel/debug/block/sda/hctx8$ cat cpu100/dispatched
3 0
estuary:/sys/kernel/debug/block/sda/hctx8$ cat cpu100/completed
2 0
estuary:/sys/kernel/debug/block/sda/hctx8$
estuary:/sys/kernel/debug/block/sda/hctx8$
estuary:/sys/kernel/debug/block/sda/hctx8$ cat state
SCHED_RESTART
estuary:/sys/kernel/debug/block/sda/hctx8$ ls
active cpu101 cpu96 cpu99 dispatch_busy io_poll sched_tags tags
busy cpu102 cpu97 ctx_map dispatched queued sched_tags_bitmap tags_bitmap
cpu100 cpu103 cpu98 dispatch flags run state type
estuary:/sys/kernel/debug/block/sda/hctx8$ cat dispatch
000000007abb596e {.op=FLUSH, .cmd_flags=PREFLUSH, 
.rq_flags=FLUSH_SEQ|MQ_INFLIGHT|DONTPREP, .state=idle, .tag=21, 
.internal_tag=-1, .cmd=opcode=0x35 35 00 00 00 00 00 00 00 00 00, 
.retries=0, .result = 0x0, .flags=TAGGED|INITIALIZED|3, .timeout=60.000, 
allocated 2208.876 s ago}
estuary:/sys/kernel/debug/block/sda/hctx8$


On cpu100, it seems completed is less than number dispatched.


^ permalink raw reply	[flat|nested] 9+ messages in thread
end of thread, other threads:[~2020-12-02  9:08 UTC | newest]

Thread overview: 9+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2020-11-30 11:22 [bug report] Hang on sync after dd John Garry
2020-12-01 10:26 ` Kashyap Desai
2020-12-01 11:48   ` John Garry
2020-12-01 12:34 ` Ming Lei
2020-12-02  1:44   ` chenxiang (M)
2020-12-02  3:22     ` Ming Lei
2020-12-02  6:22       ` chenxiang (M)
2020-12-02  7:26         ` Ming Lei
2020-12-02  9:06           ` chenxiang (M)

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).