Spin down keeps waking up (per logs)

[essd]

Both empty_exim and sleep are pre-fetched into memory just before spinning down, so they should have no reason to read from disk. Maybe it's one of the shared libraries that sleep uses...? This updated addon will prefetch the shared libraries too. Can you try it?

I'm sorry to be the bearer of bad news: I've tried the new version of the add-on, but alas, I'm still seeing random spinups (zero for three). It actually doesn't seem to want to spin down at all for more than a second or three with the new version of the add-on, which is somewhat worse than the previous version of the add-on.

In the first case, it didn't get to fully spin down. I wonder what noflushd was reading that seems to have caused the problem? (See the line immediately before "Spindown of /dev/hdc cancelled.")

Code: Select all

Oct 16 21:13:23 nas kernel: noflushd(835): READ block 3936176 on hdc1
Oct 16 21:13:23 nas kernel: noflushd(835): READ block 3936184 on hdc1
Oct 16 21:13:23 nas kernel: noflushd(835): READ block 3916640 on hdc1
Oct 16 21:13:23 nas kernel: noflushd(835): READ block 3919112 on hdc1
Oct 16 21:13:23 nas kernel: noflushd(835): READ block 778280 on hdc1
Oct 16 21:13:23 nas kernel: noflushd(835): READ block 775936 on hdc1
Oct 16 21:13:23 nas kernel: noflushd(835): READ block 778424 on hdc1
Oct 16 21:13:23 nas kernel: noflushd(835): READ block 778240 on hdc1
Oct 16 21:13:24 nas noflushd[835]: Spinning down /dev/hdc.
Oct 16 21:13:24 nas kernel: noflushd(835): WRITE block 8 on hdc1
Oct 16 21:13:24 nas kernel: noflushd(835): WRITE block 1310736 on hdc1
Oct 16 21:13:24 nas kernel: noflushd(835): WRITE block 1523624 on hdc1
Oct 16 21:13:24 nas kernel: noflushd(835): WRITE block 1523800 on hdc1
Oct 16 21:13:24 nas kernel: noflushd(835): WRITE block 1523888 on hdc1
Oct 16 21:13:24 nas kernel: syslogd(869): dirtied inode 80818 (daemon.log) on hdc1
Oct 16 21:13:24 nas last message repeated 2 times
Oct 16 21:13:24 nas kernel: noflushd(835): READ block 786488 on hdc1
Oct 16 21:13:24 nas noflushd[835]: Spindown of /dev/hdc cancelled.
Oct 16 21:13:29 nas kernel: pdflush(1411): WRITE block 1526376 on hdc1
Oct 16 21:13:29 nas kernel: pdflush(1411): WRITE block 1526416 on hdc1
Oct 16 21:13:29 nas kernel: pdflush(1411): dirtied inode 80806 (debug) on hdc1


Case #2:

Code: Select all

Oct 16 21:18:28 nas kernel: sh(1477): dirtied inode 80841 (?) on hdc1
Oct 16 21:18:28 nas kernel: sh(1477): dirtied inode 80638 (frontview) on hdc1
Oct 16 21:18:28 nas kernel: sh(1477): dirtied inode 80638 (frontview) on hdc1
Oct 16 21:18:28 nas kernel: sh(1480): dirtied inode 80841 (?) on hdc1
Oct 16 21:18:30 nas noflushd[835]: Spinning down /dev/hdc.
Oct 16 21:18:30 nas kernel: syslogd(869): dirtied inode 80818 (daemon.log) on hdc1
Oct 16 21:18:30 nas last message repeated 2 times
Oct 16 21:18:30 nas kernel: noflushd(835): WRITE block 8 on hdc1
Oct 16 21:18:30 nas kernel: noflushd(835): WRITE block 1310736 on hdc1
Oct 16 21:18:30 nas kernel: noflushd(835): WRITE block 1310744 on hdc1
Oct 16 21:18:30 nas kernel: noflushd(835): WRITE block 1310936 on hdc1
Oct 16 21:18:30 nas kernel: noflushd(835): WRITE block 1310952 on hdc1
Oct 16 21:18:30 nas kernel: noflushd(835): WRITE block 1310960 on hdc1
Oct 16 21:18:30 nas kernel: noflushd(835): WRITE block 1523624 on hdc1
Oct 16 21:18:30 nas kernel: noflushd(835): WRITE block 1523800 on hdc1
Oct 16 21:18:32 nas noflushd[835]: Spinning down /dev/hde.
Oct 16 21:18:32 nas kernel: sh(1481): READ block 4031672 on hdc1
Oct 16 21:18:37 nas kernel: noflushd(835): dirtied inode 1484 (spindown) on ramfs
Oct 16 21:18:37 nas kernel: noflushd(835): dirtied inode 4026532439 (set_pwm) on proc
Oct 16 21:18:42 nas noflushd[835]: Spinning up /dev/hdc after 0 minutes.
Oct 16 21:18:42 nas noflushd[835]: Spinning up /dev/hde after 0 minutes.
Oct 16 21:18:42 nas kernel: noflushd(835): dirtied inode 4026532439 (set_pwm) on proc
Oct 16 21:18:47 nas kernel: noflushd(835): dirtied inode 4026532439 (set_pwm) on proc


