I am running 4.5 and today I noticed that my system was running a parity check, but very slowly. I tried generating a syslog, but when before it seemed that it was easily readable, nicely arranged, this one is one big mess. Can someone please help with why the system is so slow and what's wrong with syslog. Any way to break down the syslog in a more manageable / readable format?

 

I recently added device 8, but otherwise have not done any upgrade/changes to the server. I do not remember of any power outages and the server is on a separate UPS. Today I manually rebooted it.

 

Please help...

syslog-2010-02-26.txt

I am running 4.5 and today I noticed that my system was running a parity check, but very slowly. I tried generating a syslog, but when before it seemed that it was easily readable, nicely arranged, this one is one big mess. Can someone please help with why the system is so slow and what's wrong with syslog. Any way to break down the syslog in a more manageable / readable format?

 

I recently added device 8, but otherwise have not done any upgrade/changes to the server. I do not remember of any power outages and the server is on a separate UPS. Today I manually rebooted it.

 

Please help...

The syslog you posted is perfectly readable.  Not sure what you are referring to about it.

 

other than that, both /dev/hda and /dev/hdb have had DMA mode disabled.  They are in PIO mode which is very slow.

Did you use a old 40 pin IDE cable?  Or a round IDE cable?    I'd start with replacing the cable. 

You are getting a lot of CRC errors communicating with those drives

Feb 26 21:38:38 Tower kernel: ide1 at 0xcd00-0xcd07,0xcc02 on irq 18

Feb 26 21:38:38 Tower kernel: ata7.00: exception Emask 0x10 SAct 0x1 SErr 0x780100 action 0x6

Feb 26 21:38:38 Tower kernel: ata7.00: irq_stat 0x08000000

Feb 26 21:38:38 Tower kernel: ata7: SError: { UnrecovData 10B8B Dispar BadCRC Handshk }

Feb 26 21:38:38 Tower kernel: ata7.00: cmd 60/00:00:60:00:00/02:00:00:00:00/40 tag 0 ncq 262144 in

Feb 26 21:38:38 Tower kernel:          res 50/00:00:60:00:00/00:02:00:00:00/40 Emask 0x10 (ATA bus error)

Feb 26 21:38:38 Tower kernel: ata7.00: status: { DRDY }

Feb 26 21:38:38 Tower kernel: ata7: hard resetting link

Feb 26 21:38:38 Tower kernel: ata7: SATA link up 3.0 Gbps (SStatus 123 SControl 300)

Feb 26 21:38:38 Tower kernel: ata7.00: configured for UDMA/133

Feb 26 21:38:38 Tower kernel: ata7: EH complete

Feb 26 21:38:38 Tower kernel: ata7.00: exception Emask 0x10 SAct 0x1 SErr 0x780100 action 0x6

Feb 26 21:38:38 Tower kernel: ata7.00: irq_stat 0x08000000

Feb 26 21:38:38 Tower kernel: ata7: SError: { UnrecovData 10B8B Dispar BadCRC Handshk }

Feb 26 21:38:38 Tower kernel: ata7.00: cmd 60/00:00:60:00:00/02:00:00:00:00/40 tag 0 ncq 262144 in

Feb 26 21:38:38 Tower kernel:          res 50/00:00:60:00:00/00:02:00:00:00/40 Emask 0x10 (ATA bus error)

Feb 26 21:38:38 Tower kernel: ata7.00: status: { DRDY }

Feb 26 21:38:38 Tower kernel: ata7: hard resetting link

Feb 26 21:38:38 Tower kernel: ata7: SATA link up 3.0 Gbps (SStatus 123 SControl 300)

Feb 26 21:38:38 Tower kernel: ata7.00: configured for UDMA/133

Feb 26 21:38:38 Tower kernel: ata7: EH complete

Feb 26 21:38:38 Tower kernel: ata7.00: exception Emask 0x10 SAct 0x1 SErr 0x780100 action 0x6

Feb 26 21:38:38 Tower kernel: ata7.00: irq_stat 0x08000000

Feb 26 21:38:38 Tower kernel: ata7: SError: { UnrecovData 10B8B Dispar BadCRC Handshk }

