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@xxxxxxxxxxxxxxxxxxxxxx> 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.
--
Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab
Attachment:
signature.asc
Description: PGP signature
