Unexpected Spindown

Heya,

Drive I am using is spinning down for some reason. This is happening a couple of times a week. Only noticing it on Drive 4, as that's where all my music is. Music will stop, the server will show hard drive activity light for around 10 seconds, then resume as normal.

Here's some info from the log:

Jan 28 16:50:24 Media kernel: ata6.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen

Jan 28 16:50:24 Media kernel: ata6.00: failed command: CHECK POWER MODE

Jan 28 16:50:24 Media kernel: ata6.00: cmd e5/00:00:00:00:00/00:00:00:00:00/00 tag 0

Jan 28 16:50:24 Media kernel:          res 40/00:ff:00:00:00/00:00:00:00:00/40 Emask 0x4 (timeout)

Jan 28 16:50:24 Media kernel: ata6.00: status: { DRDY }

Jan 28 16:50:24 Media kernel: ata6: hard resetting link

Jan 28 16:50:25 Media kernel: ata6: SATA link up 3.0 Gbps (SStatus 123 SControl 300)

Jan 28 16:50:25 Media kernel: ata6.00: configured for UDMA/133

Jan 28 16:50:25 Media kernel: ata6: EH complete

Jan 28 16:50:25 Media kernel: mdcmd (2117): spindown 4

Jan 28 16:50:27 Media kernel: mdcmd (2119): spindown 4

Heya,

 

Drive I am using is spinning down for some reason. This is happening a couple of times a week. Only noticing it on Drive 4, as that's where all my music is. Music will stop, the server will show hard drive activity light for around 10 seconds, then resume as normal.

 

Here's some info from the log:

 

Jan 28 16:50:24 Media kernel: ata6.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen

Jan 28 16:50:24 Media kernel: ata6.00: failed command: CHECK POWER MODE

Jan 28 16:50:24 Media kernel: ata6.00: cmd e5/00:00:00:00:00/00:00:00:00:00/00 tag 0

Jan 28 16:50:24 Media kernel:          res 40/00:ff:00:00:00/00:00:00:00:00/40 Emask 0x4 (timeout)

Jan 28 16:50:24 Media kernel: ata6.00: status: { DRDY }

Jan 28 16:50:24 Media kernel: ata6: hard resetting link

Jan 28 16:50:25 Media kernel: ata6: SATA link up 3.0 Gbps (SStatus 123 SControl 300)

Jan 28 16:50:25 Media kernel: ata6.00: configured for UDMA/133

Jan 28 16:50:25 Media kernel: ata6: EH complete

Jan 28 16:50:25 Media kernel: mdcmd (2117): spindown 4

Jan 28 16:50:27 Media kernel: mdcmd (2119): spindown 4

That CHECK POWER MODE command is sent to determine if the disk is spinning or not, in order to determine whether it's temperature should be read.  This is done to prevent reading the temp on a spun-down drive because that typically causes it to spin up(!).

From your description sounds like that command fails once in a while for some reason.  Still have the entire log?

I see! Odd why it would be failing. I can't be 100% sure if it happens with any other drives, but if it happens again I'll be sure to post again.

Here's the syslog. I have shutdown server since this happened, but looks like it happened again at 1:30am.

syslog.txt

Do you have spin down enabled?  If so what is the time out?

Default spin down is 30 minutes. I disabled spin down groups to see if that effected anything, still have the same issue. It's very intermittent.

In looking at the code, if CHECK POWER MODE fails, this in itself should not cause a spin down.

In looking at your system log I see:

Jan 29 01:42:45 Media shfs: shfs_rmdir: rmdir: /mnt/disk4/Music/Movies (39) Directory not empty

Jan 29 02:12:52 Media kernel: mdcmd (1791): spindown 0

The time difference between the two is 30 min and 7 sec, and the spindown polling thread runs every 10 sec, so if there were no I/O to disk4 between those two message times then it's correct that the drive is spinning down if you have the spindown delay set to 30 min, right?