Feb 26 21:38:38 Tower kernel: ata7.00: cmd 60/00:00:60:00:00/02:00:00:00:00/40 tag 0 ncq 262144 in

Feb 26 21:38:38 Tower kernel:          res 50/00:00:60:00:00/00:02:00:00:00/40 Emask 0x10 (ATA bus error)

Feb 26 21:38:38 Tower kernel: ata7.00: status: { DRDY }

Feb 26 21:38:38 Tower kernel: ata7: hard resetting link

 

Eventually both drives report lots of errors

Feb 26 21:39:41 Tower kernel: ata7: illegal qc_active transition (00000001->ffffffff)

Feb 26 21:39:41 Tower kernel: ata7.00: exception Emask 0x2 SAct 0x0 SErr 0x0 action 0x6 frozen

Feb 26 21:39:41 Tower kernel: ata7.00: cmd 25/00:e0:df:7a:2d/00:02:00:00:00/e0 tag 0 dma 376832 in

Feb 26 21:39:41 Tower kernel:          res 50/00:00:be:7d:2d/00:00:00:00:00/e0 Emask 0x2 (HSM violation)

Feb 26 21:39:41 Tower kernel: ata7.00: status: { DRDY }

Feb 26 21:39:41 Tower kernel: ata7: hard resetting link

Feb 26 21:39:41 Tower kernel: ata7: SATA link up 1.5 Gbps (SStatus 113 SControl 310)

Feb 26 21:39:41 Tower kernel: ata7.00: configured for UDMA/133

Feb 26 21:39:41 Tower kernel: ata7: EH complete

Feb 26 21:40:10 Tower kernel: ata7: illegal qc_active transition (00000001->ffffffff)

Feb 26 21:40:10 Tower kernel: ata7.00: exception Emask 0x2 SAct 0x0 SErr 0x0 action 0x6 frozen

Feb 26 21:40:10 Tower kernel: ata7.00: cmd 25/00:00:df:c7:42/00:03:00:00:00/e0 tag 0 dma 393216 in

Feb 26 21:40:10 Tower kernel:          res 50/00:00:de:ca:42/00:00:00:00:00/e0 Emask 0x2 (HSM violation)

Feb 26 21:40:10 Tower kernel: ata7.00: status: { DRDY }

Feb 26 21:40:10 Tower kernel: ata7: hard resetting link

Feb 26 21:40:10 Tower kernel: ata7: SATA link up 1.5 Gbps (SStatus 113 SControl 310)

Feb 26 21:40:10 Tower kernel: ata7.00: configured for UDMA/133

Feb 26 21:40:10 Tower kernel: ata7: EH complete

Feb 26 21:40:21 Tower kernel: hdb: ide_dma_intr: bad DMA status (0xff)

Feb 26 21:40:21 Tower kernel: hdb: dma_intr: status=0x50 { DriveReady SeekComplete }

Feb 26 21:40:21 Tower kernel: hdb: possibly failed opcode: 0x25

Feb 26 21:40:50 Tower kernel: ata8: illegal qc_active transition (00000001->ffffffff)

Feb 26 21:40:50 Tower kernel: ata8.00: exception Emask 0x2 SAct 0x0 SErr 0x0 action 0x6 frozen

Feb 26 21:40:50 Tower kernel: ata8.00: cmd ca/00:08:97:ee:34/00:00:00:00:00/e0 tag 0 dma 4096 out

Feb 26 21:40:50 Tower kernel:          res 50/00:00:9e:ee:34/00:00:00:00:00/e0 Emask 0x2 (HSM violation)

Feb 26 21:40:50 Tower kernel: ata8.00: status: { DRDY }

Feb 26 21:40:50 Tower kernel: ata8: hard resetting link

Feb 26 21:40:51 Tower kernel: ata8: SATA link up 1.5 Gbps (SStatus 113 SControl 300)

Feb 26 21:40:51 Tower kernel: ata8.00: configured for UDMA/133

Feb 26 21:40:51 Tower kernel: ata8: EH complete

