On Wed, Nov 01, 2023 at 03:14:22AM +0100, Marek Marczykowski-Górecki wrote:
On Wed, Nov 01, 2023 at 09:27:24AM +0800, Ming Lei wrote:
On Tue, Oct 31, 2023 at 11:42 PM Marek Marczykowski-Górecki marmarek@invisiblethingslab.com wrote:
On Tue, Oct 31, 2023 at 03:01:36PM +0100, Jan Kara wrote:
On Tue 31-10-23 04:48:44, Marek Marczykowski-Górecki wrote:
Then tried:
- PAGE_ALLOC_COSTLY_ORDER=4, order=4 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=5 - cannot reproduce,
- PAGE_ALLOC_COSTLY_ORDER=4, order=6 - freeze rather quickly
I've retried the PAGE_ALLOC_COSTLY_ORDER=4,order=5 case several times and I can't reproduce the issue there. I'm confused...
And this kind of confirms that allocations > PAGE_ALLOC_COSTLY_ORDER causing hangs is most likely just a coincidence. Rather something either in the block layer or in the storage driver has problems with handling bios with sufficiently high order pages attached. This is going to be a bit painful to debug I'm afraid. How long does it take for you trigger the hang? I'm asking to get rough estimate how heavy tracing we can afford so that we don't overwhelm the system...
Sometimes it freezes just after logging in, but in worst case it takes me about 10min of more or less `tar xz` + `dd`.
blk-mq debugfs is usually helpful for hang issue in block layer or underlying drivers:
(cd /sys/kernel/debug/block && find . -type f -exec grep -aH . {} ;)
BTW, you can just collect logs of the exact disks if you know what are behind dm-crypt, which can be figured out by `lsblk`, and it has to be collected after the hang is triggered.
dm-crypt lives on the nvme disk, this is what I collected when it hanged:
nvme0n1/hctx5/type:default nvme0n1/hctx5/dispatch_busy:0 nvme0n1/hctx5/active:0 nvme0n1/hctx5/run:273 nvme0n1/hctx5/tags_bitmap:00000000: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx5/tags_bitmap:00000010: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx5/tags_bitmap:00000020: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx5/tags_bitmap:00000030: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx5/tags_bitmap:00000040: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx5/tags_bitmap:00000050: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx5/tags_bitmap:00000060: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx5/tags_bitmap:00000070: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx5/tags:nr_tags=1023 nvme0n1/hctx5/tags:nr_reserved_tags=0 nvme0n1/hctx5/tags:active_queues=0 nvme0n1/hctx5/tags:bitmap_tags: nvme0n1/hctx5/tags:depth=1023 nvme0n1/hctx5/tags:busy=0 nvme0n1/hctx5/tags:cleared=7 nvme0n1/hctx5/tags:bits_per_word=64 nvme0n1/hctx5/tags:map_nr=16 nvme0n1/hctx5/tags:alloc_hint={633, 450, 354, 913, 651, 645} nvme0n1/hctx5/tags:wake_batch=8 nvme0n1/hctx5/tags:wake_index=0 nvme0n1/hctx5/tags:ws_active=0 nvme0n1/hctx5/tags:ws={ nvme0n1/hctx5/tags: {.wait=inactive}, nvme0n1/hctx5/tags: {.wait=inactive}, nvme0n1/hctx5/tags: {.wait=inactive}, nvme0n1/hctx5/tags: {.wait=inactive}, nvme0n1/hctx5/tags: {.wait=inactive}, nvme0n1/hctx5/tags: {.wait=inactive}, nvme0n1/hctx5/tags: {.wait=inactive}, nvme0n1/hctx5/tags: {.wait=inactive}, nvme0n1/hctx5/tags:} nvme0n1/hctx5/tags:round_robin=0 nvme0n1/hctx5/tags:min_shallow_depth=4294967295 nvme0n1/hctx5/ctx_map:00000000: 00 nvme0n1/hctx5/flags:alloc_policy=FIFO SHOULD_MERGE nvme0n1/hctx4/cpu4/default_rq_list:000000000d41998f {.op=READ, .cmd_flags=, .rq_flags=IO_STAT, .state=idle, .tag=65, .internal_tag=-1} nvme0n1/hctx4/cpu4/default_rq_list:00000000d0d04ed2 {.op=READ, .cmd_flags=, .rq_flags=IO_STAT, .state=idle, .tag=70, .internal_tag=-1} nvme0n1/hctx4/type:default nvme0n1/hctx4/dispatch_busy:9 nvme0n1/hctx4/active:0 nvme0n1/hctx4/run:20290468 nvme0n1/hctx4/tags_bitmap:00000000: 0000 0000 0000 0000 4240 0000 0000 0000 nvme0n1/hctx4/tags_bitmap:00000010: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx4/tags_bitmap:00000020: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx4/tags_bitmap:00000030: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx4/tags_bitmap:00000040: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx4/tags_bitmap:00000050: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx4/tags_bitmap:00000060: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx4/tags_bitmap:00000070: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx4/tags:nr_tags=1023 nvme0n1/hctx4/tags:nr_reserved_tags=0 nvme0n1/hctx4/tags:active_queues=0 nvme0n1/hctx4/tags:bitmap_tags: nvme0n1/hctx4/tags:depth=1023 nvme0n1/hctx4/tags:busy=3 nvme0n1/hctx4/tags:cleared=7 nvme0n1/hctx4/tags:bits_per_word=64 nvme0n1/hctx4/tags:map_nr=16 nvme0n1/hctx4/tags:alloc_hint={899, 846, 390, 472, 73, 439} nvme0n1/hctx4/tags:wake_batch=8 nvme0n1/hctx4/tags:wake_index=0 nvme0n1/hctx4/tags:ws_active=0 nvme0n1/hctx4/tags:ws={ nvme0n1/hctx4/tags: {.wait=inactive}, nvme0n1/hctx4/tags: {.wait=inactive}, nvme0n1/hctx4/tags: {.wait=inactive}, nvme0n1/hctx4/tags: {.wait=inactive}, nvme0n1/hctx4/tags: {.wait=inactive}, nvme0n1/hctx4/tags: {.wait=inactive}, nvme0n1/hctx4/tags: {.wait=inactive}, nvme0n1/hctx4/tags: {.wait=inactive}, nvme0n1/hctx4/tags:} nvme0n1/hctx4/tags:round_robin=0 nvme0n1/hctx4/tags:min_shallow_depth=4294967295 nvme0n1/hctx4/ctx_map:00000000: 01 nvme0n1/hctx4/dispatch:00000000b335fa89 {.op=WRITE, .cmd_flags=NOMERGE, .rq_flags=DONTPREP|IO_STAT, .state=idle, .tag=78, .internal_tag=-1} nvme0n1/hctx4/flags:alloc_policy=FIFO SHOULD_MERGE nvme0n1/hctx4/state:SCHED_RESTART nvme0n1/hctx3/type:default nvme0n1/hctx3/dispatch_busy:0 nvme0n1/hctx3/active:0 nvme0n1/hctx3/run:296 nvme0n1/hctx3/tags_bitmap:00000000: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx3/tags_bitmap:00000010: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx3/tags_bitmap:00000020: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx3/tags_bitmap:00000030: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx3/tags_bitmap:00000040: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx3/tags_bitmap:00000050: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx3/tags_bitmap:00000060: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx3/tags_bitmap:00000070: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx3/tags:nr_tags=1023 nvme0n1/hctx3/tags:nr_reserved_tags=0 nvme0n1/hctx3/tags:active_queues=0 nvme0n1/hctx3/tags:bitmap_tags: nvme0n1/hctx3/tags:depth=1023 nvme0n1/hctx3/tags:busy=0 nvme0n1/hctx3/tags:cleared=23 nvme0n1/hctx3/tags:bits_per_word=64 nvme0n1/hctx3/tags:map_nr=16 nvme0n1/hctx3/tags:alloc_hint={862, 557, 480, 24, 841, 23} nvme0n1/hctx3/tags:wake_batch=8 nvme0n1/hctx3/tags:wake_index=0 nvme0n1/hctx3/tags:ws_active=0 nvme0n1/hctx3/tags:ws={ nvme0n1/hctx3/tags: {.wait=inactive}, nvme0n1/hctx3/tags: {.wait=inactive}, nvme0n1/hctx3/tags: {.wait=inactive}, nvme0n1/hctx3/tags: {.wait=inactive}, nvme0n1/hctx3/tags: {.wait=inactive}, nvme0n1/hctx3/tags: {.wait=inactive}, nvme0n1/hctx3/tags: {.wait=inactive}, nvme0n1/hctx3/tags: {.wait=inactive}, nvme0n1/hctx3/tags:} nvme0n1/hctx3/tags:round_robin=0 nvme0n1/hctx3/tags:min_shallow_depth=4294967295 nvme0n1/hctx3/ctx_map:00000000: 00 nvme0n1/hctx3/flags:alloc_policy=FIFO SHOULD_MERGE nvme0n1/hctx2/type:default nvme0n1/hctx2/dispatch_busy:0 nvme0n1/hctx2/active:0 nvme0n1/hctx2/run:279 nvme0n1/hctx2/tags_bitmap:00000000: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx2/tags_bitmap:00000010: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx2/tags_bitmap:00000020: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx2/tags_bitmap:00000030: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx2/tags_bitmap:00000040: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx2/tags_bitmap:00000050: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx2/tags_bitmap:00000060: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx2/tags_bitmap:00000070: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx2/tags:nr_tags=1023 nvme0n1/hctx2/tags:nr_reserved_tags=0 nvme0n1/hctx2/tags:active_queues=0 nvme0n1/hctx2/tags:bitmap_tags: nvme0n1/hctx2/tags:depth=1023 nvme0n1/hctx2/tags:busy=0 nvme0n1/hctx2/tags:cleared=16 nvme0n1/hctx2/tags:bits_per_word=64 nvme0n1/hctx2/tags:map_nr=16 nvme0n1/hctx2/tags:alloc_hint={960, 528, 145, 730, 447, 1002} nvme0n1/hctx2/tags:wake_batch=8 nvme0n1/hctx2/tags:wake_index=0 nvme0n1/hctx2/tags:ws_active=0 nvme0n1/hctx2/tags:ws={ nvme0n1/hctx2/tags: {.wait=inactive}, nvme0n1/hctx2/tags: {.wait=inactive}, nvme0n1/hctx2/tags: {.wait=inactive}, nvme0n1/hctx2/tags: {.wait=inactive}, nvme0n1/hctx2/tags: {.wait=inactive}, nvme0n1/hctx2/tags: {.wait=inactive}, nvme0n1/hctx2/tags: {.wait=inactive}, nvme0n1/hctx2/tags: {.wait=inactive}, nvme0n1/hctx2/tags:} nvme0n1/hctx2/tags:round_robin=0 nvme0n1/hctx2/tags:min_shallow_depth=4294967295 nvme0n1/hctx2/ctx_map:00000000: 00 nvme0n1/hctx2/flags:alloc_policy=FIFO SHOULD_MERGE nvme0n1/hctx1/type:default nvme0n1/hctx1/dispatch_busy:0 nvme0n1/hctx1/active:0 nvme0n1/hctx1/run:458 nvme0n1/hctx1/tags_bitmap:00000000: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx1/tags_bitmap:00000010: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx1/tags_bitmap:00000020: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx1/tags_bitmap:00000030: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx1/tags_bitmap:00000040: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx1/tags_bitmap:00000050: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx1/tags_bitmap:00000060: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx1/tags_bitmap:00000070: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx1/tags:nr_tags=1023 nvme0n1/hctx1/tags:nr_reserved_tags=0 nvme0n1/hctx1/tags:active_queues=0 nvme0n1/hctx1/tags:bitmap_tags: nvme0n1/hctx1/tags:depth=1023 nvme0n1/hctx1/tags:busy=0 nvme0n1/hctx1/tags:cleared=31 nvme0n1/hctx1/tags:bits_per_word=64 nvme0n1/hctx1/tags:map_nr=16 nvme0n1/hctx1/tags:alloc_hint={689, 284, 498, 188, 808, 610} nvme0n1/hctx1/tags:wake_batch=8 nvme0n1/hctx1/tags:wake_index=0 nvme0n1/hctx1/tags:ws_active=0 nvme0n1/hctx1/tags:ws={ nvme0n1/hctx1/tags: {.wait=inactive}, nvme0n1/hctx1/tags: {.wait=inactive}, nvme0n1/hctx1/tags: {.wait=inactive}, nvme0n1/hctx1/tags: {.wait=inactive}, nvme0n1/hctx1/tags: {.wait=inactive}, nvme0n1/hctx1/tags: {.wait=inactive}, nvme0n1/hctx1/tags: {.wait=inactive}, nvme0n1/hctx1/tags: {.wait=inactive}, nvme0n1/hctx1/tags:} nvme0n1/hctx1/tags:round_robin=0 nvme0n1/hctx1/tags:min_shallow_depth=4294967295 nvme0n1/hctx1/ctx_map:00000000: 00 nvme0n1/hctx1/flags:alloc_policy=FIFO SHOULD_MERGE nvme0n1/hctx0/type:default nvme0n1/hctx0/dispatch_busy:0 nvme0n1/hctx0/active:0 nvme0n1/hctx0/run:375 nvme0n1/hctx0/tags_bitmap:00000000: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx0/tags_bitmap:00000010: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx0/tags_bitmap:00000020: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx0/tags_bitmap:00000030: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx0/tags_bitmap:00000040: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx0/tags_bitmap:00000050: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx0/tags_bitmap:00000060: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx0/tags_bitmap:00000070: 0000 0000 0000 0000 0000 0000 0000 0000 nvme0n1/hctx0/tags:nr_tags=1023 nvme0n1/hctx0/tags:nr_reserved_tags=0 nvme0n1/hctx0/tags:active_queues=0 nvme0n1/hctx0/tags:bitmap_tags: nvme0n1/hctx0/tags:depth=1023 nvme0n1/hctx0/tags:busy=0 nvme0n1/hctx0/tags:cleared=6 nvme0n1/hctx0/tags:bits_per_word=64 nvme0n1/hctx0/tags:map_nr=16 nvme0n1/hctx0/tags:alloc_hint={5, 18, 320, 448, 728, 9} nvme0n1/hctx0/tags:wake_batch=8 nvme0n1/hctx0/tags:wake_index=0 nvme0n1/hctx0/tags:ws_active=0 nvme0n1/hctx0/tags:ws={ nvme0n1/hctx0/tags: {.wait=inactive}, nvme0n1/hctx0/tags: {.wait=inactive}, nvme0n1/hctx0/tags: {.wait=inactive}, nvme0n1/hctx0/tags: {.wait=inactive}, nvme0n1/hctx0/tags: {.wait=inactive}, nvme0n1/hctx0/tags: {.wait=inactive}, nvme0n1/hctx0/tags: {.wait=inactive}, nvme0n1/hctx0/tags: {.wait=inactive}, nvme0n1/hctx0/tags:} nvme0n1/hctx0/tags:round_robin=0 nvme0n1/hctx0/tags:min_shallow_depth=4294967295 nvme0n1/hctx0/ctx_map:00000000: 00 nvme0n1/hctx0/flags:alloc_policy=FIFO SHOULD_MERGE nvme0n1/state:SAME_COMP|NONROT|IO_STAT|INIT_DONE|WC|FUA|REGISTERED|NOWAIT nvme0n1/pm_only:0
This is without any of the patches Mikulas proposed.
And BTW, an attempt to access another partition on the same disk (not covered with dm-crypt) hangs too.