This seems to be kicked off somehow from the mdadm assemble command. There is no additional mdadm process before I run the assemble command but there is after: #ps -elf | grep " D " 0 S root 3993 3953 0 80 0 - 55416 pipe_r 02:18 pts/1 00:00:00 grep --color=auto D #mdadm --assemble --verbose --backup-file=/root/mdadm5-6_backup_md127 --invalid-backup /dev/md127 /dev/sda /dev/sdh /dev/sdg /dev/sdc /dev/sde /dev/sdf --force mdadm: looking for devices for /dev/md127 mdadm: /dev/sda is identified as a member of /dev/md127, slot 0. mdadm: /dev/sdh is identified as a member of /dev/md127, slot 1. mdadm: /dev/sdg is identified as a member of /dev/md127, slot 2. mdadm: /dev/sdc is identified as a member of /dev/md127, slot 3. mdadm: /dev/sde is identified as a member of /dev/md127, slot 4. mdadm: /dev/sdf is identified as a member of /dev/md127, slot 5. mdadm: /dev/md127 has an active reshape - checking if critical section needs to be restored mdadm: No backup metadata on /root/mdadm5-6_backup_md127 mdadm: Failed to find backup of critical section mdadm: continuing without restoring backup mdadm: added /dev/sdh to /dev/md127 as 1 mdadm: added /dev/sdg to /dev/md127 as 2 mdadm: added /dev/sdc to /dev/md127 as 3 mdadm: added /dev/sde to /dev/md127 as 4 mdadm: added /dev/sdf to /dev/md127 as 5 (possibly out of date) mdadm: added /dev/sda to /dev/md127 as 0 <hangs here> #Then in a separate terminal: #ps -elf | grep " D " 1 D root 1249 1 0 80 0 - 936 wait_w 02:15 ? 00:00:00 /sbin/mdadm --monitor --scan --syslog -f --pid-file=/run/mdadm/mdadm.pid 4 D root 4086 4038 0 80 0 - 953 mddev_ 02:22 pts/2 00:00:00 mdadm --assemble --verbose --backup-file=/root/mdadm5-6_backup_md127 --invalid-backup /dev/md127 /dev/sda /dev/sdh /dev/sdg /dev/sdc /dev/sde /dev/sdf --force 0 S root 4102 3869 0 80 0 - 55449 pipe_r 02:25 pts/0 00:00:00 grep --color=auto D On Mon, May 8, 2023 at 1:56 AM Yu Kuai <yukuai1@xxxxxxxxxxxxxxx> wrote: > > Hi, > > 在 2023/05/08 15:43, David Gilmour 写道: > > Two mdadm processes show up: > > > > #ps -elf | grep " D " > > 1 D root 1251 1 0 80 0 - 936 wait_w 00:28 ? > > 00:00:00 /sbin/mdadm --monitor --scan --syslog -f > > --pid-file=/run/mdadm/mdadm.pid > > So this is the one accessing the array, can you stop this before > assemble? > > Thanks, > Kuai > > 4 D root 4130 4091 0 80 0 - 953 mddev_ 01:33 pts/1 > > 00:00:00 mdadm --assemble --verbose > > --backup-file=/root/mdadm5-6_backup_md127 --invalid-backup /dev/md127 > > /dev/sda /dev/sdh /dev/sdg /dev/sdc /dev/sde /dev/sdf --force > > > > Process 1251 (mdadm) has a raid5_make_request descriptor in it: > > > > #cat /proc/1251/stack > > [<0>] wait_woken+0x50/0x70 > > [<0>] raid5_make_request+0x2cb/0x3e0 [raid456] > > [<0>] md_handle_request+0x135/0x1e0 > > [<0>] __submit_bio+0x89/0x130 > > [<0>] __submit_bio_noacct+0x81/0x1f0 > > [<0>] submit_bh_wbc+0x11e/0x140 > > [<0>] block_read_full_folio+0x1d5/0x290 > > [<0>] filemap_read_folio+0x43/0x300 > > [<0>] do_read_cache_folio+0x112/0x3f0 > > [<0>] read_cache_page+0x15/0x90 > > [<0>] read_part_sector+0x3a/0x160 > > [<0>] read_lba+0xff/0x260 > > [<0>] is_gpt_valid.part.0+0x66/0x3d0 > > [<0>] find_valid_gpt.constprop.0+0x20e/0x540 > > [<0>] efi_partition+0x80/0x390 > > [<0>] check_partition+0x103/0x1d0 > > [<0>] bdev_disk_changed.part.0+0xb5/0x200 > > [<0>] blkdev_get_whole+0x7a/0x90 > > [<0>] blkdev_get_by_dev.part.0+0x13b/0x300 > > [<0>] blkdev_open+0x4c/0x90 > > [<0>] do_dentry_open+0x14f/0x380 > > [<0>] do_open+0x21a/0x3d0 > > [<0>] path_openat+0x10f/0x2b0 > > [<0>] do_filp_open+0xb2/0x160 > > [<0>] do_sys_openat2+0x9a/0x160 > > [<0>] __x64_sys_openat+0x53/0xa0 > > [<0>] do_syscall_64+0x5c/0x90 > > [<0>] entry_SYSCALL_64_after_hwframe+0x63/0xcd > > > > #cat /proc/4130/stack > > [<0>] mddev_suspend.part.0+0xdf/0x150 > > [<0>] suspend_lo_store+0xc5/0xf0 > > [<0>] md_attr_store+0x83/0xf0 > > [<0>] kernfs_fop_write_iter+0x124/0x1b0 > > [<0>] new_sync_write+0xff/0x190 > > [<0>] vfs_write+0x1ef/0x280 > > [<0>] ksys_write+0x5f/0xe0 > > [<0>] do_syscall_64+0x5c/0x90 > > [<0>] entry_SYSCALL_64_after_hwframe+0x63/0xcd > > > > > > On Mon, May 8, 2023 at 1:08 AM Yu Kuai <yukuai1@xxxxxxxxxxxxxxx> wrote: > >> > >> Hi, > >> > >> 在 2023/05/08 13:54, David Gilmour 写道: > >>> I'm not sure what I'm looking for here but here is the output of the > >>> inflight file immediately after the mdadm assemble hangs. Does this > >>> indicate something accessing the array? > >>> > >>> #cat /sys/block/md127/inflight > >>> 1 0 > >>> > >> > >> Yes, something is accessing the array. Do you try to grep all the task > >> that is "D" state? > >> > >> ps -elf | grep " D " > >> > >> Is there any task stuck in raid5_make_request? > >> > >> cat /proc/$pid/stack > >> > >>> Also attached is an strace of my mdadm command that hung in case that > >>> reveals something relevant: > >>> strace mdadm --assemble --verbose > >>> --backup-file=/root/mdadm5-6_backup_md127 --invalid-backup /dev/md127 > >>> /dev/sda /dev/sdh /dev/sdg /dev/sdc /dev/sde /dev/sdf --force 2>&1 | > >>> tee mdadm_strace_output.txt > >> > >> I don't think this will be helpful, mdadm is unlikely the task that > >> is accessing the array. > >> > >> Thanks, > >> Kuai > >>> > >>> > >>> > >>> > >>> > >>> On Sun, May 7, 2023 at 7:23 PM Yu Kuai <yukuai1@xxxxxxxxxxxxxxx> wrote: > >>>> > >>>> Hi, > >>>> > >>>> 在 2023/05/06 21:19, David Gilmour 写道: > >>>>> >From what I can tell it does look very similar. I stopped the > >>>>> systemd-udevd service and renamed it to systemd-udevd.bak. My system > >>>>> still hung on the assemble command. I'm not savvy enough to decode the > >>>>> details here but does the "mddev_suspend.part.0+0xdf/0x150" line in > >>>>> the process stack output suggest the same i/o block the other post > >>>>> indicates? > >>>>> > >>>>> × systemd-udevd.service - Rule-based Manager for Device Events and Files > >>>>> Loaded: loaded (/usr/lib/systemd/system/systemd-udevd.service; static) > >>>>> Active: failed (Result: exit-code) since Sat 2023-05-06 06:59:11 > >>>>> MDT; 1min 27s ago > >>>>> Duration: 1d 20h 16min 29.633s > >>>>> TriggeredBy: × systemd-udevd-kernel.socket > >>>>> × systemd-udevd-control.socket > >>>>> Docs: man:systemd-udevd.service(8) > >>>>> man:udev(7) > >>>>> Process: 27440 ExecStart=/usr/lib/systemd/systemd-udevd > >>>>> (code=exited, status=203/EXEC) > >>>>> Main PID: 27440 (code=exited, status=203/EXEC) > >>>>> CPU: 5ms > >>>>> > >>>>> ---------------------- > >>>>> #mdadm --assemble --verbose --backup-file=/root/mdadm5-6_backup_md127 > >>>>> --invalid-backup /dev/md127 /dev/sda /dev/sdh /dev/sdg /dev/sdc > >>>>> /dev/sdb /dev/sdf --force > >>>>> mdadm: looking for devices for /dev/md127 > >>>>> mdadm: /dev/sda is identified as a member of /dev/md127, slot 0. > >>>>> mdadm: /dev/sdh is identified as a member of /dev/md127, slot 1. > >>>>> mdadm: /dev/sdg is identified as a member of /dev/md127, slot 2. > >>>>> mdadm: /dev/sdc is identified as a member of /dev/md127, slot 3. > >>>>> mdadm: /dev/sdb is identified as a member of /dev/md127, slot 4. > >>>>> mdadm: /dev/sdf is identified as a member of /dev/md127, slot 5. > >>>>> mdadm: /dev/md127 has an active reshape - checking if critical section > >>>>> needs to be restored > >>>>> mdadm: No backup metadata on /root/mdadm5-6_backup_md127 > >>>>> mdadm: Failed to find backup of critical section > >>>>> mdadm: continuing without restoring backup > >>>>> mdadm: added /dev/sdh to /dev/md127 as 1 > >>>>> mdadm: added /dev/sdg to /dev/md127 as 2 > >>>>> mdadm: added /dev/sdc to /dev/md127 as 3 > >>>>> mdadm: added /dev/sdb to /dev/md127 as 4 > >>>>> mdadm: added /dev/sdf to /dev/md127 as 5 (possibly out of date) > >>>>> mdadm: added /dev/sda to /dev/md127 as 0 > >>>>> > >>>>> #hangs indefinitely at this point in the output > >>>>> > >>>>> ------------------------------------------ > >>>>> > >>>>> > >>>>> root 27454 0.0 0.0 3812 2656 pts/1 D+ 07:00 0:00 > >>>>> mdadm --assemble --verbose --backup-file=/root/mdadm5-6_backup_md127 > >>>>> --invalid-backup /dev/md127 /dev/sda /dev/sdh /dev/sdg /dev/sdc > >>>>> /dev/sdb /dev/sdf --force > >>>>> root 27457 0.0 0.0 0 0 ? S 07:00 0:00 [md127_raid6] > >>>>> > >>>>> #cat /proc/27454/stack > >>>>> [<0>] mddev_suspend.part.0+0xdf/0x150 > >>>>> [<0>] suspend_lo_store+0xc5/0xf0 > >>>>> [<0>] md_attr_store+0x83/0xf0 > >>>>> [<0>] kernfs_fop_write_iter+0x124/0x1b0 > >>>>> [<0>] new_sync_write+0xff/0x190 > >>>>> [<0>] vfs_write+0x1ef/0x280 > >>>>> [<0>] ksys_write+0x5f/0xe0 > >>>>> [<0>] do_syscall_64+0x5c/0x90 > >>>>> [<0>] entry_SYSCALL_64_after_hwframe+0x63/0xcd > >>>>> > >>>>> #cat /proc/27457/stack > >>>>> [<0>] md_thread+0x122/0x160 > >>>>> [<0>] kthread+0xe0/0x100 > >>>>> [<0>] ret_from_fork+0x22/0x30 > >>>>> > >>>> > >>>> Is there any thread stuck at raid5_make_request? something like below: > >>>> > >>>> Apr 23 19:17:22 atom kernel: task:systemd-udevd state:D stack: 0 > >>>> pid: 8121 ppid: 706 flags:0x00000006 > >>>> Apr 23 19:17:22 atom kernel: Call Trace: > >>>> Apr 23 19:17:22 atom kernel: <TASK> > >>>> Apr 23 19:17:22 atom kernel: __schedule+0x20a/0x550 > >>>> Apr 23 19:17:22 atom kernel: schedule+0x5a/0xc0 > >>>> Apr 23 19:17:22 atom kernel: schedule_timeout+0x11f/0x160 > >>>> Apr 23 19:17:22 atom kernel: ? make_stripe_request+0x284/0x490 [raid456] > >>>> Apr 23 19:17:22 atom kernel: wait_woken+0x50/0x70 > >>>> Apr 23 19:17:22 atom kernel: raid5_make_request+0x2cb/0x3e0 [raid456] > >>>> Apr 23 19:17:22 atom kernel: ? sched_show_numa+0xf0/0xf0 > >>>> Apr 23 19:17:22 atom kernel: md_handle_request+0x132/0x1e0 > >>>> Apr 23 19:17:22 atom kernel: ? do_mpage_readpage+0x282/0x6b0 > >>>> Apr 23 19:17:22 atom kernel: __submit_bio+0x86/0x130 > >>>> Apr 23 19:17:22 atom kernel: __submit_bio_noacct+0x81/0x1f0 > >>>> Apr 23 19:17:22 atom kernel: mpage_readahead+0x15c/0x1d0 > >>>> Apr 23 19:17:22 atom kernel: ? blkdev_write_begin+0x20/0x20 > >>>> Apr 23 19:17:22 atom kernel: read_pages+0x58/0x2f0 > >>>> Apr 23 19:17:22 atom kernel: page_cache_ra_unbounded+0x137/0x180 > >>>> Apr 23 19:17:22 atom kernel: force_page_cache_ra+0xc5/0xf0 > >>>> Apr 23 19:17:22 atom kernel: filemap_get_pages+0xe4/0x350 > >>>> Apr 23 19:17:22 atom kernel: filemap_read+0xbe/0x3c0 > >>>> Apr 23 19:17:22 atom kernel: ? make_kgid+0x13/0x20 > >>>> Apr 23 19:17:22 atom kernel: ? deactivate_locked_super+0x90/0xa0 > >>>> Apr 23 19:17:22 atom kernel: blkdev_read_iter+0xaf/0x170 > >>>> Apr 23 19:17:22 atom kernel: new_sync_read+0xf9/0x180 > >>>> Apr 23 19:17:22 atom kernel: vfs_read+0x13c/0x190 > >>>> Apr 23 19:17:22 atom kernel: ksys_read+0x5f/0xe0 > >>>> Apr 23 19:17:22 atom kernel: do_syscall_64+0x59/0x90 > >>>> > >>>> By the way, cat /sys/block/mdxx/inflight can prove this as well. > >>>> > >>>> If this is the case, can you find out who is accessing the array? > >>>> > >>>> Thanks, > >>>> Kuai > >>>> > >> > > . > > >