Feb 26 21:41:22 Tower kernel: hda: ide_dma_intr: bad DMA status (0xff)

Feb 26 21:41:22 Tower kernel: hda: dma_intr: status=0x50 { DriveReady SeekComplete }

Feb 26 21:41:22 Tower kernel: hda: possibly failed opcode: 0x25

Feb 26 21:41:30 Tower kernel: hda: dma_intr: status=0xff { Busy }

Feb 26 21:41:30 Tower kernel: hda: possibly failed opcode: 0x25

Feb 26 21:41:30 Tower kernel: hda: DMA disabled

Feb 26 21:41:30 Tower kernel: hdb: DMA disabled

Feb 26 21:41:30 Tower kernel: ide0: reset: success

Feb 26 21:42:03 Tower kernel: hda: lost interrupt

Feb 26 21:42:04 Tower kernel: hda: task_pio_intr: status=0x58 { DriveReady SeekComplete DataRequest }

Feb 26 21:42:04 Tower kernel: hda: possibly failed opcode: 0x29

Feb 26 21:42:05 Tower kernel: mdcmd (49): spindown 5

Feb 26 21:42:07 Tower kernel: mdcmd (50): spindown 6

Feb 26 21:42:09 Tower kernel: mdcmd (51): spindown 7

Feb 26 21:42:09 Tower kernel: mdcmd (52): spindown 8

Feb 26 21:42:45 Tower kernel: hdb: lost interrupt

Feb 26 21:42:45 Tower kernel: hdb: task_pio_intr: status=0x58 { DriveReady SeekComplete DataRequest }

Feb 26 21:42:45 Tower kernel: hdb: possibly failed opcode: 0x29

Feb 26 21:43:25 Tower kernel: hda: lost interrupt

Feb 26 21:43:25 Tower kernel: hda: task_pio_intr: status=0x58 { DriveReady SeekComplete DataRequest }

Feb 26 21:43:25 Tower kernel: hda: possibly failed opcode: 0x29

Feb 26 21:44:02 Tower kernel: hda: lost interrupt

Feb 26 21:44:03 Tower kernel: hda: task_pio_intr: status=0x58 { DriveReady SeekComplete DataRequest }

Feb 26 21:44:03 Tower kernel: hda: possibly failed opcode: 0x29

Feb 26 21:44:41 Tower kernel: hdb: lost interrupt

Feb 26 21:44:41 Tower kernel: hdb: task_pio_intr: status=0x58 { DriveReady SeekComplete DataRequest }

Feb 26 21:44:41 Tower kernel: hdb: possibly failed opcode: 0x29

Feb 26 21:45:13 Tower kernel: hdb: lost interrupt

Feb 26 21:45:13 Tower kernel: hdb: task_pio_intr: status=0x58 { DriveReady SeekComplete DataRequest }

Feb 26 21:45:13 Tower kernel: hdb: possibly failed opcode: 0x29

Feb 26 21:45:54 Tower kernel: hda: lost interrupt

Feb 26 21:45:54 Tower kernel: hda: task_pio_intr: status=0x58 { DriveReady SeekComplete DataRequest }

Feb 26 21:45:54 Tower kernel: hda: possibly failed opcode: 0x29

Feb 26 21:46:31 Tower kernel: hda: lost interrupt

Feb 26 21:46:32 Tower kernel: hda: task_pio_intr: status=0x58 { DriveReady SeekComplete DataRequest }

Feb 26 21:46:32 Tower kernel: hda: possibly failed opcode: 0x29

Feb 26 21:47:25 Tower kernel: hda: lost interrupt

Feb 26 21:47:25 Tower kernel: hda: task_pio_intr: status=0x58 { DriveReady SeekComplete DataRequest }

Feb 26 21:47:25 Tower kernel: hda: possibly failed opcode: 0x29

 

It could be the cable, or one of the drives interfering with the other on the same cable.

 

Joe L.

Joe,

 

Thanks for the super fast reply. Other than adding a new SATA drive, I have not opened the case in months. I am using round cables, but have been for a year or more. I can replace them with the regular ribbon cables. Is there anything I should do regarding the DMA mode? I have not changed anything in the BIOS.