With this log, you'd be correct.

Unfortunately it's still spinning down and back up again, even though there's been constant access. I tend to leave iTunes running, so all of my music library is situated on Disk 4. This issue pauses currently playing music for around 20 seconds.

Is it possible that music is getting repeated and accessing previously cached copies of the files and hence no disk access?

Potentially, I'm not actually sure how music iTunes will cache? This has only really started happening within the last 3 months. I've been installing latest versions of unRAID as they come out, so hard to tell exactly when it started happening.

I just find it strange that unRAID will spin the drive down, then immediately spin it back up again. As iTunes sometimes drops its current song when it does this, this seems to me that it may be polling the share often. If it's doing that, then it shouldn't be spinning down at all? Curious.

I concur with Speeding Ant, I believe I've seen this behaviour too. I thought it was just me, until I saw this thread. I see it when copying to the array or running movies from it, for some reason a drive will be issued a shutdown request whilst it is in use.

I wondered if this was anything to do with spin-up groups, trying to shutdown disks on one controller port or something similar even though they are in use?

It is hard to identify from syslogs without having timings for "I did this action" and then x minutes later the disk was spundown. It seems to happen most often during long file copy operations. I usually notice it bacause network utilizations drops off to @1% then recovers as the drive spins back up.   

I've just moved to 4.6 release and am not sure I've seen it in the last few days, I'll try and keep an eye on it and reportback with a syslog and a reproducible scenario.

From the log snippet below (0x6 frozen) I'd say that was caused by a bad sata connection or sata power cable.

I think bad SATA cable might be a potential cause. I did take the server apart within the last week, double check connections and label everything. However, the issue occurred just as frequently before I did this. I'll have to double check it within the next couple of days.

It looks like it isn't the spindown groups, as I've disabled them completely to see if it made a difference.

Next time you see this happen, if you know about when it happened, please capture the system log and see if there actually is a 'mdcmd spindown' command in there at that time.

Something else to consider is that you can program drive's own internal spin-down timer, and in more recent drives, there are various advanced power saving modes.  Take a look at the hdparm command.  Perhaps there are power saving conditions where the drive decides to spin down on it's own.

What I meant before by caching is that suppose you have a set of songs that have been playing and you have enough RAM that they all end up there, and later the player client requests another music file and it turns out it's in RAM and thus no disk I/O takes place.  If this happens for long enough to exceed your spin-down delay, well the drive is going to spin down.

Just as an aside, is that a Seagate drive? I see those hard resetting link faults on my Seagate drives fairly regularily.

Peer

It is indeed a Seagate. The only drive that isn't is my parity. It happened again a couple of times today, seems to be getting more frequent. This time it was with iTunes idle, with Plex playing a video file off that hard drive that it had never seen before. Unlikely to be cached, and it spun down and back up again in the middle of the 45 minute show.

Here's the snippet from log:

Jan 30 17:44:40 Media shfs: shfs_rmdir: rmdir: /mnt/disk4/Music/Smashing Pumpkins/Zeitgeist (39) Directory not empty

Jan 30 17:48:27 Media last message repeated 3 times

Jan 30 17:50:01 Media last message repeated 2 times

Jan 30 17:50:05 Media last message repeated 2 times

Jan 30 18:03:39 Media kernel: mdcmd (207): spindown 2

Jan 30 18:03:59 Media kernel: mdcmd (210): spindown 1

Jan 30 18:03:59 Media kernel: mdcmd (211): spindown 3

Jan 30 18:08:29 Media kernel: ata6.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen

Jan 30 18:08:29 Media kernel: ata6.00: failed command: CHECK POWER MODE

Jan 30 18:08:29 Media kernel: ata6.00: cmd e5/00:00:00:00:00/00:00:00:00:00/00 tag 0

Jan 30 18:08:29 Media kernel:          res 40/00:ff:00:00:00/00:00:00:00:00/40 Emask 0x4 (timeout)

