Re: ReadyNAS OS V6.9.5 - Discs don't spindown - still

Michael_Oz · ‎2019-02-24

This is turning into a ritual, as for the last few releases I again check whether disc spindown is fixed.

Last was for 6.9.3 here.

My last post there was "So has this been recognised as a bug?" which remains unanswered by Netgear, I think it is obvious.

As per the flow of the previous post, I cut to the chase.

Installed apps, just htop.

Antivirus & search are not enabled.

Volume schedules are disabled.

There is one scheduled backup ATM, runs ~midnight for a few minutes.

So, I set spindown to 5min, added the noflushd -b option and did,

# echo 1 > /proc/sys/vm/block_dump

I then unplugged the ethernet cable to ensure it wasn't being accessed by stray network devices.

Some time later...

From 1811hrs-1850hrs with 6 discs, there were 47 spin downs, 49 sping ups, average 'after' time 7s. So that's ~8 spindown of all discs with 8 spinup almost immediately.

I have the combined spindown and blockdump logs in one time sorted file.

Let me know if you want full logs. Here is representative chunk;

Feb 24 18:16:32 ME-NAS-316A noflushd[19989]: Spinning down disk 1 (/dev/sda).
Feb 24 18:16:33 ME-NAS-316A kernel: md0_raid1(1383): WRITE block 8 on sda1 (1 sectors)
Feb 24 18:16:33 ME-NAS-316A kernel: md0_raid1(1383): WRITE block 8 on sdb1 (1 sectors)
Feb 24 18:16:33 ME-NAS-316A kernel: md0_raid1(1383): WRITE block 8 on sdc1 (1 sectors)
Feb 24 18:16:33 ME-NAS-316A kernel: md0_raid1(1383): WRITE block 8 on sdd1 (1 sectors)
Feb 24 18:16:33 ME-NAS-316A kernel: md0_raid1(1383): WRITE block 8 on sde1 (1 sectors)
Feb 24 18:16:33 ME-NAS-316A kernel: md0_raid1(1383): WRITE block 8 on sdf1 (1 sectors)
Feb 24 18:16:35 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:16:35 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:16:35 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:16:35 ME-NAS-316A kernel: rnutil(21005): dirtied inode 9380 (event.sq3) on md0
Feb 24 18:16:35 ME-NAS-316A noflushd[19989]: Spinning down disk 2 (/dev/sdb).
Feb 24 18:16:42 ME-NAS-316A kernel: kworker/u8:4(20452): WRITE block 4530080 on md0 (8 sectors)
Feb 24 18:16:42 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:16:42 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:16:42 ME-NAS-316A noflushd[19989]: Spinning up disk 1 (/dev/sda) after 0:00:07.
Feb 24 18:16:42 ME-NAS-316A noflushd[19989]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Feb 24 18:16:50 ME-NAS-316A kernel: kworker/u8:0(20760): WRITE block 221312 on md0 (128 sectors)
<9 similar>
Feb 24 18:16:50 ME-NAS-316A kernel: kworker/u8:3(20652): WRITE block 1174904 on md0 (16 sectors)
Feb 24 18:16:50 ME-NAS-316A kernel: kworker/u8:4(20452): dirtied inode 1 (?) on md0
Feb 24 18:16:50 ME-NAS-316A kernel: kworker/u8:4(20452): WRITE block 221152 on md0 (32 sectors)
<79 similar>
Feb 24 18:16:50 ME-NAS-316A kernel: kworker/u8:4(20452): WRITE block 640128 on md0 (96 sectors)
Feb 24 18:16:50 ME-NAS-316A kernel: md0_raid1(1383): WRITE block 8 on sda1 (1 sectors)
Feb 24 18:16:50 ME-NAS-316A kernel: md0_raid1(1383): WRITE block 8 on sdb1 (1 sectors)
Feb 24 18:16:50 ME-NAS-316A kernel: md0_raid1(1383): WRITE block 8 on sdc1 (1 sectors)
Feb 24 18:16:50 ME-NAS-316A kernel: md0_raid1(1383): WRITE block 8 on sdd1 (1 sectors)
Feb 24 18:16:50 ME-NAS-316A kernel: md0_raid1(1383): WRITE block 8 on sde1 (1 sectors)
Feb 24 18:16:50 ME-NAS-316A kernel: md0_raid1(1383): WRITE block 8 on sdf1 (1 sectors)
Feb 24 18:16:50 ME-NAS-316A kernel: noflushd(19989): WRITE block 128 on md0 (8 sectors)
Feb 24 18:16:50 ME-NAS-316A kernel: noflushd(19989): WRITE block 131072 on md0 (8 sectors)
Feb 24 18:16:50 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:16:50 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:16:50 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:16:50 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:16:50 ME-NAS-316A kernel: systemd-journal(1465): dirtied inode 2036622 (system.journal) on md0
Feb 24 18:17:10 ME-NAS-316A kernel: md0_raid1(1383): WRITE block 8 on sda1 (1 sectors)
Feb 24 18:17:10 ME-NAS-316A kernel: md0_raid1(1383): WRITE block 8 on sdb1 (1 sectors)
Feb 24 18:17:10 ME-NAS-316A kernel: md0_raid1(1383): WRITE block 8 on sdc1 (1 sectors)
Feb 24 18:17:10 ME-NAS-316A kernel: md0_raid1(1383): WRITE block 8 on sdd1 (1 sectors)
Feb 24 18:17:10 ME-NAS-316A kernel: md0_raid1(1383): WRITE block 8 on sde1 (1 sectors)
Feb 24 18:17:10 ME-NAS-316A kernel: md0_raid1(1383): WRITE block 8 on sdf1 (1 sectors)
Feb 24 18:17:10 ME-NAS-316A kernel: systemd-journal(1465): dirtied inode 1 (?) on md0
Feb 24 18:17:10 ME-NAS-316A kernel: systemd-journal(1465): dirtied inode 2036622 (system.journal) on md0
Feb 24 18:17:10 ME-NAS-316A noflushd[19989]: Spinning down disk 3 (/dev/sdc).
Feb 24 18:17:13 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:13 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:13 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:13 ME-NAS-316A kernel: rnutil(21028): dirtied inode 9380 (event.sq3) on md0
Feb 24 18:17:13 ME-NAS-316A noflushd[19989]: Spinning down disk 4 (/dev/sdd).
Feb 24 18:17:15 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:15 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:15 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:15 ME-NAS-316A noflushd[19989]: Spinning down disk 5 (/dev/sde).
Feb 24 18:17:17 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:17 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:17 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:17 ME-NAS-316A noflushd[19989]: Spinning down disk 6 (/dev/sdf).
Feb 24 18:17:25 ME-NAS-316A kernel: kworker/u8:4(20452): WRITE block 4530080 on md0 (8 sectors)
Feb 24 18:17:25 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:25 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:25 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:25 ME-NAS-316A noflushd[19989]: Spinning up disk 3 (/dev/sdc) after 0:00:12.
Feb 24 18:17:25 ME-NAS-316A noflushd[19989]: Spinning up disk 4 (/dev/sdd) after 0:00:10.
Feb 24 18:17:25 ME-NAS-316A noflushd[19989]: Spinning up disk 5 (/dev/sde) after 0:00:08.
Feb 24 18:17:25 ME-NAS-316A noflushd[19989]: Spinning up disk 6 (/dev/sdf) after 0:00:05.

