* Re: task xfssyncd blocked while raid5 was in recovery
[not found] <CACY-59cbWX9Gu_xsfqv_p8=Q7CabWZuj=ZH2K41j4N0-o-8WLw@mail.gmail.com>
@ 2012-10-24 3:17 ` hanguozhong
2012-10-24 5:14 ` NeilBrown
0 siblings, 1 reply; 12+ messages in thread
From: hanguozhong @ 2012-10-24 3:17 UTC (permalink / raw)
To: linux-raid; +Cc: neilb, stan
>From: GuoZhong Han
>Date: 2012-10-10 10:44
>To: linux-raid
>Subject: task xfssyncd blocked while raid5 was in recovery
>Hello, every one:
>Recently, a problem has troubled me for a long time.
>I created a 4*2T (sda, sdb, sdc, sdd) raid5 with XFS file system, 128K chuck size and 2048 strip_cache_size. The mdadm 3.2.2, kernel 2.6.38 and mkfs.xfs 3.1.1 were used. When the raid5 was in >recovery and the schedule reached 47%, I/O errors occurred in sdb. The following was the output:
>......
>ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
>ata2: status=0x41 { DriveReady Error }
>ata2: error=0x04 { DriveStatusError }
>ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
>ata2: status=0x41 { DriveReady Error }
>ata2: error=0x04 { DriveStatusError }
>ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
>ata2: status=0x41 { DriveReady Error }
>ata2: error=0x04 { DriveStatusError }
>ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
>ata2: status=0x41 { DriveReady Error }
>ata2: error=0x04 { DriveStatusError }
>ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
>ata2: status=0x41 { DriveReady Error }
>ata2: error=0x04 { DriveStatusError }
>ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
>ata2: status=0x41 { DriveReady Error }
>ata2: error=0x04 { DriveStatusError }
>ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
>ata2: status=0x41 { DriveReady Error }
>ata2: error=0x04 { DriveStatusError }
>ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
>ata2: status=0x41 { DriveReady Error }
>ata2: error=0x04 { DriveStatusError }
>ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
>ata2: status=0x41 { DriveReady Error }
>ata2: error=0x04 { DriveStatusError }
>ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
>ata2: status=0x41 { DriveReady Error }
>ata2: error=0x04 { DriveStatusError }
>ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
>ata2: status=0x41 { DriveReady Error }
>ata2: error=0x04 { DriveStatusError }
>ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
>ata2: status=0x41 { DriveReady Error }
>ata2: error=0x04 { DriveStatusError }
>ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
>……
>d 0:0:1:0: [sdb] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
>sd 0:0:1:0: [sdb] Sense Key : Aborted Command [current] [descriptor]
>Descriptor sense data with sense descriptors (in hex):
> 72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
> 00 00 00 f7
> sd 0:0:1:0: [sdb] Add. Sense: No additional sense information
> sd 0:0:1:0: [sdb] CDB: Read(10): 28 00 6f 4c cc 80 00 04 00 00
> end_request: I/O error, dev sdb, sector 1867304064
> hrtimer: interrupt took 28024956 ns
> ata2: status=0x41 { DriveReady Error }
> ata2: error=0x04 { DriveStatusError }
> ata2: translatedserver RspCode F688 Ctrl 0 Idx A6F Len 70 ATA stat/err 0x
> 41/04 to SCSI SK00 00 64 65 35 64 62 65 65 31 3A 32 64 38 35 63 37 30 63 3A 39 64 31 63 33 63 38 39 3A 32 32 64 39 32 65 32 31 00 00 00 00 00 00/ASC/ASCQ 0xb/00 /00
> 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2F 00 00 00 ata2: status=0x4
> 1 { DriveReady Error }
> ata2: error=0x04 { DriveStatusError }
> ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> sd 0:0:1:0: [sdb] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
> sd 0:0:1:0: [sdb] Sense Key : Aborted Command [current] [descriptor]
> Descriptor sense data with sense descriptors (in hex):
> 72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
> 00 00 00 f7
> sd 0:0:1:0: [sdb] Add. Sense: No additional sense information
> sd 0:0:1:0: [sdb] CDB: Read(10): 28 00 6f 4c a4 80 00 04 00 00
> end_request: I/O error, dev sdb, sector 1867293824
> ata2: status=0x41 { DriveReady Error }
> ……
> Then, there were lots of error messages about the file system. The following was the output:
> ......
> INFO: task xfssyncd/md127:1058 blocked for more than 120 seconds.
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> xfssyncd/md127 D fffffff7000216d0 0 1058 2 0x00000000
> frame 0: 0xfffffff700020570 __switch_to+0x1b8/0x1c0 (sp 0xfffffe008d7ff900)
> frame 1: 0xfffffff7000216d0 schedule+0x918/0x1538 (sp 0xfffffe008d7ff9d0)
> frame 2: 0xfffffff700022a90 schedule_timeout+0x268/0x5b0 (sp 0xfffffe008d7ffd18)
> frame 3: 0xfffffff700024ee0 __down+0xd8/0x158 (sp 0xfffffe008d7ffda8)
> frame 4: 0xfffffff70085da78 down.cold+0x8/0x28 (sp 0xfffffe008d7ffe18)
> frame 5: 0xfffffff700750788 xfs_buf_lock+0xd0/0x120 (sp 0xfffffe008d7ffe38)
> frame 6: 0xfffffff700821b40 xfs_getsb+0x38/0x78 (sp 0xfffffe008d7ffe50)
> frame 7: 0xfffffff70077e230 xfs_trans_getsb+0xe0/0x100 (sp 0xfffffe008d7ffe68)
> frame 8: 0xfffffff7006babc0 xfs_mod_sb+0x88/0x198 (sp 0xfffffe008d7ffe88)
> frame 9: 0xfffffff7007a6480 xfs_fs_log_dummy+0x68/0xe0 (sp 0xfffffe008d7ffeb8)
> frame 10: 0xfffffff70079c6c0 xfs_sync_worker+0xe0/0xe8 (sp 0xfffffe008d7ffed8)
> frame 11: 0xfffffff700570a00 xfssyncd+0x240/0x328 (sp 0xfffffe008d7ffef0)
> frame 12: 0xfffffff7000f0530 kthread+0xe0/0xe8 (sp 0xfffffe008d7fff80)
> frame 13: 0xfffffff7000bab38 start_kernel_thread+0x18/0x20 (sp 0xfffffe008d7fffe8)
> INFO: task xfssyncd/md127:1058 blocked for more than 120 seconds.
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> xfssyncd/md127 D fffffff7000216d0 0 1058 2 0x00000000
> frame 0: 0xfffffff700020570 __switch_to+0x1b8/0x1c0 (sp 0xfffffe008d7ff900)
> frame 1: 0xfffffff7000216d0 schedule+0x918/0x1538 (sp 0xfffffe008d7ff9d0)
> frame 2: 0xfffffff700022a90 schedule_timeout+0x268/0x5b0 (sp 0xfffffe008d7ffd18)
> frame 3: 0xfffffff700024ee0 __down+0xd8/0x158 (sp 0xfffffe008d7ffda8)
> frame 4: 0xfffffff70085da78 down.cold+0x8/0x28 (sp 0xfffffe008d7ffe18)
> frame 5: 0xfffffff700750788 xfs_buf_lock+0xd0/0x120 (sp 0xfffffe008d7ffe38)
> frame 6: 0xfffffff700821b40 xfs_getsb+0x38/0x78 (sp 0xfffffe008d7ffe50)
> frame 7: 0xfffffff70077e230 xfs_trans_getsb+0xe0/0x100 (sp 0xfffffe008d7ffe68)
> frame 8: 0xfffffff7006babc0 xfs_mod_sb+0x88/0x198 (sp 0xfffffe008d7ffe88)
> frame 9: 0xfffffff7007a6480 xfs_fs_log_dummy+0x68/0xe0 (sp 0xfffffe008d7ffeb8)
> frame 10: 0xfffffff70079c6c0 xfs_sync_worker+0xe0/0xe8 (sp 0xfffffe008d7ffed8)
> frame 11: 0xfffffff700570a00 xfssyncd+0x240/0x328 (sp 0xfffffe008d7ffef0)
> frame 12: 0xfffffff7000f0530 kthread+0xe0/0xe8 (sp 0xfffffe008d7fff80)
> frame 13: 0xfffffff7000bab38 start_kernel_thread+0x18/0x20 (sp 0xfffffe008d7fffe8)
> INFO: task xfssyncd/md127:1058 blocked for more than 120 seconds.
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> xfssyncd/md127 D fffffff7000216d0 0 1058 2 0x00000000
> frame 0: 0xfffffff700020570 __switch_to+0x1b8/0x1c0 (sp 0xfffffe008d7ff900)
> frame 1: 0xfffffff7000216d0 schedule+0x918/0x1538 (sp 0xfffffe008d7ff9d0)
> frame 2: 0xfffffff700022a90 schedule_timeout+0x268/0x5b0 (sp 0xfffffe008d7ffd18)
> frame 3: 0xfffffff700024ee0 __down+0xd8/0x158 (sp 0xfffffe008d7ffda8)
> frame 4: 0xfffffff70085da78 down.cold+0x8/0x28 (sp 0xfffffe008d7ffe18)
> frame 5: 0xfffffff700750788 xfs_buf_lock+0xd0/0x120 (sp 0xfffffe008d7ffe38)
> frame 6: 0xfffffff700821b40 xfs_getsb+0x38/0x78 (sp 0xfffffe008d7ffe50)
> frame 7: 0xfffffff70077e230 xfs_trans_getsb+0xe0/0x100 (sp 0xfffffe008d7ffe68)
> frame 8: 0xfffffff7006babc0 xfs_mod_sb+0x88/0x198 (sp 0xfffffe008d7ffe88)
> frame 9: 0xfffffff7007a6480 xfs_fs_log_dummy+0x68/0xe0 (sp 0xfffffe008d7ffeb8)
> frame 10: 0xfffffff70079c6c0 xfs_sync_worker+0xe0/0xe8 (sp 0xfffffe008d7ffed8)
> frame 11: 0xfffffff700570a00 xfssyncd+0x240/0x328 (sp 0xfffffe008d7ffef0)
> frame 12: 0xfffffff7000f0530 kthread+0xe0/0xe8 (sp 0xfffffe008d7fff80)
> ......
> The output said “INFO: task xfssyncd/md127:1058 blocked for more than 120 seconds”. What did that mean? I used “cat /proc/mdstat” to see the state of the raid5. The output was:
> Personalities : [raid0] [raid6] [raid5] [raid4]
> md127 : active raid5 sdd[3] sdc[2] sdb[1](F) sda[0]
> 5860540032 blocks super 1.2 level 5, 128k chunk, algorithm 2 [4/3] [U_UU]
> resync=PENDING
> unused devices: <none>
> The state of the raid5 was “PENDING”. I had never seen such a state of raid5 before. After that, I wrote a program to access the raid5, there was no response any more. Then I used “ps aux| > task xfssyncd” to see the state of “xfssyncd”. Unfortunately, there was no response yet. Then I tried “ps aux”. There were outputs, but the program could exit with “Ctrl+d” or “Ctrl+z”. And > when I tested the write performance for raid5, I/O errors often occurred. I did not know why this I/O errors occurred so frequently.
> What was the problem? Can any one help me?
At first, I thought it was a bug of xfs filesystem. Then I change the filesystem to ext4. I used sda, sdb, sdc and sdd to build a raid5 again.
When the raid5 was in recovery, I/O errors occurred in "sdb". And the state of the raid5 tend to "PENDING" again.
I used "ps aux|grep 127" to see the status of the programs. The following were the outputs:
root 1197 0.0 0.0 0 0 ? D Oct23 0:03 [jbd2/md127-8]
root 1157 75.6 0.0 0 0 ? R Oct23 908:02 [md127_raid5]
root 1159 1.2 0.0 0 0 ? S Oct23 14:36 [md127_resync]
root 1381 0.0 0.0 0 0 ? D Oct23 0:12 [flush-9:127]
The state of "md127_raid5", "jbd2/md127-8", "md127_resync", and "flush-9:127" did not change to other state when I used "ps aux|grep 127" many times.
And the %cpu of "md127_raid5" had been the highest in about 75.6%. Programs to read and write to "md127" seemed hang, there was no response.
I has no other way, unless restart the machine.
The following were the outputs of "smartctl -A /dev/sde":
# ./smartctl -A /dev/sde
smartctl 5.39.1 2010-01-28 r3054 [tilegx-unknown-linux-gnu] (local build)
Copyright (C) 2002-10 by Bruce Allen, http://smartmontools.sourceforge.net
Probable ATA device behind a SAT layer
Try an additional '-d ata' or '-d sat' argument.
I use the tilera platform, the newest kernel I can update is 3.0.38. Now I try to update my kernel to this version.
But I do not know if this problem have fixed in 3.0.38. If you have better solutions, please tell me.
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: task xfssyncd blocked while raid5 was in recovery
2012-10-24 3:17 ` task xfssyncd blocked while raid5 was in recovery hanguozhong
@ 2012-10-24 5:14 ` NeilBrown
2012-10-30 2:19 ` hanguozhong
0 siblings, 1 reply; 12+ messages in thread
From: NeilBrown @ 2012-10-24 5:14 UTC (permalink / raw)
To: hanguozhong; +Cc: linux-raid, stan
[-- Attachment #1: Type: text/plain, Size: 11499 bytes --]
On Wed, 24 Oct 2012 11:17:15 +0800 hanguozhong <hanguozhong@meganovo.com>
wrote:
> >From: GuoZhong Han
> >Date: 2012-10-10 10:44
> >To: linux-raid
> >Subject: task xfssyncd blocked while raid5 was in recovery
>
> >Hello, every one:
> >Recently, a problem has troubled me for a long time.
> >I created a 4*2T (sda, sdb, sdc, sdd) raid5 with XFS file system, 128K chuck size and 2048 strip_cache_size. The mdadm 3.2.2, kernel 2.6.38 and mkfs.xfs 3.1.1 were used. When the raid5 was in >recovery and the schedule reached 47%, I/O errors occurred in sdb. The following was the output:
>
> >......
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >……
> >d 0:0:1:0: [sdb] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
> >sd 0:0:1:0: [sdb] Sense Key : Aborted Command [current] [descriptor]
> >Descriptor sense data with sense descriptors (in hex):
> > 72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
> > 00 00 00 f7
> > sd 0:0:1:0: [sdb] Add. Sense: No additional sense information
> > sd 0:0:1:0: [sdb] CDB: Read(10): 28 00 6f 4c cc 80 00 04 00 00
> > end_request: I/O error, dev sdb, sector 1867304064
> > hrtimer: interrupt took 28024956 ns
> > ata2: status=0x41 { DriveReady Error }
> > ata2: error=0x04 { DriveStatusError }
> > ata2: translatedserver RspCode F688 Ctrl 0 Idx A6F Len 70 ATA stat/err 0x
> > 41/04 to SCSI SK00 00 64 65 35 64 62 65 65 31 3A 32 64 38 35 63 37 30 63 3A 39 64 31 63 33 63 38 39 3A 32 32 64 39 32 65 32 31 00 00 00 00 00 00/ASC/ASCQ 0xb/00 /00
> > 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2F 00 00 00 ata2: status=0x4
> > 1 { DriveReady Error }
> > ata2: error=0x04 { DriveStatusError }
> > ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> > sd 0:0:1:0: [sdb] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
> > sd 0:0:1:0: [sdb] Sense Key : Aborted Command [current] [descriptor]
> > Descriptor sense data with sense descriptors (in hex):
> > 72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
> > 00 00 00 f7
> > sd 0:0:1:0: [sdb] Add. Sense: No additional sense information
> > sd 0:0:1:0: [sdb] CDB: Read(10): 28 00 6f 4c a4 80 00 04 00 00
> > end_request: I/O error, dev sdb, sector 1867293824
> > ata2: status=0x41 { DriveReady Error }
> > ……
>
> > Then, there were lots of error messages about the file system. The following was the output:
>
> > ......
> > INFO: task xfssyncd/md127:1058 blocked for more than 120 seconds.
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > xfssyncd/md127 D fffffff7000216d0 0 1058 2 0x00000000
> > frame 0: 0xfffffff700020570 __switch_to+0x1b8/0x1c0 (sp 0xfffffe008d7ff900)
> > frame 1: 0xfffffff7000216d0 schedule+0x918/0x1538 (sp 0xfffffe008d7ff9d0)
> > frame 2: 0xfffffff700022a90 schedule_timeout+0x268/0x5b0 (sp 0xfffffe008d7ffd18)
> > frame 3: 0xfffffff700024ee0 __down+0xd8/0x158 (sp 0xfffffe008d7ffda8)
> > frame 4: 0xfffffff70085da78 down.cold+0x8/0x28 (sp 0xfffffe008d7ffe18)
> > frame 5: 0xfffffff700750788 xfs_buf_lock+0xd0/0x120 (sp 0xfffffe008d7ffe38)
> > frame 6: 0xfffffff700821b40 xfs_getsb+0x38/0x78 (sp 0xfffffe008d7ffe50)
> > frame 7: 0xfffffff70077e230 xfs_trans_getsb+0xe0/0x100 (sp 0xfffffe008d7ffe68)
> > frame 8: 0xfffffff7006babc0 xfs_mod_sb+0x88/0x198 (sp 0xfffffe008d7ffe88)
> > frame 9: 0xfffffff7007a6480 xfs_fs_log_dummy+0x68/0xe0 (sp 0xfffffe008d7ffeb8)
> > frame 10: 0xfffffff70079c6c0 xfs_sync_worker+0xe0/0xe8 (sp 0xfffffe008d7ffed8)
> > frame 11: 0xfffffff700570a00 xfssyncd+0x240/0x328 (sp 0xfffffe008d7ffef0)
> > frame 12: 0xfffffff7000f0530 kthread+0xe0/0xe8 (sp 0xfffffe008d7fff80)
> > frame 13: 0xfffffff7000bab38 start_kernel_thread+0x18/0x20 (sp 0xfffffe008d7fffe8)
> > INFO: task xfssyncd/md127:1058 blocked for more than 120 seconds.
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > xfssyncd/md127 D fffffff7000216d0 0 1058 2 0x00000000
> > frame 0: 0xfffffff700020570 __switch_to+0x1b8/0x1c0 (sp 0xfffffe008d7ff900)
> > frame 1: 0xfffffff7000216d0 schedule+0x918/0x1538 (sp 0xfffffe008d7ff9d0)
> > frame 2: 0xfffffff700022a90 schedule_timeout+0x268/0x5b0 (sp 0xfffffe008d7ffd18)
> > frame 3: 0xfffffff700024ee0 __down+0xd8/0x158 (sp 0xfffffe008d7ffda8)
> > frame 4: 0xfffffff70085da78 down.cold+0x8/0x28 (sp 0xfffffe008d7ffe18)
> > frame 5: 0xfffffff700750788 xfs_buf_lock+0xd0/0x120 (sp 0xfffffe008d7ffe38)
> > frame 6: 0xfffffff700821b40 xfs_getsb+0x38/0x78 (sp 0xfffffe008d7ffe50)
> > frame 7: 0xfffffff70077e230 xfs_trans_getsb+0xe0/0x100 (sp 0xfffffe008d7ffe68)
> > frame 8: 0xfffffff7006babc0 xfs_mod_sb+0x88/0x198 (sp 0xfffffe008d7ffe88)
> > frame 9: 0xfffffff7007a6480 xfs_fs_log_dummy+0x68/0xe0 (sp 0xfffffe008d7ffeb8)
> > frame 10: 0xfffffff70079c6c0 xfs_sync_worker+0xe0/0xe8 (sp 0xfffffe008d7ffed8)
> > frame 11: 0xfffffff700570a00 xfssyncd+0x240/0x328 (sp 0xfffffe008d7ffef0)
> > frame 12: 0xfffffff7000f0530 kthread+0xe0/0xe8 (sp 0xfffffe008d7fff80)
> > frame 13: 0xfffffff7000bab38 start_kernel_thread+0x18/0x20 (sp 0xfffffe008d7fffe8)
> > INFO: task xfssyncd/md127:1058 blocked for more than 120 seconds.
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > xfssyncd/md127 D fffffff7000216d0 0 1058 2 0x00000000
> > frame 0: 0xfffffff700020570 __switch_to+0x1b8/0x1c0 (sp 0xfffffe008d7ff900)
> > frame 1: 0xfffffff7000216d0 schedule+0x918/0x1538 (sp 0xfffffe008d7ff9d0)
> > frame 2: 0xfffffff700022a90 schedule_timeout+0x268/0x5b0 (sp 0xfffffe008d7ffd18)
> > frame 3: 0xfffffff700024ee0 __down+0xd8/0x158 (sp 0xfffffe008d7ffda8)
> > frame 4: 0xfffffff70085da78 down.cold+0x8/0x28 (sp 0xfffffe008d7ffe18)
> > frame 5: 0xfffffff700750788 xfs_buf_lock+0xd0/0x120 (sp 0xfffffe008d7ffe38)
> > frame 6: 0xfffffff700821b40 xfs_getsb+0x38/0x78 (sp 0xfffffe008d7ffe50)
> > frame 7: 0xfffffff70077e230 xfs_trans_getsb+0xe0/0x100 (sp 0xfffffe008d7ffe68)
> > frame 8: 0xfffffff7006babc0 xfs_mod_sb+0x88/0x198 (sp 0xfffffe008d7ffe88)
> > frame 9: 0xfffffff7007a6480 xfs_fs_log_dummy+0x68/0xe0 (sp 0xfffffe008d7ffeb8)
> > frame 10: 0xfffffff70079c6c0 xfs_sync_worker+0xe0/0xe8 (sp 0xfffffe008d7ffed8)
> > frame 11: 0xfffffff700570a00 xfssyncd+0x240/0x328 (sp 0xfffffe008d7ffef0)
> > frame 12: 0xfffffff7000f0530 kthread+0xe0/0xe8 (sp 0xfffffe008d7fff80)
> > ......
>
> > The output said “INFO: task xfssyncd/md127:1058 blocked for more than 120 seconds”. What did that mean? I used “cat /proc/mdstat” to see the state of the raid5. The output was:
>
> > Personalities : [raid0] [raid6] [raid5] [raid4]
> > md127 : active raid5 sdd[3] sdc[2] sdb[1](F) sda[0]
> > 5860540032 blocks super 1.2 level 5, 128k chunk, algorithm 2 [4/3] [U_UU]
> > resync=PENDING
>
> > unused devices: <none>
>
> > The state of the raid5 was “PENDING”. I had never seen such a state of raid5 before. After that, I wrote a program to access the raid5, there was no response any more. Then I used “ps aux| > task xfssyncd” to see the state of “xfssyncd”. Unfortunately, there was no response yet. Then I tried “ps aux”. There were outputs, but the program could exit with “Ctrl+d” or “Ctrl+z”. And > when I tested the write performance for raid5, I/O errors often occurred. I did not know why this I/O errors occurred so frequently.
> > What was the problem? Can any one help me?
>
> At first, I thought it was a bug of xfs filesystem. Then I change the filesystem to ext4. I used sda, sdb, sdc and sdd to build a raid5 again.
> When the raid5 was in recovery, I/O errors occurred in "sdb". And the state of the raid5 tend to "PENDING" again.
> I used "ps aux|grep 127" to see the status of the programs. The following were the outputs:
>
> root 1197 0.0 0.0 0 0 ? D Oct23 0:03 [jbd2/md127-8]
> root 1157 75.6 0.0 0 0 ? R Oct23 908:02 [md127_raid5]
> root 1159 1.2 0.0 0 0 ? S Oct23 14:36 [md127_resync]
> root 1381 0.0 0.0 0 0 ? D Oct23 0:12 [flush-9:127]
>
> The state of "md127_raid5", "jbd2/md127-8", "md127_resync", and "flush-9:127" did not change to other state when I used "ps aux|grep 127" many times.
> And the %cpu of "md127_raid5" had been the highest in about 75.6%. Programs to read and write to "md127" seemed hang, there was no response.
> I has no other way, unless restart the machine.
>
> The following were the outputs of "smartctl -A /dev/sde":
> # ./smartctl -A /dev/sde
> smartctl 5.39.1 2010-01-28 r3054 [tilegx-unknown-linux-gnu] (local build)
> Copyright (C) 2002-10 by Bruce Allen, http://smartmontools.sourceforge.net
>
> Probable ATA device behind a SAT layer
> Try an additional '-d ata' or '-d sat' argument.
>
> I use the tilera platform, the newest kernel I can update is 3.0.38. Now I try to update my kernel to this version.
> But I do not know if this problem have fixed in 3.0.38. If you have better solutions, please tell me.
Might be fixed by upstream commit:
commit fab363b5ff502d1b39ddcfec04271f5858d9f26e
Author: Shaohua Li <shli@kernel.org>
Date: Tue Jul 3 15:57:19 2012 +1000
raid5: delayed stripe fix
which is in 3.0.38.
If it isn't that, I don't know what it is.
So it is worth trying 3.0.38.
NeilBrown
[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 828 bytes --]
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: task xfssyncd blocked while raid5 was in recovery
2012-10-24 5:14 ` NeilBrown
@ 2012-10-30 2:19 ` hanguozhong
2012-10-30 4:49 ` Stan Hoeppner
0 siblings, 1 reply; 12+ messages in thread
From: hanguozhong @ 2012-10-30 2:19 UTC (permalink / raw)
To: linux-raid; +Cc: neilb, stan, 黄春辉
>From: NeilBrown
>Date: 2012-10-24 13:14
>To: hanguozhong
>CC: linux-raid; stan
>Subject: Re: task xfssyncd blocked while raid5 was in recovery
>On Wed, 24 Oct 2012 11:17:15 +0800 hanguozhong <hanguozhong@meganovo.com>
>wrote:
> >From: GuoZhong Han
> >Date: 2012-10-10 10:44
> >To: linux-raid
> >Subject: task xfssyncd blocked while raid5 was in recovery
>
> >Hello, every one:
> >Recently, a problem has troubled me for a long time.
> >I created a 4*2T (sda, sdb, sdc, sdd) raid5 with XFS file system, 128K chuck size and 2048 strip_cache_size. The mdadm 3.2.2, kernel 2.6.38 and mkfs.xfs 3.1.1 were used. When the raid5 was in >recovery and the schedule reached 47%, I/O errors occurred in sdb. The following was the output:
>
> >......
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >ata2: status=0x41 { DriveReady Error }
> >ata2: error=0x04 { DriveStatusError }
> >ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> >……
> >d 0:0:1:0: [sdb] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
> >sd 0:0:1:0: [sdb] Sense Key : Aborted Command [current] [descriptor]
> >Descriptor sense data with sense descriptors (in hex):
> > 72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
> > 00 00 00 f7
> > sd 0:0:1:0: [sdb] Add. Sense: No additional sense information
> > sd 0:0:1:0: [sdb] CDB: Read(10): 28 00 6f 4c cc 80 00 04 00 00
> > end_request: I/O error, dev sdb, sector 1867304064
> > hrtimer: interrupt took 28024956 ns
> > ata2: status=0x41 { DriveReady Error }
> > ata2: error=0x04 { DriveStatusError }
> > ata2: translatedserver RspCode F688 Ctrl 0 Idx A6F Len 70 ATA stat/err 0x
> > 41/04 to SCSI SK00 00 64 65 35 64 62 65 65 31 3A 32 64 38 35 63 37 30 63 3A 39 64 31 63 33 63 38 39 3A 32 32 64 39 32 65 32 31 00 00 00 00 00 00/ASC/ASCQ 0xb/00 /00
> > 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2F 00 00 00 ata2: status=0x4
> > 1 { DriveReady Error }
> > ata2: error=0x04 { DriveStatusError }
> > ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
> > sd 0:0:1:0: [sdb] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
> > sd 0:0:1:0: [sdb] Sense Key : Aborted Command [current] [descriptor]
> > Descriptor sense data with sense descriptors (in hex):
> > 72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
> > 00 00 00 f7
> > sd 0:0:1:0: [sdb] Add. Sense: No additional sense information
> > sd 0:0:1:0: [sdb] CDB: Read(10): 28 00 6f 4c a4 80 00 04 00 00
> > end_request: I/O error, dev sdb, sector 1867293824
> > ata2: status=0x41 { DriveReady Error }
> > ……
>
> > Then, there were lots of error messages about the file system. The following was the output:
>
> > ......
> > INFO: task xfssyncd/md127:1058 blocked for more than 120 seconds.
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > xfssyncd/md127 D fffffff7000216d0 0 1058 2 0x00000000
> > frame 0: 0xfffffff700020570 __switch_to+0x1b8/0x1c0 (sp 0xfffffe008d7ff900)
> > frame 1: 0xfffffff7000216d0 schedule+0x918/0x1538 (sp 0xfffffe008d7ff9d0)
> > frame 2: 0xfffffff700022a90 schedule_timeout+0x268/0x5b0 (sp 0xfffffe008d7ffd18)
> > frame 3: 0xfffffff700024ee0 __down+0xd8/0x158 (sp 0xfffffe008d7ffda8)
> > frame 4: 0xfffffff70085da78 down.cold+0x8/0x28 (sp 0xfffffe008d7ffe18)
> > frame 5: 0xfffffff700750788 xfs_buf_lock+0xd0/0x120 (sp 0xfffffe008d7ffe38)
> > frame 6: 0xfffffff700821b40 xfs_getsb+0x38/0x78 (sp 0xfffffe008d7ffe50)
> > frame 7: 0xfffffff70077e230 xfs_trans_getsb+0xe0/0x100 (sp 0xfffffe008d7ffe68)
> > frame 8: 0xfffffff7006babc0 xfs_mod_sb+0x88/0x198 (sp 0xfffffe008d7ffe88)
> > frame 9: 0xfffffff7007a6480 xfs_fs_log_dummy+0x68/0xe0 (sp 0xfffffe008d7ffeb8)
> > frame 10: 0xfffffff70079c6c0 xfs_sync_worker+0xe0/0xe8 (sp 0xfffffe008d7ffed8)
> > frame 11: 0xfffffff700570a00 xfssyncd+0x240/0x328 (sp 0xfffffe008d7ffef0)
> > frame 12: 0xfffffff7000f0530 kthread+0xe0/0xe8 (sp 0xfffffe008d7fff80)
> > frame 13: 0xfffffff7000bab38 start_kernel_thread+0x18/0x20 (sp 0xfffffe008d7fffe8)
> > INFO: task xfssyncd/md127:1058 blocked for more than 120 seconds.
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > xfssyncd/md127 D fffffff7000216d0 0 1058 2 0x00000000
> > frame 0: 0xfffffff700020570 __switch_to+0x1b8/0x1c0 (sp 0xfffffe008d7ff900)
> > frame 1: 0xfffffff7000216d0 schedule+0x918/0x1538 (sp 0xfffffe008d7ff9d0)
> > frame 2: 0xfffffff700022a90 schedule_timeout+0x268/0x5b0 (sp 0xfffffe008d7ffd18)
> > frame 3: 0xfffffff700024ee0 __down+0xd8/0x158 (sp 0xfffffe008d7ffda8)
> > frame 4: 0xfffffff70085da78 down.cold+0x8/0x28 (sp 0xfffffe008d7ffe18)
> > frame 5: 0xfffffff700750788 xfs_buf_lock+0xd0/0x120 (sp 0xfffffe008d7ffe38)
> > frame 6: 0xfffffff700821b40 xfs_getsb+0x38/0x78 (sp 0xfffffe008d7ffe50)
> > frame 7: 0xfffffff70077e230 xfs_trans_getsb+0xe0/0x100 (sp 0xfffffe008d7ffe68)
> > frame 8: 0xfffffff7006babc0 xfs_mod_sb+0x88/0x198 (sp 0xfffffe008d7ffe88)
> > frame 9: 0xfffffff7007a6480 xfs_fs_log_dummy+0x68/0xe0 (sp 0xfffffe008d7ffeb8)
> > frame 10: 0xfffffff70079c6c0 xfs_sync_worker+0xe0/0xe8 (sp 0xfffffe008d7ffed8)
> > frame 11: 0xfffffff700570a00 xfssyncd+0x240/0x328 (sp 0xfffffe008d7ffef0)
> > frame 12: 0xfffffff7000f0530 kthread+0xe0/0xe8 (sp 0xfffffe008d7fff80)
> > frame 13: 0xfffffff7000bab38 start_kernel_thread+0x18/0x20 (sp 0xfffffe008d7fffe8)
> > INFO: task xfssyncd/md127:1058 blocked for more than 120 seconds.
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > xfssyncd/md127 D fffffff7000216d0 0 1058 2 0x00000000
> > frame 0: 0xfffffff700020570 __switch_to+0x1b8/0x1c0 (sp 0xfffffe008d7ff900)
> > frame 1: 0xfffffff7000216d0 schedule+0x918/0x1538 (sp 0xfffffe008d7ff9d0)
> > frame 2: 0xfffffff700022a90 schedule_timeout+0x268/0x5b0 (sp 0xfffffe008d7ffd18)
> > frame 3: 0xfffffff700024ee0 __down+0xd8/0x158 (sp 0xfffffe008d7ffda8)
> > frame 4: 0xfffffff70085da78 down.cold+0x8/0x28 (sp 0xfffffe008d7ffe18)
> > frame 5: 0xfffffff700750788 xfs_buf_lock+0xd0/0x120 (sp 0xfffffe008d7ffe38)
> > frame 6: 0xfffffff700821b40 xfs_getsb+0x38/0x78 (sp 0xfffffe008d7ffe50)
> > frame 7: 0xfffffff70077e230 xfs_trans_getsb+0xe0/0x100 (sp 0xfffffe008d7ffe68)
> > frame 8: 0xfffffff7006babc0 xfs_mod_sb+0x88/0x198 (sp 0xfffffe008d7ffe88)
> > frame 9: 0xfffffff7007a6480 xfs_fs_log_dummy+0x68/0xe0 (sp 0xfffffe008d7ffeb8)
> > frame 10: 0xfffffff70079c6c0 xfs_sync_worker+0xe0/0xe8 (sp 0xfffffe008d7ffed8)
> > frame 11: 0xfffffff700570a00 xfssyncd+0x240/0x328 (sp 0xfffffe008d7ffef0)
> > frame 12: 0xfffffff7000f0530 kthread+0xe0/0xe8 (sp 0xfffffe008d7fff80)
> > ......
>
> > The output said “INFO: task xfssyncd/md127:1058 blocked for more than 120 seconds”. What did that mean? I used “cat /proc/mdstat” to see the state of the raid5. The output was:
>
> > Personalities : [raid0] [raid6] [raid5] [raid4]
> > md127 : active raid5 sdd[3] sdc[2] sdb[1](F) sda[0]
> > 5860540032 blocks super 1.2 level 5, 128k chunk, algorithm 2 [4/3] [U_UU]
> > resync=PENDING
>
> > unused devices: <none>
>
> > The state of the raid5 was “PENDING”. I had never seen such a state of raid5 before. After that, I wrote a program to access the raid5, there was no response any more. Then I used “ps aux| > task xfssyncd” to see the state of “xfssyncd”. Unfortunately, there was no response yet. Then I tried “ps aux”. There were outputs, but the program could exit with “Ctrl+d” or “Ctrl+z”. And > when I tested the write performance for raid5, I/O errors often occurred. I did not know why this I/O errors occurred so frequently.
> > What was the problem? Can any one help me?
>
> At first, I thought it was a bug of xfs filesystem. Then I change the filesystem to ext4. I used sda, sdb, sdc and sdd to build a raid5 again.
> When the raid5 was in recovery, I/O errors occurred in "sdb". And the state of the raid5 tend to "PENDING" again.
> I used "ps aux|grep 127" to see the status of the programs. The following were the outputs:
>
> root 1197 0.0 0.0 0 0 ? D Oct23 0:03 [jbd2/md127-8]
> root 1157 75.6 0.0 0 0 ? R Oct23 908:02 [md127_raid5]
> root 1159 1.2 0.0 0 0 ? S Oct23 14:36 [md127_resync]
> root 1381 0.0 0.0 0 0 ? D Oct23 0:12 [flush-9:127]
>
> The state of "md127_raid5", "jbd2/md127-8", "md127_resync", and "flush-9:127" did not change to other state when I used "ps aux|grep 127" many times.
> And the %cpu of "md127_raid5" had been the highest in about 75.6%. Programs to read and write to "md127" seemed hang, there was no response.
> I has no other way, unless restart the machine.
>
> The following were the outputs of "smartctl -A /dev/sde":
> # ./smartctl -A /dev/sde
> smartctl 5.39.1 2010-01-28 r3054 [tilegx-unknown-linux-gnu] (local build)
> Copyright (C) 2002-10 by Bruce Allen, http://smartmontools.sourceforge.net
>
> Probable ATA device behind a SAT layer
> Try an additional '-d ata' or '-d sat' argument.
>
> I use the tilera platform, the newest kernel I can update is 3.0.38. Now I try to update my kernel to this version.
> But I do not know if this problem have fixed in 3.0.38. If you have better solutions, please tell me.
>>Might be fixed by upstream commit:
>>commit fab363b5ff502d1b39ddcfec04271f5858d9f26e
>>Author: Shaohua Li <shli@kernel.org>
>>Date: Tue Jul 3 15:57:19 2012 +1000
>> raid5: delayed stripe fix
>>which is in 3.0.38.
>>If it isn't that, I don't know what it is.
>>So it is worth trying 3.0.38.
>>NeilBrown
Hi, Neil:
Thanks for your advice.
I tried to update my kernel to 3.0.38 last week.
Then I creted a 4*2T(sda, sdb, sdc, sdd) raid5 include the "bad" disk(sdb) just like last time.
Diffrent from the last test, I added 8 disks(sde, sdf, sdg, sdh, sdi, sdj, sjk, sdl) for the tests.
The disks were plugged in the device via 2 2680 Rocket cards. Each Rocket card supported at most 8 disks.
In the first test, Rocket card 1 accessed sda,sdb...,sdg and sdh, meanwhile Rocket car accessed sdi,sdj,sdk and sdl.
I used a program to write 10M datas to the array per second for test while the array was in recovery.
And when the percentage of the recovery went up to 92.1%, the speed of the recovery turned down to 18K/sec.
The outputs of the system said:
2012-10-27 23:57:04 ata9.00: exception Emask 0x0 SAct 0x7fffffff SErr 0x0 action 0x6 t0
2012-10-27 23:57:04 ata9.00: failed command: READ FPDMA QUEUED
2012-10-27 23:57:04 ata9.00: cmd 60/00:00:80:62:a7/04:00:d6:00:00/40 tag 0 ncq 524288 in
2012-10-27 23:57:04 res 01/04:b4:80:ca:a7/00:00:d6:00:00/40 Emask 0x2 (HSM violation)
2012-10-27 23:57:04 ata9.00: status: { ERR }
2012-10-27 23:57:04 ata9.00: error: { ABRT }
2012-10-27 23:57:04 ata9.00: failed command: READ FPDMA QUEUED
2012-10-27 23:57:04 ata9.00: cmd 60/00:00:80:82:a7/04:00:d6:00:00/40 tag 1 ncq 524288 in
2012-10-27 23:57:04 res 01/04:b4:80:ca:a7/00:00:d6:00:00/40 Emask 0x2 (HSM violation)
2012-10-27 23:57:04 ata9.00: status: { ERR }
2012-10-27 23:57:04 ata9.00: error: { ABRT }
2012-10-27 23:57:04 ata9.00: failed command: READ FPDMA QUEUED
2012-10-27 23:57:04 ata9.00: cmd 60/00:00:80:66:a7/04:00:d6:00:00/40 tag 2 ncq 524288 in
2012-10-27 23:57:04 res 01/04:b4:80:ca:a7/00:00:d6:00:00/40 Emask 0x2 (HSM violation)
2012-10-27 23:57:04 ata9.00: status: { ERR }
2012-10-27 23:57:04 ata9.00: error: { ABRT }
2012-10-27 23:57:04 ata9.00: failed command: READ FPDMA QUEUED
2012-10-27 23:57:04 ata9.00: cmd 60/00:00:80:6a:a7/04:00:d6:00:00/40 tag 3 ncq 524288 in
2012-10-27 23:57:04 res 01/04:b4:80:ca:a7/00:00:d6:00:00/40 Emask 0x2 (HSM violation)
2012-10-27 23:57:04 ata9.00: status: { ERR }
2012-10-27 23:57:04 ata9.00: error: { ABRT }
...
2012-10-27 23:57:04 ata9.00: failed command: READ FPDMA QUEUED
2012-10-27 23:57:04 ata9.00: cmd 60/00:00:80:be:a7/04:00:d6:00:00/40 tag 19 ncq 524288 in
2012-10-27 23:57:04 res 01/04:b4:80:ca:a7/00:00:d6:00:00/40 Emask 0x2 (HSM violation)
...
2012-10-27 23:57:05 ata9.00: cmd 60/00:00:80:4e:a2/04:00:d6:00:00/40 tag 30 ncq 524288 in
2012-10-27 23:57:05 res 01/04:b4:80:ca:a7/00:00:d6:00:00/40 Emask 0x2 (HSM violation)
2012-10-27 23:57:05 ata9.00: status: { ERR }
2012-10-27 23:57:05 ata9.00: error: { ABRT }
2012-10-27 23:57:05 ata9: hard resetting link
2012-10-27 23:57:07 ata9.00: configured for UDMA/133
2012-10-27 23:57:07 ata9: EH complete
The status of the raid5 was not "PENDING" in this test, and the %cpu of "md127_raid5" was normal.
But three was no response to my program which wrote datas to the array since the recovery speed slowed down.
The following were the outputs of "ps aux|grep md127" and "cat /proc/mdstat"
#ps aux|grep md127
root 1462 1.3 0.0 0 0 ? S Oct27 33:42 [md127_raid5]
root 1464 0.6 0.0 0 0 ? D Oct27 16:09 [md127_resync]
root 1497 0.0 0.0 0 0 ? S Oct27 0:12 [xfsbufd/md127]
root 1498 0.0 0.0 0 0 ? S Oct27 1:45 [xfsaild/md127]
root 1501 0.0 0.0 0 0 ? D Oct27 1:16 [flush-9:127]
# cat /proc/mdstat
Personalities : [raid6] [raid5] [raid4]
md127 : active raid5 sdd[3] sdc[2] sdb[1] sda[0]
5860540032 blocks super 1.2 level 5, 128k chunk, algorithm 2 [4/4] [UUUU]
[==================>..] resync = 92.1% (1800644160/1953513344) finish=140607.9min speed=18K/sec
unused devices: <none>
I used "fdisk -l /dev/sd*" to see if "fdisk" could access the disks, there were no responses of sda,sdb...,
sdg and sdh which could be accessed via card 1. On the contrary, the outputs of sdi,sdj,sdk and sdl were quite normal.
Programs to read and write to the device which connected to card 1 seemed hang, they were all in the "D" staus. And
then I used "reboot" to restart the system, there was no respones yet.
Then I did another test, I unplugged sda, sdb, sdc and sdd and plugged they the other slots which connected to card 2.
The result was as the same as the first test. The speed of recovery slowed down when the percentage of recovery went up to 92.1%.
And there were the same outputs as the former. When I used "fdisk -l /dev/sd*" to see if "fdisk" could access the disks. I found
there were no respones of the disks which could be access via card 2. The outputs of the disks connect to card 1 were normal.
It seemed that the "bad" disk in the raid5 hanged the IO of the card which it was connected to.
Other disks, regardless of whether they were in the array or not, as long as they were connected to the card,
the programs to write to or read from the they would be blocked.
My problem seems not really be solved, can you help me? I would be very grateful to you.
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: task xfssyncd blocked while raid5 was in recovery
2012-10-30 2:19 ` hanguozhong
@ 2012-10-30 4:49 ` Stan Hoeppner
0 siblings, 0 replies; 12+ messages in thread
From: Stan Hoeppner @ 2012-10-30 4:49 UTC (permalink / raw)
To: GuoZhong Han; +Cc: linux-raid, neilb, 黄春辉
On 10/29/2012 9:19 PM, hanguozhong wrote:
> The disks were plugged in the device via 2 2680 Rocket cards. Each Rocket card supported at most 8 disks.
Card: HighPoint RocketRAID 2680/2680SGL Marvell 88SE6485
Driver: MVSAS
After years of development the MVSAS driver is still not suitable for
production use. It is the cause of your problems here. Any board using
the Marvell SAS chips is not suitable for use with Linux at this time
due to the poor driver quality. These boards work fine under Windows
apparently.
> 2012-10-27 23:57:04 ata9.00: exception Emask 0x0 SAct 0x7fffffff SErr 0x0 action 0x6 t0
> 2012-10-27 23:57:04 ata9.00: failed command: READ FPDMA QUEUED
> 2012-10-27 23:57:04 ata9.00: cmd 60/00:00:80:62:a7/04:00:d6:00:00/40 tag 0 ncq 524288 in
> 2012-10-27 23:57:04 res 01/04:b4:80:ca:a7/00:00:d6:00:00/40 Emask 0x2 (HSM violation)
<snip>
> 2012-10-27 23:57:07 ata9.00: configured for UDMA/133
> 2012-10-27 23:57:07 ata9: EH complete
<snip>
> My problem seems not really be solved, can you help me? I would be very grateful to you.
Yes, I can help. Replace the HighPoint boards with LSI 9211-8i boards
and everything should work fine, barring any compatibility issue with
the Tilera platform.
--
Stan
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: task xfssyncd blocked while raid5 was in recovery
[not found] ` <201210112054336567511@meganovo.com>
@ 2012-10-11 14:47 ` Stan Hoeppner
0 siblings, 0 replies; 12+ messages in thread
From: Stan Hoeppner @ 2012-10-11 14:47 UTC (permalink / raw)
To: hanguozhong; +Cc: Mikael Abrahamsson, Linux RAID
On 10/11/2012 7:54 AM, hanguozhong wrote:
>>> Doesn't he still have 3 good drives? So since sdb was failed, there
>>> would be no reason for sdb to cause blocking or writes to the (now
>>> degraded) raid5? OP said he saw write IO errors to the array (?), which
>>> I thought was strange.
>>
>> I think the more important question is, why was the OP writing to a
>> filesystem on a small RAID5 array while it was doing a rebuild?
>
>>> Why is that an important question?
>
>>> Even if he was, should there ever be IO write errors on it, even if it has
>>> a lot of load on it?
>
> The problem was, there was no response to my program any more after xfssyncd was blocked.
> And I could use "rm -rf /mnt/md127/*" to remove the datas in the raid5.
Please always reply to the linux-raid list, not to individual subscribers.
None of the above really matters at this point. We know you have one
disk with at least one bad sector which isn't being reassigned for some
reason. We know that the error recovery procedure in the drive and the
block layer was causing problems. We also know you were generating a
non-trivial amount of IO on the array with a rebuild and application
write load when xfssyncd blocked.
It seems your application was likely doing sync, fsync, or fdatasync
operations. Writes to the XFS journal are always synchronous barrier
writes, so if you were running a metadata heavy benchmark program you
were issuing lots of fsyncs. It seems that due to the underlying IO
problems, xfssyncd was blocking on ack from the fsyncs. If that's not
the case, then you're hitting one of the XFS bugs I mentioned that have
already been fixed in newer kernels.
Thus, your solution is:
1. Fix or replace the drive with the bad sector(s)
2. Update to a 3.x series kernel
Discussing anything else before you complete these tasks is a waste of
keystrokes, yours and ours.
--
Stan
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: task xfssyncd blocked while raid5 was in recovery
2012-10-11 2:42 ` hanguozhong
2012-10-11 3:47 ` Chris Murphy
@ 2012-10-11 11:20 ` Stan Hoeppner
1 sibling, 0 replies; 12+ messages in thread
From: Stan Hoeppner @ 2012-10-11 11:20 UTC (permalink / raw)
To: linux-raid
On 10/10/2012 9:42 PM, hanguozhong wrote:
> Hm, I searched "XFS.. blocked for 120s" on google. There was a same problem
> with me, the flowing is the link:
> http://lists.debian.org/debian-kernel/2012/01/msg00274.html
That's not the same problem as you. The INFO text doesn't tell you the
source of the problem, the included thread information does. To debug
that you need to be an XFS developer. Which is why you should report
that to the xfs list, not here.
> I use the tilera platform, so it is hard to upgrade to kernel 3.2.31 or 3.4.13.
Ahh, I didn't recognize your name. You're the guy trying to build the 8
drive storage appliance with a 36 core Tilera chip.
What is the latest Tilera supported kernel? Do they support any 3.x
series kernels? How often do they update their kernel and userland code
so you can get badly needed bug fixes?
This is the 2nd glaring reason demonstrating you should have gone with
x86, or another fully supported low core count low power CPU (MIPS), as
I previously mentioned.
--
Stan
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: task xfssyncd blocked while raid5 was in recovery
2012-10-11 11:01 ` Stan Hoeppner
@ 2012-10-11 11:16 ` Mikael Abrahamsson
[not found] ` <201210112054336567511@meganovo.com>
0 siblings, 1 reply; 12+ messages in thread
From: Mikael Abrahamsson @ 2012-10-11 11:16 UTC (permalink / raw)
To: Stan Hoeppner; +Cc: linux-raid
On Thu, 11 Oct 2012, Stan Hoeppner wrote:
>> Doesn't he still have 3 good drives? So since sdb was failed, there
>> would be no reason for sdb to cause blocking or writes to the (now
>> degraded) raid5? OP said he saw write IO errors to the array (?), which
>> I thought was strange.
>
> I think the more important question is, why was the OP writing to a
> filesystem on a small RAID5 array while it was doing a rebuild?
Why is that an important question?
Even if he was, should there ever be IO write errors on it, even if it has
a lot of load on it?
--
Mikael Abrahamsson email: swmike@swm.pp.se
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: task xfssyncd blocked while raid5 was in recovery
2012-10-11 6:12 ` Mikael Abrahamsson
@ 2012-10-11 11:01 ` Stan Hoeppner
2012-10-11 11:16 ` Mikael Abrahamsson
0 siblings, 1 reply; 12+ messages in thread
From: Stan Hoeppner @ 2012-10-11 11:01 UTC (permalink / raw)
To: linux-raid
On 10/11/2012 1:12 AM, Mikael Abrahamsson wrote:
> On Wed, 10 Oct 2012, Stan Hoeppner wrote:
>
>> Precisely what it says. It doesn't tell you WHY it was blocked, as it
>> can't know. The fact that your md array was in recovery and having
>> problems with one of the member drives is a good reason for xfssyncd
>> to block.
>
> Doesn't he still have 3 good drives? So since sdb was failed, there
> would be no reason for sdb to cause blocking or writes to the (now
> degraded) raid5? OP said he saw write IO errors to the array (?), which
> I thought was strange.
I think the more important question is, why was the OP writing to a
filesystem on a small RAID5 array while it was doing a rebuild? My
assumption here was that the seek load due to the rebuild was what
caused xfssyncd to block. IO Load is a common cause of this particular
kernel message when it relates to XFS.
Note this msg is not an error, but informational, thus the "INFO: " tag.
This is why you have the option to turn off the message. Also note
there are many conditions that will prompt this "blocked for 120s"
kernel message, and that this message is not unique to XFS. Point of
fact, Google for "blocked for more than 120 seconds" and no results on
the first page relate to XFS.
--
Stan
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: task xfssyncd blocked while raid5 was in recovery
2012-10-10 11:54 ` Stan Hoeppner
2012-10-11 2:42 ` hanguozhong
@ 2012-10-11 6:12 ` Mikael Abrahamsson
2012-10-11 11:01 ` Stan Hoeppner
1 sibling, 1 reply; 12+ messages in thread
From: Mikael Abrahamsson @ 2012-10-11 6:12 UTC (permalink / raw)
To: linux-raid
On Wed, 10 Oct 2012, Stan Hoeppner wrote:
> Precisely what it says. It doesn't tell you WHY it was blocked, as it
> can't know. The fact that your md array was in recovery and having
> problems with one of the member drives is a good reason for xfssyncd to
> block.
Doesn't he still have 3 good drives? So since sdb was failed, there would
be no reason for sdb to cause blocking or writes to the (now degraded)
raid5? OP said he saw write IO errors to the array (?), which I thought
was strange.
--
Mikael Abrahamsson email: swmike@swm.pp.se
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: task xfssyncd blocked while raid5 was in recovery
2012-10-11 2:42 ` hanguozhong
@ 2012-10-11 3:47 ` Chris Murphy
2012-10-11 11:20 ` Stan Hoeppner
1 sibling, 0 replies; 12+ messages in thread
From: Chris Murphy @ 2012-10-11 3:47 UTC (permalink / raw)
To: linux-raid
On Oct 10, 2012, at 8:42 PM, hanguozhong wrote:
>
> I did not save the outputs of smartctl, but I remember that the “RAW_VALUE”
> of the attribute whose name was“Current_Pending_Sector” of sdb was 1. Did that
> indicate that the drive was bad?
Just one sector is bad. But there are other attributes, maybe the disk isn't spinning up, maybe there are a lot of other read errors or uncorrected ECC errors. So I think we need more data.
smartctl -A /dev/sdb
> If the drive was not bad, what is the best way to relocate
> these bad sectors to spare? I have been using the tool "HDD_Regenerator" running in windows,
> which is too slow. Each relocation took dozens of hours. It takes a long time to find the bad sector.
> If you have any better idea, please let me know.
Bad sectors can be like mice. Chances are, you've got more than one. I would obliterate the disk with Secure Erase. It's faster than writing zeros with dd. But I question why normal usage isn't causing the sectors to be reallocated and you continue to have errors. I personally would replace the disk, and get the array back to normal health, and then futz with the misbehaving drive on a separate system - if this is an important array.
Chris Murphy
--
To unsubscribe from this list: send the line "unsubscribe linux-raid" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: task xfssyncd blocked while raid5 was in recovery
2012-10-10 3:14 GuoZhong Han
@ 2012-10-10 11:54 ` Stan Hoeppner
2012-10-11 2:42 ` hanguozhong
2012-10-11 6:12 ` Mikael Abrahamsson
0 siblings, 2 replies; 12+ messages in thread
From: Stan Hoeppner @ 2012-10-10 11:54 UTC (permalink / raw)
To: GuoZhong Han; +Cc: linux-raid
On 10/9/2012 10:14 PM, GuoZhong Han wrote:
> Recently, a problem has troubled me for a long time.
>
> I created a 4*2T (sda, sdb, sdc, sdd) raid5 with XFS file system, 128K
> chuck size and 2048 strip_cache_size. The mdadm 3.2.2, kernel 2.6.38
> and mkfs.xfs 3.1.1 were used. When the raid5 was in recovery and the
> schedule reached 47%, I/O errors occurred in sdb. The following was
> the output:
> ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
>
> ata2: status=0x41 { DriveReady Error }
>
> ata2: error=0x04 { DriveStatusError }
<snip repeated log entries>
> end_request: I/O error, dev sdb, sector 1867304064
Run smartctl and post this section:
"Vendor Specific SMART Attributes with Thresholds"
The drive that is sdb may or may not be bad. smartctl may tell you
(us). If the drive is not bad you'll need to force relocation of this
bad sector to a spare. If you don't know how we can assist.
> INFO: task xfssyncd/md127:1058 blocked for more than 120 seconds.
> The output said “INFO: task xfssyncd/md127:1058 blocked for more than
> 120 seconds”. What did that mean?
Precisely what it says. It doesn't tell you WHY it was blocked, as it
can't know. The fact that your md array was in recovery and having
problems with one of the member drives is a good reason for xfssyncd to
block.
> The state of the raid5 was “PENDING”. I had never seen such a
> state of raid5 before. After that, I wrote a program to access the
> raid5, there was no response any more. Then I used “ps aux| task
> xfssyncd” to see the state of “xfssyncd”. Unfortunately, there was no
> response yet. Then I tried “ps aux”. There were outputs, but the
> program could exit with “Ctrl+d” or “Ctrl+z”. And when I tested the
> write performance for raid5, I/O errors often occurred. I did not know
> why this I/O errors occurred so frequently.
>
> What was the problem? Can any one help me?
It looks like drive sdb is bad or going bad. smartctl output or
additional testing should confirm this.
Also, your "XFS...blocked for 120s" error reminds me there are some
known bugs in XFS kernel 2.6.38 which cause a similar error, but are not
the cause of your error. Yours is a drive problem. Nonetheless, there
have been dozens of XFS bugs fixed since 2.6.38 and I recommend you
upgrade to kernel 3.2.31 or 3.4.13 if you roll your own kernels. If you
use distro kernels get the latest 3.x series in the repos.
--
Stan
--
To unsubscribe from this list: send the line "unsubscribe linux-raid" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 12+ messages in thread
* task xfssyncd blocked while raid5 was in recovery
@ 2012-10-10 3:14 GuoZhong Han
2012-10-10 11:54 ` Stan Hoeppner
0 siblings, 1 reply; 12+ messages in thread
From: GuoZhong Han @ 2012-10-10 3:14 UTC (permalink / raw)
To: linux-raid
Hello, every one:
Recently, a problem has troubled me for a long time.
I created a 4*2T (sda, sdb, sdc, sdd) raid5 with XFS file system, 128K
chuck size and 2048 strip_cache_size. The mdadm 3.2.2, kernel 2.6.38
and mkfs.xfs 3.1.1 were used. When the raid5 was in recovery and the
schedule reached 47%, I/O errors occurred in sdb. The following was
the output:
......
ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
ata2: status=0x41 { DriveReady Error }
ata2: error=0x04 { DriveStatusError }
ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
ata2: status=0x41 { DriveReady Error }
ata2: error=0x04 { DriveStatusError }
ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
ata2: status=0x41 { DriveReady Error }
ata2: error=0x04 { DriveStatusError }
ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
ata2: status=0x41 { DriveReady Error }
ata2: error=0x04 { DriveStatusError }
ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
ata2: status=0x41 { DriveReady Error }
ata2: error=0x04 { DriveStatusError }
ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
ata2: status=0x41 { DriveReady Error }
ata2: error=0x04 { DriveStatusError }
ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
ata2: status=0x41 { DriveReady Error }
ata2: error=0x04 { DriveStatusError }
ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
ata2: status=0x41 { DriveReady Error }
ata2: error=0x04 { DriveStatusError }
ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
ata2: status=0x41 { DriveReady Error }
ata2: error=0x04 { DriveStatusError }
ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
ata2: status=0x41 { DriveReady Error }
ata2: error=0x04 { DriveStatusError }
ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
ata2: status=0x41 { DriveReady Error }
ata2: error=0x04 { DriveStatusError }
ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
ata2: status=0x41 { DriveReady Error }
ata2: error=0x04 { DriveStatusError }
ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
……
d 0:0:1:0: [sdb] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
sd 0:0:1:0: [sdb] Sense Key : Aborted Command [current] [descriptor]
Descriptor sense data with sense descriptors (in hex):
72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
00 00 00 f7
sd 0:0:1:0: [sdb] Add. Sense: No additional sense information
sd 0:0:1:0: [sdb] CDB: Read(10): 28 00 6f 4c cc 80 00 04 00 00
end_request: I/O error, dev sdb, sector 1867304064
hrtimer: interrupt took 28024956 ns
ata2: status=0x41 { DriveReady Error }
ata2: error=0x04 { DriveStatusError }
ata2: translatedserver RspCode F688 Ctrl 0 Idx A6F Len 70 ATA stat/err 0x
41/04 to SCSI SK00 00 64 65 35 64 62 65 65 31 3A 32 64 38 35 63 37 30
63 3A 39 64 31 63 33 63 38 39 3A 32 32 64 39 32 65 32 31 00 00 00 00
00 00/ASC/ASCQ 0xb/00 /00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2F 00 00 00 ata2: status=0x4
1 { DriveReady Error }
ata2: error=0x04 { DriveStatusError }
ata2: translated ATA stat/err 0x41/04 to SCSI SK/ASC/ASCQ 0xb/00/00
sd 0:0:1:0: [sdb] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
sd 0:0:1:0: [sdb] Sense Key : Aborted Command [current] [descriptor]
Descriptor sense data with sense descriptors (in hex):
72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
00 00 00 f7
sd 0:0:1:0: [sdb] Add. Sense: No additional sense information
sd 0:0:1:0: [sdb] CDB: Read(10): 28 00 6f 4c a4 80 00 04 00 00
end_request: I/O error, dev sdb, sector 1867293824
ata2: status=0x41 { DriveReady Error }
……
Then, there were lots of error messages about the file system. The
following was the output:
......
INFO: task xfssyncd/md127:1058 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
xfssyncd/md127 D fffffff7000216d0 0 1058 2 0x00000000
frame 0: 0xfffffff700020570 __switch_to+0x1b8/0x1c0 (sp 0xfffffe008d7ff900)
frame 1: 0xfffffff7000216d0 schedule+0x918/0x1538 (sp 0xfffffe008d7ff9d0)
frame 2: 0xfffffff700022a90 schedule_timeout+0x268/0x5b0 (sp
0xfffffe008d7ffd18)
frame 3: 0xfffffff700024ee0 __down+0xd8/0x158 (sp 0xfffffe008d7ffda8)
frame 4: 0xfffffff70085da78 down.cold+0x8/0x28 (sp 0xfffffe008d7ffe18)
frame 5: 0xfffffff700750788 xfs_buf_lock+0xd0/0x120 (sp 0xfffffe008d7ffe38)
frame 6: 0xfffffff700821b40 xfs_getsb+0x38/0x78 (sp 0xfffffe008d7ffe50)
frame 7: 0xfffffff70077e230 xfs_trans_getsb+0xe0/0x100 (sp 0xfffffe008d7ffe68)
frame 8: 0xfffffff7006babc0 xfs_mod_sb+0x88/0x198 (sp 0xfffffe008d7ffe88)
frame 9: 0xfffffff7007a6480 xfs_fs_log_dummy+0x68/0xe0 (sp 0xfffffe008d7ffeb8)
frame 10: 0xfffffff70079c6c0 xfs_sync_worker+0xe0/0xe8 (sp 0xfffffe008d7ffed8)
frame 11: 0xfffffff700570a00 xfssyncd+0x240/0x328 (sp 0xfffffe008d7ffef0)
frame 12: 0xfffffff7000f0530 kthread+0xe0/0xe8 (sp 0xfffffe008d7fff80)
frame 13: 0xfffffff7000bab38 start_kernel_thread+0x18/0x20 (sp
0xfffffe008d7fffe8)
INFO: task xfssyncd/md127:1058 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
xfssyncd/md127 D fffffff7000216d0 0 1058 2 0x00000000
frame 0: 0xfffffff700020570 __switch_to+0x1b8/0x1c0 (sp 0xfffffe008d7ff900)
frame 1: 0xfffffff7000216d0 schedule+0x918/0x1538 (sp 0xfffffe008d7ff9d0)
frame 2: 0xfffffff700022a90 schedule_timeout+0x268/0x5b0 (sp
0xfffffe008d7ffd18)
frame 3: 0xfffffff700024ee0 __down+0xd8/0x158 (sp 0xfffffe008d7ffda8)
frame 4: 0xfffffff70085da78 down.cold+0x8/0x28 (sp 0xfffffe008d7ffe18)
frame 5: 0xfffffff700750788 xfs_buf_lock+0xd0/0x120 (sp 0xfffffe008d7ffe38)
frame 6: 0xfffffff700821b40 xfs_getsb+0x38/0x78 (sp 0xfffffe008d7ffe50)
frame 7: 0xfffffff70077e230 xfs_trans_getsb+0xe0/0x100 (sp 0xfffffe008d7ffe68)
frame 8: 0xfffffff7006babc0 xfs_mod_sb+0x88/0x198 (sp 0xfffffe008d7ffe88)
frame 9: 0xfffffff7007a6480 xfs_fs_log_dummy+0x68/0xe0 (sp 0xfffffe008d7ffeb8)
frame 10: 0xfffffff70079c6c0 xfs_sync_worker+0xe0/0xe8 (sp 0xfffffe008d7ffed8)
frame 11: 0xfffffff700570a00 xfssyncd+0x240/0x328 (sp 0xfffffe008d7ffef0)
frame 12: 0xfffffff7000f0530 kthread+0xe0/0xe8 (sp 0xfffffe008d7fff80)
frame 13: 0xfffffff7000bab38 start_kernel_thread+0x18/0x20 (sp
0xfffffe008d7fffe8)
INFO: task xfssyncd/md127:1058 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
xfssyncd/md127 D fffffff7000216d0 0 1058 2 0x00000000
frame 0: 0xfffffff700020570 __switch_to+0x1b8/0x1c0 (sp 0xfffffe008d7ff900)
frame 1: 0xfffffff7000216d0 schedule+0x918/0x1538 (sp 0xfffffe008d7ff9d0)
frame 2: 0xfffffff700022a90 schedule_timeout+0x268/0x5b0 (sp
0xfffffe008d7ffd18)
frame 3: 0xfffffff700024ee0 __down+0xd8/0x158 (sp 0xfffffe008d7ffda8)
frame 4: 0xfffffff70085da78 down.cold+0x8/0x28 (sp 0xfffffe008d7ffe18)
frame 5: 0xfffffff700750788 xfs_buf_lock+0xd0/0x120 (sp 0xfffffe008d7ffe38)
frame 6: 0xfffffff700821b40 xfs_getsb+0x38/0x78 (sp 0xfffffe008d7ffe50)
frame 7: 0xfffffff70077e230 xfs_trans_getsb+0xe0/0x100 (sp 0xfffffe008d7ffe68)
frame 8: 0xfffffff7006babc0 xfs_mod_sb+0x88/0x198 (sp 0xfffffe008d7ffe88)
frame 9: 0xfffffff7007a6480 xfs_fs_log_dummy+0x68/0xe0 (sp 0xfffffe008d7ffeb8)
frame 10: 0xfffffff70079c6c0 xfs_sync_worker+0xe0/0xe8 (sp 0xfffffe008d7ffed8)
frame 11: 0xfffffff700570a00 xfssyncd+0x240/0x328 (sp 0xfffffe008d7ffef0)
frame 12: 0xfffffff7000f0530 kthread+0xe0/0xe8 (sp 0xfffffe008d7fff80)
......
The output said “INFO: task xfssyncd/md127:1058 blocked for more than
120 seconds”. What did that mean? I used “cat /proc/mdstat” to see the
state of the raid5. The output was:
Personalities : [raid0] [raid6] [raid5] [raid4]
md127 : active raid5 sdd[3] sdc[2] sdb[1](F) sda[0]
5860540032 blocks super 1.2 level 5, 128k chunk, algorithm 2 [4/3] [U_UU]
resync=PENDING
unused devices: <none>
The state of the raid5 was “PENDING”. I had never seen such a
state of raid5 before. After that, I wrote a program to access the
raid5, there was no response any more. Then I used “ps aux| task
xfssyncd” to see the state of “xfssyncd”. Unfortunately, there was no
response yet. Then I tried “ps aux”. There were outputs, but the
program could exit with “Ctrl+d” or “Ctrl+z”. And when I tested the
write performance for raid5, I/O errors often occurred. I did not know
why this I/O errors occurred so frequently.
What was the problem? Can any one help me?
--
To unsubscribe from this list: send the line "unsubscribe linux-raid" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 12+ messages in thread
end of thread, other threads:[~2012-10-30 4:49 UTC | newest]
Thread overview: 12+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
[not found] <CACY-59cbWX9Gu_xsfqv_p8=Q7CabWZuj=ZH2K41j4N0-o-8WLw@mail.gmail.com>
2012-10-24 3:17 ` task xfssyncd blocked while raid5 was in recovery hanguozhong
2012-10-24 5:14 ` NeilBrown
2012-10-30 2:19 ` hanguozhong
2012-10-30 4:49 ` Stan Hoeppner
2012-10-10 3:14 GuoZhong Han
2012-10-10 11:54 ` Stan Hoeppner
2012-10-11 2:42 ` hanguozhong
2012-10-11 3:47 ` Chris Murphy
2012-10-11 11:20 ` Stan Hoeppner
2012-10-11 6:12 ` Mikael Abrahamsson
2012-10-11 11:01 ` Stan Hoeppner
2012-10-11 11:16 ` Mikael Abrahamsson
[not found] ` <201210112054336567511@meganovo.com>
2012-10-11 14:47 ` Stan Hoeppner
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).