Jan 30 18:08:29 Media kernel: ata6.00: status: { DRDY }

Jan 30 18:08:29 Media kernel: ata6: hard resetting link

Jan 30 18:08:30 Media kernel: ata6: SATA link up 3.0 Gbps (SStatus 123 SControl 300)

Jan 30 18:08:30 Media kernel: ata6.00: configured for UDMA/133

Jan 30 18:08:30 Media kernel: ata6: EH complete

Jan 30 18:20:11 Media kernel: mdcmd (306): spindown 0

Jan 30 18:47:34 Media kernel: ata6.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen

Jan 30 18:47:34 Media kernel: ata6.00: failed command: CHECK POWER MODE

Jan 30 18:47:34 Media kernel: ata6.00: cmd e5/00:00:00:00:00/00:00:00:00:00/00 tag 0

Jan 30 18:47:34 Media kernel:          res 40/00:ff:00:00:00/00:00:00:00:00/40 Emask 0x4 (timeout)

Jan 30 18:47:34 Media kernel: ata6.00: status: { DRDY }

Jan 30 18:47:34 Media kernel: ata6: hard resetting link

Jan 30 18:47:35 Media kernel: ata6: SATA link up 3.0 Gbps (SStatus 123 SControl 300)

Jan 30 18:47:35 Media kernel: ata6.00: configured for UDMA/133

Jan 30 18:47:35 Media kernel: ata6: EH complete

Jan 30 19:01:15 Media shfs: duplicate object: /mnt/disk4/Storage/.DS_Store

Jan 30 19:01:55 Media last message repeated 30 times

Jan 30 19:23:31 Media last message repeated 10 times

Jan 30 19:24:46 Media shfs: duplicate object: /mnt/disk4/Storage/.DS_Store

Jan 30 19:24:46 Media last message repeated 6 times

Jan 30 19:32:08 Media kernel: mdcmd (735): spindown 2

Jan 30 19:52:50 Media kernel: mdcmd (860): spindown 1

Jan 30 19:52:50 Media kernel: mdcmd (861): spindown 3

Jan 30 19:53:20 Media kernel: mdcmd (865): spindown 0

Jan 30 20:00:42 Media kernel: ata6.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen

Jan 30 20:00:42 Media kernel: ata6.00: failed command: CHECK POWER MODE

Jan 30 20:00:42 Media kernel: ata6.00: cmd e5/00:00:00:00:00/00:00:00:00:00/00 tag 0

Jan 30 20:00:42 Media kernel:          res 40/00:ff:00:00:00/00:00:00:00:00/40 Emask 0x4 (timeout)

Jan 30 20:00:42 Media kernel: ata6.00: status: { DRDY }

Jan 30 20:00:42 Media kernel: ata6: hard resetting link

Jan 30 20:00:43 Media kernel: ata6: SATA link up 3.0 Gbps (SStatus 123 SControl 300)

Jan 30 20:00:43 Media kernel: ata6.00: configured for UDMA/133

Jan 30 20:00:43 Media kernel: ata6: EH complete

Jan 30 20:19:18 Media ntpd[1422]: time reset -0.439854 s

Jan 30 20:23:00 Media ntpd[1422]: synchronized to 17.82.253.7, stratum 2

Jan 30 20:31:35 Media shfs: duplicate object: /mnt/disk4/Storage/.DS_Store

Jan 30 20:32:43 Media last message repeated 17 times

Jan 30 20:49:33 Media last message repeated 4 times

If possible shorten and/or replace the sata cables. Both Seagate and WD green drives behave in a similar fashion when in my external HDD case with effectively very long SATA cables. 

You can check advanced power management with

hdparm -I /dev/sdx

Record what it is set to (important as default values are not always easy to come by)

Disable it with

hdparm -B 255 /dev/sdx

My two Seagate drives ship with 192 as this value, my Samsungs are set to disabled 255.