I undid the blockdump & -b, set spindown to 45m.

Retired_Member · ‎2019-05-30

Hi @Michael_Oz, any change for good on your side with the freshly released 6.10.1?

Kind regards

StephenB · ‎2019-05-30

@Michael_Oz wrote:

Feb 24 18:16:35 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:16:35 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:16:35 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
...
Feb 24 18:16:42 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:16:42 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
...
Feb 24 18:16:50 ME-NAS-316A kernel: kworker/u8:4(20452): dirtied inode 1 (?) on md0
...
Feb 24 18:16:50 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:16:50 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:16:50 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:16:50 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
...
Feb 24 18:17:10 ME-NAS-316A kernel: systemd-journal(1465): dirtied inode 1 (?) on md0
Feb 24 18:17:10 ME-NAS-316A kernel: systemd-journal(1465): dirtied inode 2036622 (system.journal) on md0
...
Feb 24 18:17:13 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:13 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:13 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:13 ME-NAS-316A kernel: rnutil(21028): dirtied inode 9380 (event.sq3) on md0
...
Feb 24 18:17:15 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:15 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:15 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
...
Feb 24 18:17:17 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:17 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:17 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
...
Feb 24 18:17:25 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:25 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc
Feb 24 18:17:25 ME-NAS-316A kernel: readynasd(3755): dirtied inode 4026532241 (LCD) on proc

I'd be more concerned about these dirtied inode messages than disk spindown.

Though they might be a result of spindown (a consequence of pending writes being cached), I'm not seeing them on my own system (which also has spindown enabled). But it is resyncing at the moment, and it's possible that the log doesn't go back far enough to see them.

Michael_Oz · ‎2019-05-30

@Retired_Member wrote:
Hi @Michael_Oz, any change for good on your side with the freshly released 6.10.1?
Kind regards

I'll need to do a full backup first. That takes a while.

Michael_Oz · ‎2019-05-30

@StephenB wrote:
... I'm not seeing them on my own system (which also has spindown enabled).

Do you have

noflushd -b and

# echo 1 > /proc/sys/vm/block_dump

?

StephenB · ‎2019-05-31

@Michael_Oz wrote:

noflushd -b and
# echo 1 > /proc/sys/vm/block_dump
?

No (though at the moment the system is resyncing, so there's no point in doing those at present).

Michael_Oz · ‎2019-09-03

@Retired_Member wrote:
Hi @Michael_Oz, any change for good on your side with the freshly released 6.10.1?
Kind regards

No 6.10.1 did not fix non-spindown.

After lodging a Chat with formal 'My Support', they did ome poking around and confirmed it not working on their test systems.

Summary of results [my notes]

On their testing [engineers] it seems it never did happen to a Western Digital. However, we hope to enhancements on the future firmware release. Thank you for working with us on this by the way. We are still investigating other potential issue with regard to the feature.
...
Since we already knew about the issue [in earlier testing], will it be fine to close this case for now. Please wait for a future enhancement for the spin down feature of the Readynas. Thank you!

So I'll repeat this whole process with the next release...