Round IDE cables do not meet specifications for high speed data transfer.  Never did.  Might work at low speed, or where only one disk is accessed at a time, but they have no place in an unRAID server.  Replace them with high quality 80 conductor flat cables.

The PIO mode will go away when you reboot and it tries DMA mode once more.

 

As far as the server working for months UNTIL YOU CHANGED IT RECENTLY.  Well... you added a disk, which might induce more noise on the power supply than previously.  Or, you moved a cable to where it now picks up more noise. 

Joe,

 

I just checked and I did in fact had regular IDE (not round) cable installed between the two IDE drives. I changed the cable just to make sure, and attached a new syslog.

 

Thanks,

 

Lev

syslog-2010-02-26_v2.txt

That helped with the errors on the IDE drives. 

 

The other errors are one of your SATA disks that is unable to communicate at the higher SATA-2 speed, so it is being throttled down to 1.5Gb/s.  It could be a bad cable, or a loose cable, or perhaps a jumper setting on the drive itself limiting its speed.

 

eb 26 23:11:16 Tower kernel: ata7.00: ATA-8: Hitachi HDT721010SLA360, ST6OA31B, max UDMA/133

Feb 26 23:11:16 Tower kernel: ata7.00: 1953525168 sectors, multi 0: LBA48 NCQ (depth 31/32)

Feb 26 23:11:16 Tower kernel: ata7.00: configured for UDMA/133

Feb 26 23:11:16 Tower kernel: ata7.00: exception Emask 0x10 SAct 0x3 SErr 0x780100 action 0x6

Feb 26 23:11:16 Tower kernel: ata7.00: irq_stat 0x08000000

Feb 26 23:11:16 Tower kernel: ata7: SError: { UnrecovData 10B8B Dispar BadCRC Handshk }

Feb 26 23:11:16 Tower kernel: ata7.00: cmd 60/40:00:20:00:00/00:00:00:00:00/40 tag 0 ncq 32768 in

Feb 26 23:11:16 Tower kernel:          res 50/00:08:a8:6d:70/00:00:74:00:00/40 Emask 0x10 (ATA bus error)

Feb 26 23:11:16 Tower kernel: ata7.00: status: { DRDY }

Feb 26 23:11:16 Tower kernel: ata7.00: cmd 60/08:08:a8:6d:70/00:00:74:00:00/40 tag 1 ncq 4096 in

Feb 26 23:11:16 Tower kernel:          res 50/00:08:a8:6d:70/00:00:74:00:00/40 Emask 0x10 (ATA bus error)

Feb 26 23:11:16 Tower kernel: ata7.00: status: { DRDY }

Feb 26 23:11:16 Tower kernel: ata7: hard resetting link

Feb 26 23:11:16 Tower kernel: ata7: SATA link up 3.0 Gbps (SStatus 123 SControl 300)

Feb 26 23:11:16 Tower kernel: ata7.00: configured for UDMA/133

Feb 26 23:11:16 Tower kernel: ata7: EH complete

Feb 26 23:11:16 Tower kernel: ata7.00: exception Emask 0x10 SAct 0x1 SErr 0x780100 action 0x6

Feb 26 23:11:16 Tower kernel: ata7.00: irq_stat 0x08000000

Feb 26 23:11:16 Tower kernel: ata7: SError: { UnrecovData 10B8B Dispar BadCRC Handshk }

Feb 26 23:11:16 Tower kernel: ata7.00: cmd 60/00:00:60:00:00/02:00:00:00:00/40 tag 0 ncq 262144 in

Feb 26 23:11:16 Tower kernel:          res 50/00:00:60:00:00/00:02:00:00:00/40 Emask 0x10 (ATA bus error)

Feb 26 23:11:16 Tower kernel: ata7.00: status: { DRDY }

Feb 26 23:11:16 Tower kernel: ata7: hard resetting link

Feb 26 23:11:16 Tower kernel: ata7: SATA link up 3.0 Gbps (SStatus 123 SControl 300)