The third one, which I won't bother to copy and paste, involved sh and mdconfig.

On a side note, is there an easy way to translate a block number into a path or filename? I haven't looked at Linux filesystems implementations in a while, but it seems like that might help.

Yours seems like a strange case though, because with my Duo here, once it spins down, it will stay down for up to a week.

I have noticed some interesting behavior in this regard:

The previous system state seems to have something to do with whether or not it wants to spin down. I have two Macs on the network running 10.5.5. I don't know if there is a 100% correlation, but it seems that if I use either of the Macs to do a time machine backup to the NAS, I experience spindown problems afterward. If the NAS comes up with a fresh boot and I don't try to do any Time Machine backups, it seems like there is less of a problem.

I haven't done any testing to verify that this is a causal relationship or not: I have certainly seen days when the drive is spun down for most of the time, and I've seen days when it goes up and down more often than a toilet seat in a coed dorm. I am also unsure if it's related to Time Machine specifically, or perhaps general AFP access, or even something else (Bonjour and so on).

My previous testing with tcpdump showed that the other systems were not sending any significant traffic to the NAS device after the backups had completed, so I would suspect that this is not a case of the clients provoking the server (for which I'd expect to see afpd involved in the above logs anyway).

In other words, treat this Time Machine as "something I've noticed" that might warrant further investigation if you're trying to reproduce it...although it could still be a red herring.

[Skywalker]

I can't say if it's for sure the cause, but I do know that Time Machine sends commands to the NAS that tell it explicitly to sync all cached data. Of course, when you do that, the disks will certainly spin up.

[essd]

I can't say if it's for sure the cause, but I do know that Time Machine sends commands to the NAS that tell it explicitly to sync all cached data. Of course, when you do that, the disks will certainly spin up.

Even when I was doing Time Machine backups, I would be simply requesting the system to "do a backup now" without using the automatic backup feature. While this would clearly cause the disks to spin up during a backup, I can't imagine why it would cause spinups when /not/ doing a backup.

In any event, I just disproved my own Time Machine theory. I did a restart of the Duo while logging network traffic via tcpdump, as well as captured all of the block_dump data while doing so. It tried to spin down five minutes after bootup, but the drives spun back up right away.

Other than Bonjour advertisements for the AFP service itself, I can confirm there was absolutely no AFP-related traffic over the net between startup and the spindown/spinup problem.

Code: Select all

Oct 17 09:48:41 nas noflushd[814]: Spinning down /dev/hdc.
Oct 17 09:48:41 nas kernel: syslogd(830): dirtied inode 80809 (daemon.log) on hdc1
Oct 17 09:48:41 nas last message repeated 2 times
Oct 17 09:48:41 nas kernel: noflushd(814): WRITE block 0 on hdc1
Oct 17 09:48:41 nas kernel: noflushd(814): WRITE block 8 on hdc1
Oct 17 09:48:41 nas kernel: noflushd(814): WRITE block 1310736 on hdc1
Oct 17 09:48:41 nas kernel: noflushd(814): WRITE block 1310952 on hdc1
Oct 17 09:48:41 nas kernel: noflushd(814): WRITE block 1561448 on hdc1
Oct 17 09:48:41 nas kernel: noflushd(814): WRITE block 1562480 on hdc1
Oct 17 09:48:43 nas noflushd[814]: Spinning down /dev/hde.
Oct 17 09:48:43 nas kernel: noflushd(814): WRITE block 8 on hdc1
Oct 17 09:48:43 nas kernel: noflushd(814): WRITE block 1310736 on hdc1
Oct 17 09:48:43 nas kernel: noflushd(814): WRITE block 1563152 on hdc1
Oct 17 09:48:47 nas kernel: noflushd(814): dirtied inode 1472 (spindown) on ramfs
Oct 17 09:48:47 nas kernel: noflushd(814): dirtied inode 4026532439 (set_pwm) on proc
Oct 17 09:48:52 nas noflushd[814]: Spinning up /dev/hdc after 0 minutes.
Oct 17 09:48:52 nas noflushd[814]: Spinning up /dev/hde after 0 minutes.


Here is the grand sum of all network traffic during that time:

Code: Select all

09:48:25.975793 IP 10.1.1.1 > ALL-SYSTEMS.MCAST.NET: igmp query v2
09:48:26.416914 IP 10.1.1.101 > 224.0.0.251: igmp v2 report 224.0.0.251
09:48:31.459592 arp who-has 10.1.1.101 (Broadcast) tell 10.1.1.1
09:48:35.701238 IP 10.1.1.195 > HP-DEVICE-DISC.MCAST.NET: igmp v2 report HP-DEVICE-DISC.MCAST.NET
09:48:35.734523 IP 10.1.1.195 > 239.255.255.250: igmp v2 report 239.255.255.250
09:48:57.663759 IP 10.1.1.199.58560 > 10.1.1.255.netbios-ns: NBT UDP PACKET(137): QUERY; REQUEST; BROADCAST
09:48:57.934380 IP 10.1.1.199.58560 > 10.1.1.255.netbios-ns: NBT UDP PACKET(137): QUERY; REQUEST; BROADCAST
09:48:58.204756 IP 10.1.1.199.58560 > 10.1.1.255.netbios-ns: NBT UDP PACKET(137): QUERY; REQUEST; BROADCAST
09:48:58.616833 IP 10.1.1.199.58561 > 10.1.1.255.netbios-ns: NBT UDP PACKET(137): QUERY; REQUEST; BROADCAST


[Vatoe]

For what it was worth, the patch didn't improve mine either..

[essd]

For what it was worth, the patch didn't improve mine either..

I've actually reverted to the 10/8 release of the UpdateSpindown-4.1.4 patch. The most recent version (released yesterday) would seemingly never spin down for me, but at least the prior release spins down sometimes.

[Briain]

Hi

I tried the latest patch and it so far has worked a treat; SC7.3 and Twonky 4.4.9 both impacted on hibernation (I had previous versions of each; all OK but the latest versions have been causing chaos). I tried the first hibernation patch but it didn't change anything, the latest one seems to have calmed things right down! I've been too busy to try a longer hibernation but will see how things look tomorrow and report back.

I need to hibernate myself now, I also need a patch. Just have to settle for a quick dram and see if that spins me down

Bri

[Briain]

Both empty_exim and sleep are pre-fetched into memory just before spinning down, so they should have no reason to read from disk. Maybe it's one of the shared libraries that sleep uses...? This updated addon will prefetch the shared libraries too. Can you try it? Yours seems like a strange case though, because with my Duo here, once it spins down, it will stay down for up to a week.

Hi again

Think I've found a pattern. The NAS hibernates perfectly (with the latest Spindown update) but if I do a Twonky rescan, the NAS refuses to hibernate at all. If I reboot it, it hibernates again. I'll try a rescan and see if just restarting Twonky helps solve the problem.

I know a lot of people have noticed that Twonky rescan doesn't always pick up new music; I wonder if this is related and that Twonky is in some sort incomplete rescan state?

Update: I've now proven to myself that adding a track then rescanning prevents hibernation. Rebuilding the database does not cause this problem so it looks to be a rescan related issue. Using the Twonky restart URL (http://NAS.IP.ADDRESS:PORT/rpc/restart/) resets things and permits hibernation to take place.

The NAS still spins up after about 20 minutes; I'll enable SSH and see if I can find out anything useful.

Hope that helps
Bri

NB Enabled logs and NAS hibernated for a few of minutes then spun up at 16:57; only one read activity as shown in red. Not sure frontview activities are al about; Frontview was closed at the time:

Oct 20 16:55:48 BriServ kernel: noflushd(702): dirtied inode 4026532447 (set_pwm) on proc
Oct 20 16:57:06 BriServ kernel: sh(2104): dirtied inode 48929 (?) on hdc1
Oct 20 16:57:06 BriServ kernel: sh(2104): dirtied inode 48638 (frontview) on hdc1
Oct 20 16:57:06 BriServ kernel: sh(2104): dirtied inode 48638 (frontview) on hdc1
Oct 20 16:57:06 BriServ kernel: sh(2107): dirtied inode 48929 (?) on hdc1
Oct 20 16:57:06 BriServ kernel: sh(2109): READ block 3280120 on hdc1
Oct 20 16:57:06 BriServ kernel: sh(2110): dirtied inode 32067 (?) on hdc1
Oct 20 16:57:06 BriServ kernel: sh(2110): dirtied inode 32002 (tmp) on hdc1
Oct 20 16:57:06 BriServ kernel: sh(2110): dirtied inode 32002 (tmp) on hdc1
Oct 20 16:57:16 BriServ kernel: sh(2113): dirtied inode 32067 (?) on hdc1
Oct 20 16:57:16 BriServ kernel: monitor_enclosu(995): dirtied inode 48765 (enclosure.log) on hdc1
Oct 20 16:57:16 BriServ kernel: monitor_enclosu(995): dirtied inode 4026532467 (backlight) on proc
Oct 20 16:57:18 BriServ kernel: noflushd(702): WRITE block 8 on hdc1
Oct 20 16:57:18 BriServ kernel: noflushd(702): WRITE block 524296 on hdc1
Oct 20 16:57:18 BriServ kernel: noflushd(702): WRITE block 524320 on hdc1
Oct 20 16:57:18 BriServ kernel: noflushd(702): WRITE block 786448 on hdc1
Oct 20 16:57:18 BriServ kernel: noflushd(702): WRITE block 786456 on hdc1
Oct 20 16:57:18 BriServ kernel: noflushd(702): WRITE block 786696 on hdc1
Oct 20 16:57:28 BriServ kernel: noflushd(702): dirtied inode 4026532447 (set_pwm) on proc
Oct 20 16:57:34 BriServ kernel: noflushd(702): dirtied inode 4026532447 (set_pwm) on proc
Oct 20 16:57:39 BriServ kernel: pdflush(42): WRITE block 875104 on hdc1
Oct 20 16:57:39 BriServ kernel: pdflush(42): dirtied inode 48806 (syslog) on hdc1
Oct 20 16:57:39 BriServ kernel: pdflush(42): WRITE block 874984 on hdc1

[Vatoe]

For what it was worth, the patch didn't improve mine either..

I've actually reverted to the 10/8 release of the UpdateSpindown-4.1.4 patch. The most recent version (released yesterday) would seemingly never spin down for me, but at least the prior release spins down sometimes.

Any chance sending me a copy of the 10/8 release to raven325i at hotmail dot com? I never actually applied that one.

[Briain]

For what it was worth, the patch didn't improve mine either..

I've actually reverted to the 10/8 release of the UpdateSpindown-4.1.4 patch. The most recent version (released yesterday) would seemingly never spin down for me, but at least the prior release spins down sometimes.

Any chance sending me a copy of the 10/8 release to raven325i at hotmail dot com? I never actually applied that one.

Hi

I noticed your request and have just sent the 10/08 version to you.

Bri

[Vatoe]

Hi

I noticed your request and have just sent the 10/08 version to you.

Bri

Thanks very much Bri, I appreciate it.

[Charlie Brown]

Our customer claiming spin down function of RND4000.
Detailed is below.

Customer using
1. RND2000
FW: 4.1.4
HDD: WD1001FALS

2. RND4000
FW: 4.1.4
HDD: WD1001FALS

The customer using HDD not in our compatibility list.
RND2000 spin down works fine with the HDD but RND4000 didn't work.
So call center engineer suggests him to do "spin down measures add-ons" on forum.

The customer told us after installed above "add-ons" to the RND4000 spin down works but not
stable.

Do you have any idea why RND2000 spin down works fine but RND4000 same HDD?

[chirpa]

The customer told us after installed above "add-ons" to the RND4000 spin down works but not stable.

Can you expand with more details on how it is not stable? Do you mean it spins up often?

[Charlie Brown]

Can you expand with more details on how it is not stable? Do you mean it spins up often?

spins downs is not start even past 5mins (configured time). sometime is ok sometime late.

If this information is not enough. I will conatct the customer again. Please let me know.

[brsinburnsville]

I have a ReadyNAS NV+ and have the similar symptoms. I have 3 Seagate 1TB drives. I upgraded to 4.1.4 and I would see the disks spin down and immediate spin back up shown in the logs. I applied the "addon" listed in this thread and now it does not even attempt to spin down the disks. Does someone have the intermediate "addon" (I think dated Oct 8th) that they can send me to try? I also can supply some logs later if necessary.

Thanks.
Bob

[Vatoe]

I have a ReadyNAS NV+ and have the similar symptoms. I have 3 Seagate 1TB drives. I upgraded to 4.1.4 and I would see the disks spin down and immediate spin back up shown in the logs. I applied the "addon" listed in this thread and now it does not even attempt to spin down the disks. Does someone have the intermediate "addon" (I think dated Oct 8th) that they can send me to try? I also can supply some logs later if necessary.

Thanks.
Bob

The intermediate add-on didn't make that much difference in my view. The spin down problems described here still occur. I think the latest add-on did make it worse though, so you can do what I did - re-install the 4.1.4 firmware which will remove the add-on.