On Wed, 2018-02-14 at 08:44 -0700, Jens Axboe wrote:
>
> Mike, when you see a hang like that, would it be possible for you to
> dump the contents of /sys/kernel/debug/block/<dev in question/* for us
> to inspect? That will tell us a lot about the internal state at that
> time.
Finally. 4.15.4 stalled this morning while building other updated
trees.
#!/bin/sh
for i in `find /sys/kernel/debug/block/sd[bd] -type f`
do
echo $i:
cat $i
echo
done
/sys/kernel/debug/block/sdb/hctx0/cpu7/completed:
7483 4884
/sys/kernel/debug/block/sdb/hctx0/cpu7/merged:
0
/sys/kernel/debug/block/sdb/hctx0/cpu7/dispatched:
7483 4884
/sys/kernel/debug/block/sdb/hctx0/cpu7/rq_list:
/sys/kernel/debug/block/sdb/hctx0/cpu6/completed:
12240 7814
/sys/kernel/debug/block/sdb/hctx0/cpu6/merged:
0
/sys/kernel/debug/block/sdb/hctx0/cpu6/dispatched:
12240 7814
/sys/kernel/debug/block/sdb/hctx0/cpu6/rq_list:
/sys/kernel/debug/block/sdb/hctx0/cpu5/completed:
8549 7842
/sys/kernel/debug/block/sdb/hctx0/cpu5/merged:
0
/sys/kernel/debug/block/sdb/hctx0/cpu5/dispatched:
8549 7842
/sys/kernel/debug/block/sdb/hctx0/cpu5/rq_list:
/sys/kernel/debug/block/sdb/hctx0/cpu4/completed:
10115 5073
/sys/kernel/debug/block/sdb/hctx0/cpu4/merged:
0
/sys/kernel/debug/block/sdb/hctx0/cpu4/dispatched:
10115 5073
/sys/kernel/debug/block/sdb/hctx0/cpu4/rq_list:
/sys/kernel/debug/block/sdb/hctx0/cpu3/completed:
13181 4867
/sys/kernel/debug/block/sdb/hctx0/cpu3/merged:
0
/sys/kernel/debug/block/sdb/hctx0/cpu3/dispatched:
13181 4867
/sys/kernel/debug/block/sdb/hctx0/cpu3/rq_list:
/sys/kernel/debug/block/sdb/hctx0/cpu2/completed:
101270 9089
/sys/kernel/debug/block/sdb/hctx0/cpu2/merged:
0
/sys/kernel/debug/block/sdb/hctx0/cpu2/dispatched:
101270 9089
/sys/kernel/debug/block/sdb/hctx0/cpu2/rq_list:
/sys/kernel/debug/block/sdb/hctx0/cpu1/completed:
8158 4392
/sys/kernel/debug/block/sdb/hctx0/cpu1/merged:
0
/sys/kernel/debug/block/sdb/hctx0/cpu1/dispatched:
8158 4392
/sys/kernel/debug/block/sdb/hctx0/cpu1/rq_list:
/sys/kernel/debug/block/sdb/hctx0/cpu0/completed:
8605 5819
/sys/kernel/debug/block/sdb/hctx0/cpu0/merged:
0
/sys/kernel/debug/block/sdb/hctx0/cpu0/dispatched:
8605 5819
/sys/kernel/debug/block/sdb/hctx0/cpu0/rq_list:
/sys/kernel/debug/block/sdb/hctx0/active:
0
/sys/kernel/debug/block/sdb/hctx0/run:
373736
/sys/kernel/debug/block/sdb/hctx0/queued:
219336
/sys/kernel/debug/block/sdb/hctx0/dispatched:
0 7629
1 216748
2 446
4 0
8 0
16 0
32+ 0
/sys/kernel/debug/block/sdb/hctx0/io_poll:
considered=0
invoked=0
success=0
/sys/kernel/debug/block/sdb/hctx0/sched_tags_bitmap:
00000000: 0000 0000 0000 0000
/sys/kernel/debug/block/sdb/hctx0/sched_tags:
nr_tags=62
nr_reserved_tags=0
active_queues=0
bitmap_tags:
depth=62
busy=0
bits_per_word=8
map_nr=8
alloc_hint={9, 1, 3, 0, 17, 0, 9, 17}
wake_batch=7
wake_index=4
ws={
{.wait_cnt=7, .wait=active},
{.wait_cnt=7, .wait=active},
{.wait_cnt=7, .wait=inactive},
{.wait_cnt=7, .wait=inactive},
{.wait_cnt=1, .wait=active},
{.wait_cnt=7, .wait=active},
{.wait_cnt=7, .wait=inactive},
{.wait_cnt=7, .wait=active},
}
round_robin=1
/sys/kernel/debug/block/sdb/hctx0/tags_bitmap:
00000000: 0000 0000
/sys/kernel/debug/block/sdb/hctx0/tags:
nr_tags=31
nr_reserved_tags=0
active_queues=0
bitmap_tags:
depth=31
busy=0
bits_per_word=4
map_nr=8
alloc_hint={3, 12, 2, 9, 18, 2, 4, 11}
wake_batch=3
wake_index=0
ws={
{.wait_cnt=3, .wait=inactive},
{.wait_cnt=3, .wait=inactive},
{.wait_cnt=3, .wait=inactive},
{.wait_cnt=3, .wait=inactive},
{.wait_cnt=3, .wait=inactive},
{.wait_cnt=3, .wait=inactive},
{.wait_cnt=3, .wait=inactive},
{.wait_cnt=3, .wait=inactive},
}
round_robin=1
/sys/kernel/debug/block/sdb/hctx0/ctx_map:
00000000: 00
/sys/kernel/debug/block/sdb/hctx0/busy:
/sys/kernel/debug/block/sdb/hctx0/dispatch:
/sys/kernel/debug/block/sdb/hctx0/flags:
alloc_policy=RR SHOULD_MERGE|SG_MERGE
/sys/kernel/debug/block/sdb/hctx0/state:
/sys/kernel/debug/block/sdb/write_hints:
hint0: 0
hint1: 0
hint2: 0
hint3: 0
hint4: 0
/sys/kernel/debug/block/sdb/state:
SAME_COMP|IO_STAT|INIT_DONE|POLL|WC|FLUSH_NQ|REGISTERED|SCSI_PASSTHROUGH
/sys/kernel/debug/block/sdb/requeue_list:
/sys/kernel/debug/block/sdb/poll_stat:
read (512 Bytes): samples=0
write (512 Bytes): samples=0
read (1024 Bytes): samples=0
write (1024 Bytes): samples=0
read (2048 Bytes): samples=0
write (2048 Bytes): samples=0
read (4096 Bytes): samples=0
write (4096 Bytes): samples=0
read (8192 Bytes): samples=0
write (8192 Bytes): samples=0
read (16384 Bytes): samples=0
write (16384 Bytes): samples=0
read (32768 Bytes): samples=0
write (32768 Bytes): samples=0
read (65536 Bytes): samples=0
write (65536 Bytes): samples=0
/sys/kernel/debug/block/sdd/hctx0/cpu7/completed:
2642 5235
/sys/kernel/debug/block/sdd/hctx0/cpu7/merged:
0
/sys/kernel/debug/block/sdd/hctx0/cpu7/dispatched:
2642 5235
/sys/kernel/debug/block/sdd/hctx0/cpu7/rq_list:
/sys/kernel/debug/block/sdd/hctx0/cpu6/completed:
2873 15051
/sys/kernel/debug/block/sdd/hctx0/cpu6/merged:
0
/sys/kernel/debug/block/sdd/hctx0/cpu6/dispatched:
2873 15051
/sys/kernel/debug/block/sdd/hctx0/cpu6/rq_list:
/sys/kernel/debug/block/sdd/hctx0/cpu5/completed:
3212 13912
/sys/kernel/debug/block/sdd/hctx0/cpu5/merged:
0
/sys/kernel/debug/block/sdd/hctx0/cpu5/dispatched:
3212 13912
/sys/kernel/debug/block/sdd/hctx0/cpu5/rq_list:
/sys/kernel/debug/block/sdd/hctx0/cpu4/completed:
4304 8158
/sys/kernel/debug/block/sdd/hctx0/cpu4/merged:
0
/sys/kernel/debug/block/sdd/hctx0/cpu4/dispatched:
4304 8158
/sys/kernel/debug/block/sdd/hctx0/cpu4/rq_list:
/sys/kernel/debug/block/sdd/hctx0/cpu3/completed:
3034 6275
/sys/kernel/debug/block/sdd/hctx0/cpu3/merged:
0
/sys/kernel/debug/block/sdd/hctx0/cpu3/dispatched:
3034 6275
/sys/kernel/debug/block/sdd/hctx0/cpu3/rq_list:
/sys/kernel/debug/block/sdd/hctx0/cpu2/completed:
10339 21025
/sys/kernel/debug/block/sdd/hctx0/cpu2/merged:
0
/sys/kernel/debug/block/sdd/hctx0/cpu2/dispatched:
10339 21025
/sys/kernel/debug/block/sdd/hctx0/cpu2/rq_list:
/sys/kernel/debug/block/sdd/hctx0/cpu1/completed:
3237 9737
/sys/kernel/debug/block/sdd/hctx0/cpu1/merged:
0
/sys/kernel/debug/block/sdd/hctx0/cpu1/dispatched:
3237 9737
/sys/kernel/debug/block/sdd/hctx0/cpu1/rq_list:
/sys/kernel/debug/block/sdd/hctx0/cpu0/completed:
1490 6101
/sys/kernel/debug/block/sdd/hctx0/cpu0/merged:
0
/sys/kernel/debug/block/sdd/hctx0/cpu0/dispatched:
1490 6101
/sys/kernel/debug/block/sdd/hctx0/cpu0/rq_list:
/sys/kernel/debug/block/sdd/hctx0/active:
0
/sys/kernel/debug/block/sdd/hctx0/run:
116625
/sys/kernel/debug/block/sdd/hctx0/queued:
116625
/sys/kernel/debug/block/sdd/hctx0/dispatched:
0 2438
1 116700
2 92
4 0
8 0
16 0
32+ 0
/sys/kernel/debug/block/sdd/hctx0/io_poll:
considered=0
invoked=0
success=0
/sys/kernel/debug/block/sdd/hctx0/sched_tags_bitmap:
00000000: 0000 0000 0000 0000
/sys/kernel/debug/block/sdd/hctx0/sched_tags:
nr_tags=62
nr_reserved_tags=0
active_queues=0
bitmap_tags:
depth=62
busy=0
bits_per_word=8
map_nr=8
alloc_hint={9, 51, 57, 0, 0, 2, 2, 21}
wake_batch=7
wake_index=0
ws={
{.wait_cnt=7, .wait=inactive},
{.wait_cnt=7, .wait=inactive},
{.wait_cnt=7, .wait=inactive},
{.wait_cnt=7, .wait=inactive},
{.wait_cnt=7, .wait=inactive},
{.wait_cnt=7, .wait=inactive},
{.wait_cnt=7, .wait=inactive},
{.wait_cnt=7, .wait=inactive},
}
round_robin=1
/sys/kernel/debug/block/sdd/hctx0/tags_bitmap:
00000000: 0000 0000
/sys/kernel/debug/block/sdd/hctx0/tags:
nr_tags=31
nr_reserved_tags=0
active_queues=0
bitmap_tags:
depth=31
busy=0
bits_per_word=4
map_nr=8
alloc_hint={7, 21, 26, 26, 25, 2, 22, 6}
wake_batch=3
wake_index=0
ws={
{.wait_cnt=3, .wait=inactive},
{.wait_cnt=3, .wait=inactive},
{.wait_cnt=3, .wait=inactive},
{.wait_cnt=3, .wait=inactive},
{.wait_cnt=3, .wait=inactive},
{.wait_cnt=3, .wait=inactive},
{.wait_cnt=3, .wait=inactive},
{.wait_cnt=3, .wait=inactive},
}
round_robin=1
/sys/kernel/debug/block/sdd/hctx0/ctx_map:
00000000: 00
/sys/kernel/debug/block/sdd/hctx0/busy:
/sys/kernel/debug/block/sdd/hctx0/dispatch:
/sys/kernel/debug/block/sdd/hctx0/flags:
alloc_policy=RR SHOULD_MERGE|SG_MERGE
/sys/kernel/debug/block/sdd/hctx0/state:
/sys/kernel/debug/block/sdd/write_hints:
hint0: 0
hint1: 0
hint2: 0
hint3: 0
hint4: 0
/sys/kernel/debug/block/sdd/state:
SAME_COMP|IO_STAT|INIT_DONE|POLL|WC|FLUSH_NQ|REGISTERED|SCSI_PASSTHROUGH
/sys/kernel/debug/block/sdd/requeue_list:
/sys/kernel/debug/block/sdd/poll_stat:
read (512 Bytes): samples=0
write (512 Bytes): samples=0
read (1024 Bytes): samples=0
write (1024 Bytes): samples=0
read (2048 Bytes): samples=0
write (2048 Bytes): samples=0
read (4096 Bytes): samples=0
write (4096 Bytes): samples=0
read (8192 Bytes): samples=0
write (8192 Bytes): samples=0
read (16384 Bytes): samples=0
write (16384 Bytes): samples=0
read (32768 Bytes): samples=0
write (32768 Bytes): samples=0
read (65536 Bytes): samples=0
write (65536 Bytes): samples=0