Re: mdadm grow raid 5 to 6 failure (crash)
From: David Gilmour <hidden>
Date: 2023-05-08 08:28:08
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 [off-list ref] wrote:
Hi, 在 2023/05/08 15:43, David Gilmour 写道:quoted
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.pidSo this is the one accessing the array, can you stop this before assemble? Thanks, Kuaiquoted
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 [off-list ref] wrote:quoted
Hi, 在 2023/05/08 13:54, David Gilmour 写道:quoted
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 0Yes, 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/stackquoted
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.txtI don't think this will be helpful, mdadm is unlikely the task that is accessing the array. Thanks, Kuaiquoted
On Sun, May 7, 2023 at 7:23 PM Yu Kuai [off-list ref] wrote:quoted
Hi, 在 2023/05/06 21:19, David Gilmour 写道:quoted
quoted
From what I can tell it does look very similar. I stopped thesystemd-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/0x30Is 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.