Feb 26 23:11:16 Tower kernel: ata7.00: configured for UDMA/133

Feb 26 23:11:16 Tower kernel: ata7: EH complete

Feb 26 23:11:16 Tower kernel: ata7.00: exception Emask 0x10 SAct 0x1 SErr 0x780100 action 0x6

Feb 26 23:11:16 Tower kernel: ata7.00: irq_stat 0x08000000

Feb 26 23:11:16 Tower kernel: ata7: SError: { UnrecovData 10B8B Dispar BadCRC Handshk }

Feb 26 23:11:16 Tower kernel: ata7.00: cmd 60/00:00:60:00:00/02:00:00:00:00/40 tag 0 ncq 262144 in

Feb 26 23:11:16 Tower kernel:          res 50/00:00:60:00:00/00:02:00:00:00/40 Emask 0x10 (ATA bus error)

Feb 26 23:11:16 Tower kernel: ata7.00: status: { DRDY }

Feb 26 23:11:16 Tower kernel: ata7: hard resetting link

Feb 26 23:11:16 Tower kernel: ata7: SATA link up 3.0 Gbps (SStatus 123 SControl 300)

Feb 26 23:11:16 Tower kernel: ata7.00: configured for UDMA/133

Feb 26 23:11:16 Tower kernel: ata7: EH complete

Feb 26 23:11:16 Tower kernel: ata7: limiting SATA link speed to 1.5 Gbps

Feb 26 23:11:16 Tower kernel: ata7.00: exception Emask 0x10 SAct 0x1 SErr 0x780100 action 0x6

Feb 26 23:11:16 Tower kernel: ata7.00: irq_stat 0x08000000

Feb 26 23:11:16 Tower kernel: ata7: SError: { UnrecovData 10B8B Dispar BadCRC Handshk }

Feb 26 23:11:16 Tower kernel: ata7.00: cmd 60/00:00:60:00:00/02:00:00:00:00/40 tag 0 ncq 262144 in

Feb 26 23:11:16 Tower kernel:          res 50/00:00:60:00:00/00:02:00:00:00/40 Emask 0x10 (ATA bus error)

Feb 26 23:11:16 Tower kernel: ata7.00: status: { DRDY }

Feb 26 23:11:16 Tower kernel: ata7: hard resetting link

OK. That is the new drive that I added. I will change the cable and report...

 

Thanks, Joe!

 

 

OK. Here is the new syslog. I am not too optimistic as the cable seemed to be seated well.

 

Lev

 

PS. If that new drive is the culprit, I can take it out of the array. I do not have anything on it that cannot be easily replaced. I am referring to the ATA-8: Hitachi HDT721010SLA360, ST6OA31B, max UDMA/133

 

syslog-2010-02-26_v3.txt

OK. Here is the new syslog. I am not too optimistic as the cable seemed to be seated well.

 

Lev

 

PS. If that new drive is the culprit, I can take it out of the array. I do not have anything on it that cannot be easily replaced. I am referring to the ATA-8: Hitachi HDT721010SLA360, ST6OA31B, max UDMA/133

 

 

I don't see any more errors showing the drive dropping to 1.5Gb/s.  The syslog now looks clean for the new drive.

Joe,

 

I let the system run parity check over night, and it is DREADFULLY slow. It is running at 91 KB/sec! It is only 0.4% complete, and it has been running for over 8 hours.

 

I see the two IDE drives are operating on PIO mode, not DMA.

That would be the reason for the slow performance.

 

Have you put a new 80 conductor cable into place on those two drives?  Whatever you have use is not able to handle DMA access.

 

Feb 26 23:49:01 Tower kernel: Probing IDE interface ide0...

Feb 26 23:49:01 Tower kernel: hda: ST3500630A, ATA DISK drive

Feb 26 23:49:01 Tower kernel: hdb: ST3750640A, ATA DISK drive

Feb 26 23:49:01 Tower kernel: hda: host max PIO5 wanted PIO255(auto-tune) selected PIO4

Feb 26 23:49:01 Tower kernel: hda: UDMA/100 mode selected

