On 09/04/2017 10:45 AM, Xiao Ni wrote:
On 09/04/2017 10:16 AM, NeilBrown wrote:
On Sat, Sep 02 2017, Xiao Ni wrote:
Hi Neil and Shaohua
I'm trying to reproduce the problem the problem
"raid5_finish_reshape is stuck at revalidate_disk".
But there is a new stuck. I tried with 4.13.0-rc5 and latest mdadm.
The steps are:
#!/bin/bash
num=0
while [ 1 ]
do
echo "*************************$num"
mdadm -Ss
mdadm --create --run /dev/md0 --level 5 --metadata 1.2
--raid-devices 5 /dev/loop0 /dev/loop1 /dev/loop2 /dev/loop3
/dev/loop4 --spare-devices 1 /dev/loop5 --chunk 512
mdadm --wait /dev/md0
mkfs -t ext4 /dev/md0
mount -t ext4 /dev/md0 /mnt/md_test
dd if=/dev/urandom of=/mnt/md_test/testfile bs=1M count=100
mdadm --add /dev/md0 /dev/loop6
mdadm --grow --raid-devices 6 /dev/md0
dd if=/dev/urandom of=/mnt/md_test/testfile bs=1M count=1000
mdadm --wait /dev/md0
((num++))
umount /dev/md0
done
The calltrace messages are:
Sep 1 13:57:25 localhost kernel: INFO: task kworker/u8:4:21401
blocked for more than 120 seconds.
Sep 1 13:57:25 localhost kernel: Tainted: G OE 4.13.0-rc5 #2
Sep 1 13:57:25 localhost kernel: "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Sep 1 13:57:25 localhost kernel: kworker/u8:4 D 0 21401
2 0x00000080
Sep 1 13:57:25 localhost kernel: Workqueue: writeback wb_workfn
(flush-9:0)
Sep 1 13:57:25 localhost kernel: Call Trace:
Sep 1 13:57:25 localhost kernel: __schedule+0x28d/0x890
Sep 1 13:57:25 localhost kernel: schedule+0x36/0x80
Sep 1 13:57:25 localhost kernel: md_write_start+0xf0/0x220 [md_mod]
Sep 1 13:57:25 localhost kernel: ? remove_wait_queue+0x60/0x60
Sep 1 13:57:25 localhost kernel: raid5_make_request+0x89/0x8b0
[raid456]
Sep 1 13:57:25 localhost kernel: ? bio_split+0x5d/0x90
Sep 1 13:57:25 localhost kernel: ? blk_queue_split+0xd2/0x630
Sep 1 13:57:25 localhost kernel: ? remove_wait_queue+0x60/0x60
Sep 1 13:57:25 localhost kernel: md_make_request+0xf5/0x260 [md_mod]
....
All the processes send bio to md are stuck at md_write_start.
wait_event(mddev->sb_wait,
!test_bit(MD_SB_CHANGE_PENDING,
&mddev->sb_flags) && !mddev->suspended);
Sep 1 13:57:26 localhost kernel: INFO: task md0_reshape:23605
blocked for more than 120 seconds.
Sep 1 13:57:26 localhost kernel: Tainted: G OE 4.13.0-rc5 #2
Sep 1 13:57:26 localhost kernel: "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Sep 1 13:57:26 localhost kernel: md0_reshape D 0 23605
2 0x00000080
Sep 1 13:57:26 localhost kernel: Call Trace:
Sep 1 13:57:26 localhost kernel: __schedule+0x28d/0x890
Sep 1 13:57:26 localhost kernel: schedule+0x36/0x80
Sep 1 13:57:26 localhost kernel: raid5_sync_request+0x2cf/0x370
[raid456]
Sep 1 13:57:26 localhost kernel: ? remove_wait_queue+0x60/0x60
Sep 1 13:57:26 localhost kernel: md_do_sync+0xafe/0xee0 [md_mod]
Sep 1 13:57:26 localhost kernel: ? remove_wait_queue+0x60/0x60
Sep 1 13:57:26 localhost kernel: md_thread+0x132/0x180 [md_mod]
Sep 1 13:57:26 localhost kernel: kthread+0x109/0x140
Sep 1 13:57:26 localhost kernel: ? find_pers+0x70/0x70 [md_mod]
Sep 1 13:57:26 localhost kernel: ? kthread_park+0x60/0x60
Sep 1 13:57:26 localhost kernel: ? do_syscall_64+0x67/0x150
Sep 1 13:57:26 localhost kernel: ret_from_fork+0x25/0x30
It stucks at:
/* Allow raid5_quiesce to complete */
wait_event(conf->wait_for_overlap, conf->quiesce != 2);
Sep 1 13:57:26 localhost kernel: INFO: task mdadm:23613 blocked for
more than 120 seconds.
Sep 1 13:57:26 localhost kernel: Tainted: G OE 4.13.0-rc5 #2
Sep 1 13:57:26 localhost kernel: "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Sep 1 13:57:26 localhost kernel: mdadm D 0 23613
1 0x00000080
Sep 1 13:57:26 localhost kernel: Call Trace:
Sep 1 13:57:26 localhost kernel: __schedule+0x28d/0x890
Sep 1 13:57:26 localhost kernel: schedule+0x36/0x80
Sep 1 13:57:26 localhost kernel: raid5_quiesce+0x274/0x2b0 [raid456]
Sep 1 13:57:26 localhost kernel: ? remove_wait_queue+0x60/0x60
Sep 1 13:57:26 localhost kernel: suspend_lo_store+0x82/0xe0 [md_mod]
Sep 1 13:57:26 localhost kernel: md_attr_store+0x80/0xc0 [md_mod]
Sep 1 13:57:26 localhost kernel: sysfs_kf_write+0x3a/0x50
Sep 1 13:57:26 localhost kernel: kernfs_fop_write+0xff/0x180
Sep 1 13:57:26 localhost kernel: __vfs_write+0x37/0x170
Sep 1 13:57:26 localhost kernel: ? selinux_file_permission+0xe5/0x120
Sep 1 13:57:26 localhost kernel: ? security_file_permission+0x3b/0xc0
Sep 1 13:57:26 localhost kernel: vfs_write+0xb2/0x1b0
Sep 1 13:57:26 localhost kernel: ? syscall_trace_enter+0x1d0/0x2b0
Sep 1 13:57:26 localhost kernel: SyS_write+0x55/0xc0
Sep 1 13:57:26 localhost kernel: do_syscall_64+0x67/0x150
It's stuck at:
conf->quiesce = 2;
wait_event_cmd(conf->wait_for_quiescent,
atomic_read(&conf->active_stripes) == 0 &&
atomic_read(&conf->active_aligned_reads) == 0,
unlock_all_device_hash_locks_irq(conf),
lock_all_device_hash_locks_irq(conf));
conf->quiesce = 1;
[root@dell-pr1700-02 ~]# cat /proc/mdstat
Personalities : [raid6] [raid5] [raid4]
md0 : active raid5 loop6[7] loop4[6] loop5[5](S) loop3[3] loop2[2]
loop1[1] loop0[0]
2039808 blocks super 1.2 level 5, 512k chunk, algorithm 2
[6/6] [UUUUUU]
[>....................] reshape = 0.5% (2560/509952)
finish=162985.0min speed=0K/sec
unused devices: <none>
I can reproduce this. So I add some logs by printk to check
MD_SB_CHANGE_PENDING of mddev->flags
and mddev->suspended.
mddev->suspend : 0
mddev->flags : SP CHANGE PENDING is set
conf->quiesce : 2
The I echo active > /sys/block/md0/md/array_state, reshape can start
and finish successfully.
I notice there are some fixes for raid5 stuck problem. Not sure
whether it's introduced by those
patches.
Best Regards
Xiao
Thanks for the detailed report.
All the processes that you have mentioned are waiting for
raid5_quiesce() to complete.
raid5_quiesce() must be waiting for either active_stripes or
active_aligned_reads to reach zero. Most likely active_stripes.
That suggests that either there is a stripe that is active and isn't
being handled for some reason, or the accounting of active stripes has
problems.
The fact that setting the array to 'active' removes the hang is
interesting. That would cause the threads blocked in md_write_start to
continue, but I cannot see how that would affect active_stripes as
threads waiting for md_write_start() never hold a stripe. Doing that
could cause a stripe to be used, then released, which might trigger a
wakeup that had been lost.
At first I doubt there are some active strips that haven't been
handled yet.
But the process raid5d doesn't appear in calltrace. It wasn't stuck.
It would be useful to see if ->active_stripes is 0 when the deadlock
happens.
One way to do that is to add a printk into raid5_status(). Then
whenever you "cat /proc/mdstat" the printk will trigger and tell you the
value of ->active_stripes.
I haven't managed to reproduce this yet, or I would track it down my
self.
Sure the testing is running again. I'll give the information later.
Hi Neil
I have reproduced this.
[root@dell-pr1700-02 ~]# cat /proc/mdstat
Personalities : [raid6] [raid5] [raid4]
md0 : active raid5 loop6[7] loop4[6] loop5[5](S) loop3[3] loop2[2]
loop1[1] loop0[0]
2039808 blocks super 1.2 level 5, 512k chunk, algorithm 2 [6/6]
[UUUUUU]
[>....................] reshape = 0.5% (2560/509952)
finish=2498.2min speed=3K/sec
unused devices: <none>
[root@dell-pr1700-02 ~]# dmesg
[ 3072.826251] suspend : 0
[ 3072.828683] SP CHANGE PENDING is set
[ 3072.832243] conf quiesce 2
[ 3072.834932] active stripes : 251
[ 3072.838139] active aligned reads : 0
[root@dell-pr1700-02 ~]# ps auxf | grep md
...
root 1682 0.0 0.0 0 0 ? S< 23:02 0:00 \_ [md]
root 3103 97.2 0.0 0 0 ? R 23:34 14:06 \_
[md0_raid5]
root 3123 0.0 0.0 0 0 ? D 23:34 0:00 \_
[jbd2/md0-8]
root 3134 0.0 0.0 0 0 ? D 23:34 0:00 \_
[md0_reshape]
....
root 3142 0.5 0.0 108996 2728 pts/1 D+ 23:34 0:04
| \_ dd if=/dev/urandom of=/mnt/md_test/testfile bs=1M count=1000
root 3223 0.0 0.0 112672 2300 pts/0 S+ 23:48 0:00
\_ grep --color=auto md
root 3141 0.0 0.0 10132 5288 ? DLs 23:34 0:00
/usr/sbin/mdadm --grow --continue /dev/md0
It's strange, raid5d is running but it don't handle active stripes.
Do you need more information?
Regards
Xiao
Regards
Xiao
Thanks,
NeilBrown
--
To unsubscribe from this list: send the line "unsubscribe linux-raid" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
--
To unsubscribe from this list: send the line "unsubscribe linux-raid" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
