On Tue, 2017-03-28 at 08:06 -0600, Jens Axboe wrote: > On Mon, Mar 27 2017, Bart Van Assche wrote: > > Hello Jens, > > > > If I leave the srp-test software running for a few minutes using the > > following command: > > > > # while ~bart/software/infiniband/srp-test/run_tests -d -r 30; do :; done > > > > then after some time the following complaint appears for multiple > > kworkers: > > > > INFO: task kworker/9:0:65 blocked for more than 480 seconds. > > Tainted: G I 4.11.0-rc4-dbg+ #5 > > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > > kworker/9:0 D 0 65 2 0x00000000 > > Workqueue: dio/dm-0 dio_aio_complete_work > > Call Trace: > > __schedule+0x3df/0xc10 > > schedule+0x38/0x90 > > rwsem_down_write_failed+0x2c4/0x4c0 > > call_rwsem_down_write_failed+0x17/0x30 > > down_write+0x5a/0x70 > > __generic_file_fsync+0x43/0x90 > > ext4_sync_file+0x2d0/0x550 > > vfs_fsync_range+0x46/0xa0 > > dio_complete+0x181/0x1b0 > > dio_aio_complete_work+0x17/0x20 > > process_one_work+0x208/0x6a0 > > worker_thread+0x49/0x4a0 > > kthread+0x107/0x140 > > ret_from_fork+0x2e/0x40 > > > > I had not yet observed this behavior with kernel v4.10 or older. If this > > happens and I check the queue state with the following script: > > Can you include the 'state' file in your script? > > Do you know when this started happening? You say it doesn't happen in > 4.10, but did it pass earlier in the 4.11-rc cycle? > > Does it reproduce with dm? > > I can't tell from your report if this is new in the 4.11 series, > > > The kernel tree I used in my tests is the result of merging the > > following commits: > > * commit 3dca2c2f3d3b from git://git.kernel.dk/linux-block.git > > ("Merge branch 'for-4.12/block' into for-next") > > * commit f88ab0c4b481 from git://git.kernel.org/pub/scm/linux/kernel/git/mkp/scsi.git > > ("scsi: libsas: fix ata xfer length") > > * commit ad0376eb1483 from git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git > > ("Merge tag 'edac_for_4.11_2' of git://git.kernel.org/pub/scm/linux/kernel/git/bp/bp") > > Can we try and isolate it a bit - -rc4 alone, for instance? Hello Jens, Sorry but performing a bisect would be hard: without recent SCSI and block layer fixes this test triggers other failures before the lockup reported in this e-mail is triggered. See e.g. https://marc.info/?l=linux-scsi&m=148979716822799. I do not know whether it would be possible to modify the test such that only the dm driver is involved but no SCSI code. When I reran the test this morning the hang was triggered by the 02-sq-on-mq test. This means that dm was used in blk-sq mode and that blk-mq was used for the ib_srp SCSI device instances. Please find below the updated script and its output. --- #!/bin/bash show_state() { local a dev=$1 for a in device/state queue/scheduler; do [ -e "$dev/$a" ] && grep -aH '' "$dev/$a" done } cd /sys/class/block || exit $? for dev in *; do if [ -e "$dev/mq" ]; then echo "$dev" pending=0 for f in "$dev"/mq/*/{pending,*/rq_list}; do [ -e "$f" ] || continue if { read -r line1 && read -r line2; } <"$f"; then echo "$f" echo "$line1 $line2" >/dev/null head -n 9 "$f" ((pending++)) fi done ( busy=0 cd /sys/kernel/debug/block >&/dev/null && for d in "$dev"/mq/*; do [ ! -d "$d" ] && continue grep -q '^busy=0$' "$d/tags" && continue ((busy++)) for f in "$d"/{dispatch,tags*,cpu*/rq_list}; do [ -e "$f" ] && grep -aH '' "$f" done done exit $busy ) pending=$((pending+$?)) [ "$pending" -gt 0 ] && show_state "$dev" fi done --- sda sdb sdc sdd sde sde/mq/2/dispatch:ffff8803f5b65d00 {.cmd_flags=0xca01, .rq_flags=0x2040, .tag=37, .internal_tag=-1} sde/mq/2/tags:nr_tags=62 sde/mq/2/tags:nr_reserved_tags=0 sde/mq/2/tags:active_queues=0 sde/mq/2/tags: sde/mq/2/tags:bitmap_tags: sde/mq/2/tags:depth=62 sde/mq/2/tags:busy=31 sde/mq/2/tags:bits_per_word=8 sde/mq/2/tags:map_nr=8 sde/mq/2/tags:alloc_hint={54, 43, 44, 43, 22, 42, 52, 4, 10, 7, 16, 32, 11, 17, 44, 26, 51, 59, 9, 45, 9, 55, 10, 44, 22, 46, 25, 25, 21, 18, 52, 32} sde/mq/2/tags:wake_batch=7 sde/mq/2/tags:wake_index=0 sde/mq/2/tags:ws={ sde/mq/2/tags: {.wait_cnt=7, .wait=inactive}, sde/mq/2/tags: {.wait_cnt=7, .wait=inactive}, sde/mq/2/tags: {.wait_cnt=7, .wait=inactive}, sde/mq/2/tags: {.wait_cnt=7, .wait=inactive}, sde/mq/2/tags: {.wait_cnt=7, .wait=inactive}, sde/mq/2/tags: {.wait_cnt=7, .wait=inactive}, sde/mq/2/tags: {.wait_cnt=7, .wait=inactive}, sde/mq/2/tags: {.wait_cnt=7, .wait=inactive}, sde/mq/2/tags:} sde/mq/2/tags:round_robin=0 sde/mq/2/tags_bitmap:00000000: 7f00 0000 e0ff ff1f sde/mq/2/cpu9/rq_list:ffff8803f5b67440 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=38, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff8803f5b68b80 {.cmd_flags=0xca01, .rq_flags=0x2040, .tag=39, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff8803f5b6a2c0 {.cmd_flags=0xca01, .rq_flags=0x2040, .tag=40, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff8803f5b6ba00 {.cmd_flags=0xca01, .rq_flags=0x2040, .tag=41, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff8803f5b6d140 {.cmd_flags=0xca01, .rq_flags=0x2040, .tag=42, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff8803f5b6e880 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=43, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff880373ac0000 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=44, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff880373ac1740 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=45, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff880373ac2e80 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=46, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff880373ac45c0 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=47, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff880373ac5d00 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=48, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff880373ac7440 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=49, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff880373ac8b80 {.cmd_flags=0xca01, .rq_flags=0x2040, .tag=50, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff880373aca2c0 {.cmd_flags=0xca01, .rq_flags=0x2040, .tag=51, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff880373acba00 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=52, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff880373acd140 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=53, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff880373ace880 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=54, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff8803f4950000 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=55, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff8803f4951740 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=56, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff8803f4952e80 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=57, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff8803f49545c0 {.cmd_flags=0xca01, .rq_flags=0x2040, .tag=58, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff8803f4955d00 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=59, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff8803f4957440 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=60, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff88036bfe0000 {.cmd_flags=0xca01, .rq_flags=0x2040, .tag=0, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff88036bfe1740 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=1, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff88036bfe2e80 {.cmd_flags=0xca01, .rq_flags=0x2040, .tag=2, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff88036bfe45c0 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=3, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff88036bfe5d00 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=4, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff88036bfe7440 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=5, .internal_tag=-1} sde/mq/2/cpu9/rq_list:ffff88036bfe8b80 {.cmd_flags=0x7a01, .rq_flags=0x2040, .tag=6, .internal_tag=-1} sde/device/state:running sde/queue/scheduler:[none] sdf sdf/mq/2/tags:nr_tags=62 sdf/mq/2/tags:nr_reserved_tags=0 sdf/mq/2/tags:active_queues=0 sdf/mq/2/tags: sdf/mq/2/tags:bitmap_tags: sdf/mq/2/tags:depth=62 sdf/mq/2/tags:busy=31 sdf/mq/2/tags:bits_per_word=8 sdf/mq/2/tags:map_nr=8 sdf/mq/2/tags:alloc_hint={54, 43, 44, 43, 22, 42, 52, 4, 10, 7, 16, 32, 11, 17, 44, 26, 51, 59, 9, 45, 9, 55, 10, 44, 22, 46, 25, 25, 21, 18, 52, 32} sdf/mq/2/tags:wake_batch=7 sdf/mq/2/tags:wake_index=0 sdf/mq/2/tags:ws={ sdf/mq/2/tags: {.wait_cnt=7, .wait=inactive}, sdf/mq/2/tags: {.wait_cnt=7, .wait=inactive}, sdf/mq/2/tags: {.wait_cnt=7, .wait=inactive}, sdf/mq/2/tags: {.wait_cnt=7, .wait=inactive}, sdf/mq/2/tags: {.wait_cnt=7, .wait=inactive}, sdf/mq/2/tags: {.wait_cnt=7, .wait=inactive}, sdf/mq/2/tags: {.wait_cnt=7, .wait=inactive}, sdf/mq/2/tags: {.wait_cnt=7, .wait=inactive}, sdf/mq/2/tags:} sdf/mq/2/tags:round_robin=0 sdf/mq/2/tags_bitmap:00000000: 7f00 0000 e0ff ff1f sdf/device/state:running sdf/queue/scheduler:[none] sdg sdh sdi sdj sr0