Feb 26 23:49:01 Tower kernel: hdb: host max PIO5 wanted PIO255(auto-tune) selected PIO4

Feb 26 23:49:01 Tower kernel: hdb: UDMA/100 mode selected

Feb 26 23:49:01 Tower kernel: Probing IDE interface ide1...

Feb 26 23:49:01 Tower kernel: ide0 at 0xcf00-0xcf07,0xce02 on irq 18

Feb 26 23:49:01 Tower kernel: ide1 at 0xcd00-0xcd07,0xcc02 on irq 18

Feb 26 23:49:01 Tower kernel: ide-gd driver 1.18

Feb 26 23:49:01 Tower kernel: hda: max request size: 512KiB

Feb 26 23:49:01 Tower kernel: hda: 976773168 sectors (500107 MB) w/16384KiB Cache, CHS=60801/255/63

Feb 26 23:49:01 Tower kernel: hda: cache flushes supported

Feb 26 23:49:01 Tower kernel:  hda: hda1

Feb 26 23:49:01 Tower kernel: hdb: max request size: 512KiB

Feb 26 23:49:01 Tower kernel: hdb: 1465149168 sectors (750156 MB) w/16384KiB Cache, CHS=65535/255/63

Feb 26 23:49:01 Tower kernel: hdb: cache flushes supported

Feb 26 23:49:01 Tower kernel:  hdb: hdb1

Joe,

 

Yes. A new cable is on. Can I try to isolate it to the drive, and then maybe take that one drive out of the array?

 

That would be what I would try.

 

You can just un-assign one drive at a time.

Joe,

Should I unassign a drive and then run pariy check? What set of steps should I follow to isolate the problem without loosing the data? 

Joe,

Should I unassign a drive and then run pariy check? What set of steps should I follow to isolate the problem without loosing the data? 

You can't run a parity check with an un-assigned drive.  Don't thin the array will let you since an un-assigned drive iis the same as a failed drive as far as it is concerned.

Then, how will I know when I disconnect a bad drive? Should I unasign it, then reboot the system and repost syslog? Will that show the failed drive as out of the system? Any idea which drive I should start with?

Then, how will I know when I disconnect a bad drive? Should I unasign it, then reboot the system and repost syslog? Will that show the failed drive as out of the system? Any idea which drive I should start with?

If the drive is electrically affecting its mate, un-assigning it will have no effect.

 

I know I asked this once before... but...

 

Is the IDE cable you used an 80 conductor flat cable?   

(some cables look almost identical and have only 40 conductors and are only good for slower devices)

 

Does it have BLACK, GREY, and BLUE connectors on the ends?  If so, which color did you connect where?

 

Joe L.

Joe,

It is the higher density IDE cable, with the blue connector on the mobo side. The last drive connector is black. The next to last is grey.

 

I am thinking of maybe removing the "new" last SATA drive out of the array, as it was the last action before the problems began. Then, I'll see if everything is OK... One step at a time. I deleted everything off that drive, unassigned it, and removed it. However, now the disk shows up as "not installed", and there is no other option for me to validate the array that I did in fact want to remove the drive out of the array.

Joe,

I am not infront of the pc at the moment, but I am sure that is the higher density IDE cable, with the blue connector on the mobo side and I think black on the drives. I'll check to make sure in a few minutes, when I get home.

 

OK. The last connector to the drive is black. the next to last is grey.

Just wanted to make sure.  Older 40-pin cables did not have the three different color connectors.

Maybe foolish of me, but I removed the SATA drive out of the system and then reinstalled it. Now the data rebuild is running much faster than the parity check was. I attached syslog.

syslog-2010-02-27_v1.txt

Just as an update. I have removed the newest SATA 1TB drive out of the array, and have ran a parity-check after running parity-rebuild, finding 0 errors. I've attached the syslog. Is there anything in it that I need to address prior to adding back the 1TB drive? I am a little weary of adding it in as the last time the errors were introduced roughly the same time that the drive was added. By the way, I also upgraded to 4.5.1.

 

Thanks,

 

Lev

syslog-2010-03-01_v1.txt