Re: Readynas OS 6.6 drives wont spindown

hawke84 · ‎2016-10-09

Hi, I recently upgraded to OS6.6 on my RN104, never had a problem with disk spindown before but soon as I have upgraded the disks dont really spindown anymore, they spindown for about 10 seconds then spinup again. I only had one app installed which was plex but I have disabelled that but its not fixed it. any suggestions would be great but im suspecting that this is a bug with OS6.6

Oct 08 12:46:24 Readynas noflushd[2161]: Enabling spindown for disk 3 [sda,0:2:ST2000DL003-9VT166:5YD3KGQ0:CC32:5900]
Oct 08 12:46:24 Readynas noflushd[2161]: Enabling spindown for disk 2 [sdb,0:1:WDC_WD10EFRX-68PJCN0:WD-WCC4J6AX24A6:82.00A82:5400]
Oct 08 13:00:13 Readynas noflushd[2161]: Error: Readahead /etc/resolv.conf failed.
Oct 08 13:00:13 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 08 13:00:15 Readynas noflushd[2161]: Spindown of disk 3 (/dev/sda) cancelled.
Oct 08 13:14:07 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 08 13:14:20 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:10.
Oct 08 13:19:21 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 08 13:19:34 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:10.
Oct 08 13:22:15 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 08 13:24:38 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 08 14:44:16 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 1:19:35.
Oct 08 14:44:16 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 1:21:59.
Oct 08 14:51:37 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 08 14:51:45 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:05.
Oct 08 14:52:56 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 08 14:56:49 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 08 16:56:12 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 2:03:14.
Oct 08 17:01:13 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 08 17:17:42 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:16:27.
Oct 08 17:17:47 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 2:20:55.
Oct 08 17:22:48 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 08 17:23:01 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:10.
Oct 08 17:34:12 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 08 17:34:25 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:10.
Oct 08 17:46:57 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 08 17:46:59 Readynas noflushd[2161]: Spindown of disk 2 (/dev/sdb) cancelled.
Oct 08 18:00:20 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 08 18:00:23 Readynas noflushd[2161]: Spindown of disk 2 (/dev/sdb) cancelled.
Oct 08 21:15:13 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 08 21:15:16 Readynas noflushd[2161]: Spindown of disk 2 (/dev/sdb) cancelled.
Oct 08 21:26:27 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 08 21:26:40 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:10.
Oct 08 21:44:13 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 08 21:44:15 Readynas noflushd[2161]: Spindown of disk 2 (/dev/sdb) cancelled.
Oct 08 21:52:56 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 08 21:53:09 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:10.
Oct 08 22:25:34 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 08 22:25:36 Readynas noflushd[2161]: Spindown of disk 3 (/dev/sda) cancelled.
Oct 08 22:30:37 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 08 22:30:50 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:10.
Oct 08 22:31:00 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 08 22:36:04 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 08 22:46:38 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:15:35.
Oct 08 22:46:43 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:10:36.
Oct 08 22:51:44 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 08 22:51:57 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:10.
Oct 08 22:57:08 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 08 22:57:12 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 08 22:57:19 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:07.
Oct 08 23:02:20 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 08 23:09:09 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:06:46.
Oct 08 23:09:09 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:11:55.
Oct 08 23:14:21 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 08 23:14:24 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 08 23:14:31 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 08 23:14:38 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:14.
Oct 08 23:22:09 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 08 23:22:12 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 08 23:38:31 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:16:17.
Oct 08 23:38:37 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:16:25.
Oct 08 23:44:07 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 08 23:44:11 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 08 23:44:18 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:07.
Oct 08 23:44:18 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 08 23:49:19 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 08 23:49:22 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 08 23:49:30 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:08.
Oct 08 23:49:30 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 08 23:54:31 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 08 23:54:34 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 08 23:54:41 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 08 23:54:48 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:14.
Oct 08 23:59:49 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 08 23:59:52 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 08 23:59:59 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:07.
Oct 08 23:59:59 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 00:05:20 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 00:05:23 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 00:05:31 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 00:05:36 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:13.
Oct 09 00:10:37 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 00:10:40 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 00:10:48 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 00:10:53 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:13.
Oct 09 00:15:54 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 00:15:57 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 00:16:05 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 00:16:10 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:13.
Oct 09 00:21:11 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 00:21:15 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 00:21:22 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 00:21:27 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:12.
Oct 09 00:26:28 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 00:26:31 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 00:26:39 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 00:26:45 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:14.
Oct 09 00:32:56 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 00:32:59 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 00:33:06 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 00:33:11 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:12.
Oct 09 00:38:12 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 00:38:15 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 00:38:23 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 00:38:29 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:14.
Oct 09 00:44:10 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 00:44:13 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 00:44:20 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:07.
Oct 09 00:44:20 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 00:51:42 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 00:51:45 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 00:51:52 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:07.
Oct 09 00:51:52 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 00:56:53 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 00:56:56 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 00:56:58 Readynas noflushd[2161]: Spindown of disk 2 (/dev/sdb) cancelled.
Oct 09 00:57:08 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:12.
Oct 09 01:05:20 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 01:05:23 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 01:05:30 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:07.
Oct 09 01:05:30 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 01:10:31 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 01:10:44 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:10.
Oct 09 01:14:25 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 01:14:38 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:10.
Oct 09 01:15:48 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 01:19:42 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 01:19:54 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:10.
Oct 09 01:20:00 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:04:09.
Oct 09 01:25:01 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 01:25:04 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 01:25:11 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:07.
Oct 09 01:25:11 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 01:30:12 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 01:30:15 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 01:30:23 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 01:30:29 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:14.
Oct 09 01:35:30 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 01:35:33 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 01:35:40 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 01:35:45 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:12.
Oct 09 01:40:46 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 01:40:49 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 01:40:57 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 01:41:03 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:14.
Oct 09 01:46:04 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 01:46:07 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 01:46:14 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 01:46:20 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:13.
Oct 09 01:51:20 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 01:51:24 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 01:51:31 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 01:51:37 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:13.
Oct 09 01:56:38 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 01:56:41 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 01:56:48 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 01:56:54 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:13.
Oct 09 02:01:55 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 02:01:58 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 02:02:05 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 02:02:11 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:13.
Oct 09 02:07:12 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 02:07:15 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 02:07:22 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 02:07:28 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:13.
Oct 09 02:12:29 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 02:12:32 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 02:12:39 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:07.
Oct 09 02:12:39 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 02:17:40 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 02:17:43 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 02:21:11 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:03:25.
Oct 09 02:21:21 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:03:38.
Oct 09 02:26:22 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 02:26:36 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:11.
Oct 09 02:26:36 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 02:31:39 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 06:25:06 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 3:58:28.
Oct 09 06:25:12 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 3:53:30.
Oct 09 06:30:23 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 06:30:26 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 06:30:33 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 06:30:39 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:13.
Oct 09 06:35:40 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 06:35:43 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 06:35:50 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 06:35:56 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:13.
Oct 09 06:40:57 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 06:41:00 Readynas noflushd[2161]: Spinning down disk 2 (/dev/sdb).
Oct 09 06:41:07 Readynas noflushd[2161]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 06:41:13 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:13.
Oct 09 06:48:14 Readynas noflushd[2161]: Spinning down disk 3 (/dev/sda).
Oct 09 06:48:27 Readynas noflushd[2161]: Spinning up disk 3 (/dev/sda) after 0:00:10.
Oct 09 06:49:12 Readynas noflushd[2161]: Quitting on signal...

dacwe · ‎2016-10-09

Interesting, I have the same problem: https://community.netgear.com/t5/Using-your-ReadyNAS/Spindown/m-p/1151489/highlight/true#M117348

StephenB · ‎2016-10-09

Mine are spinning down, though I am not running RAID.

hawke84 · ‎2016-10-09

im not on RAID either, JBOD, 2 disks

StephenB · ‎2016-10-09

Here's what I am seeing - some short spin-up times, but several spindowns for hours.

I already sent a PM on the readahead error with the WD60EFRX.

@rn102 wrote:

Oct 09 01:00:16 RN102 noflushd[32278]: Enabling spindown for disk 1 [sda,0:0:WDC_WD80EFZX-68UW8N0:VKGW079X:83.H0A83:5400]
Oct 09 01:00:16 RN102 noflushd[32278]: Enabling spindown for disk 2 [sdb,0:1:WDC_WD60EFRX-68MYMN1:WD-WX41D849PK8T:82.00A82:5700]
Oct 09 01:00:16 RN102 noflushd[32278]: Error: Readahead /etc/resolv.conf failed.
Oct 09 01:15:42 RN102 noflushd[32278]: Error: Readahead /etc/resolv.conf failed.
Oct 09 01:15:42 RN102 noflushd[32278]: Spinning down disk 1 (/dev/sda).
Oct 09 01:15:47 RN102 noflushd[32278]: Spindown of disk 1 (/dev/sda) cancelled.
Oct 09 01:15:47 RN102 noflushd[32278]: Spinning down disk 2 (/dev/sdb).
Oct 09 01:17:00 RN102 noflushd[32278]: Spinning up disk 2 (/dev/sdb) after 0:01:10.
Oct 09 01:32:03 RN102 noflushd[32278]: Spinning down disk 2 (/dev/sdb).
Oct 09 01:32:13 RN102 noflushd[32278]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 01:36:56 RN102 noflushd[32278]: Spinning down disk 1 (/dev/sda).
Oct 09 01:47:14 RN102 noflushd[32278]: Spinning down disk 2 (/dev/sdb).
Oct 09 03:05:26 RN102 noflushd[32278]: Spinning up disk 1 (/dev/sda) after 1:28:25.
Oct 09 03:05:37 RN102 noflushd[32278]: Spinning up disk 2 (/dev/sdb) after 1:18:20.
Oct 09 03:20:40 RN102 noflushd[32278]: Spinning down disk 2 (/dev/sdb).
Oct 09 03:20:50 RN102 noflushd[32278]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 09 03:32:33 RN102 noflushd[32278]: Spinning down disk 1 (/dev/sda).
Oct 09 03:32:44 RN102 noflushd[32278]: Spinning up disk 1 (/dev/sda) after 0:00:05.
Oct 09 03:36:06 RN102 noflushd[32278]: Spinning down disk 2 (/dev/sdb).
Oct 09 03:43:47 RN102 noflushd[32278]: Spinning up disk 2 (/dev/sdb) after 0:07:36.
Oct 09 03:59:11 RN102 noflushd[32278]: Spinning down disk 1 (/dev/sda).
Oct 09 03:59:17 RN102 noflushd[32278]: Spinning down disk 2 (/dev/sdb).
Oct 09 03:59:26 RN102 noflushd[32278]: Spinning up disk 1 (/dev/sda) after 0:00:09.
Oct 09 04:14:28 RN102 noflushd[32278]: Spinning down disk 1 (/dev/sda).
Oct 09 06:17:16 RN102 noflushd[32278]: Spinning up disk 1 (/dev/sda) after 2:02:45.
Oct 09 06:40:04 RN102 noflushd[32278]: Spinning down disk 1 (/dev/sda).
Oct 09 06:47:03 RN102 noflushd[32278]: Spinning up disk 1 (/dev/sda) after 0:06:56.
Oct 09 07:02:05 RN102 noflushd[32278]: Spinning down disk 1 (/dev/sda).
Oct 09 07:17:55 RN102 noflushd[32278]: Spinning up disk 1 (/dev/sda) after 0:15:47.
Oct 09 07:35:37 RN102 noflushd[32278]: Spinning up disk 2 (/dev/sdb) after 3:36:16.
Oct 09 07:55:41 RN102 noflushd[32278]: Spinning down disk 1 (/dev/sda).
Oct 09 07:55:46 RN102 noflushd[32278]: Spinning down disk 2 (/dev/sdb).
Oct 09 07:55:55 RN102 noflushd[32278]: Spinning up disk 1 (/dev/sda) after 0:00:09.
Oct 09 08:10:57 RN102 noflushd[32278]: Spinning down disk 1 (/dev/sda).
Oct 09 09:05:42 RN102 noflushd[32278]: Spinning up disk 1 (/dev/sda) after 0:54:42.
Oct 09 09:05:47 RN102 noflushd[32278]: Spinning up disk 2 (/dev/sdb) after 1:09:57.
Oct 09 09:20:50 RN102 noflushd[32278]: Spinning down disk 1 (/dev/sda).
Oct 09 09:20:56 RN102 noflushd[32278]: Spinning down disk 2 (/dev/sdb).
Oct 09 09:21:05 RN102 noflushd[32278]: Spinning up disk 1 (/dev/sda) after 0:00:09.
Oct 09 09:36:08 RN102 noflushd[32278]: Spinning down disk 1 (/dev/sda).
Oct 09 09:51:03 RN102 noflushd[32278]: Spinning up disk 1 (/dev/sda) after 0:14:52.
Oct 09 09:51:04 RN102 noflushd[32278]: Spinning up disk 2 (/dev/sdb) after 0:30:04.

hawke84 · ‎2016-10-09

Hmm that's interesting. I've just been watching it for a bit and it is still just spin up and down. What is the Swindon time you have set? I've tried changing it but no joy

hawke84 · ‎2016-10-09

Is there a log of connections or some way to see what is waking the device, just to rule out external factors

mdgm-ntgr · ‎2016-10-09

If you are comfortable with SSH, an easy to enable the block_dump option to noflushd is to add it to the TIMEOUT variable in /etc/default/noflushd. For example, if the content of that file contains "TIMEOUT=5", change it to "TIMEOUT=5 -b".

Then `systemctl restart noflushd`.

The logs you get after enabling the block_dump option would be useful.

StephenB · ‎2016-10-09

@hawke84 wrote:
What is the Spindown time you have set?

15 minutes

dacwe · ‎2016-10-10

Hi, okey, I think I found it. Running block dump during spindowns shows rnutil writing to disk each time it spins down (and up ~ 300 second delay beween each block of writes, same interval that I set them to spin down):

[152085.230218] md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
[152085.230302] md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)
[152087.341075] rnutil(18266): dirtied inode 7065 (event.sq3-journal) on md0
[152090.020301] jbd2/md0-8(887): WRITE block 3699200 on md0 (8 sectors)
[152090.020382] md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
[152090.020450] md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)
[152092.220612] jbd2/md0-8(887): WRITE block 3699208 on md0 (8 sectors)
[152092.220645] jbd2/md0-8(887): WRITE block 3699216 on md0 (8 sectors)
[152092.220663] jbd2/md0-8(887): WRITE block 3699224 on md0 (8 sectors)
[152092.220680] jbd2/md0-8(887): WRITE block 3699232 on md0 (8 sectors)
[152092.220696] jbd2/md0-8(887): WRITE block 3699240 on md0 (8 sectors)
[152092.220712] jbd2/md0-8(887): WRITE block 3699248 on md0 (8 sectors)
[152092.220729] jbd2/md0-8(887): WRITE block 3699256 on md0 (8 sectors)
[152092.223595] jbd2/md0-8(887): WRITE block 3699264 on md0 (8 sectors)
[152092.440233] md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
[152092.440310] md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)
[152094.636059] rnutil(18269): dirtied inode 7065 (event.sq3-journal) on md0
[152094.700631] rnutil(18272): dirtied inode 7065 (event.sq3-journal) on md0
[152395.630210] md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
[152395.630294] md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)
[152397.740973] rnutil(18279): dirtied inode 7065 (event.sq3-journal) on md0
[152401.030310] jbd2/md0-8(887): WRITE block 3699400 on md0 (8 sectors)
[152401.030393] md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
[152401.030466] md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)
[152403.415237] jbd2/md0-8(887): WRITE block 3699408 on md0 (8 sectors)
[152403.415272] jbd2/md0-8(887): WRITE block 3699416 on md0 (8 sectors)
[152403.415290] jbd2/md0-8(887): WRITE block 3699424 on md0 (8 sectors)
[152403.415306] jbd2/md0-8(887): WRITE block 3699432 on md0 (8 sectors)
[152403.415322] jbd2/md0-8(887): WRITE block 3699440 on md0 (8 sectors)
[152403.415340] jbd2/md0-8(887): WRITE block 3699448 on md0 (8 sectors)
[152403.415357] jbd2/md0-8(887): WRITE block 3699456 on md0 (8 sectors)
[152403.418191] jbd2/md0-8(887): WRITE block 3699464 on md0 (8 sectors)
[152403.640207] md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
[152403.640256] md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)
[152405.035925] rnutil(18282): dirtied inode 7065 (event.sq3-journal) on md0
[152405.100149] rnutil(18285): dirtied inode 7065 (event.sq3-journal) on md0
[152706.030227] md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
[152706.030309] md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)
[152708.131392] rnutil(18300): dirtied inode 7065 (event.sq3-journal) on md0
[152711.030303] jbd2/md0-8(887): WRITE block 3699592 on md0 (8 sectors)
[152711.030384] md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
[152711.030451] md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)
[152713.299433] jbd2/md0-8(887): WRITE block 3699600 on md0 (8 sectors)
[152713.299467] jbd2/md0-8(887): WRITE block 3699608 on md0 (8 sectors)
[152713.299485] jbd2/md0-8(887): WRITE block 3699616 on md0 (8 sectors)
[152713.299502] jbd2/md0-8(887): WRITE block 3699624 on md0 (8 sectors)
[152713.299518] jbd2/md0-8(887): WRITE block 3699632 on md0 (8 sectors)
[152713.299534] jbd2/md0-8(887): WRITE block 3699640 on md0 (8 sectors)
[152713.299552] jbd2/md0-8(887): WRITE block 3699648 on md0 (8 sectors)
[152713.302469] jbd2/md0-8(887): WRITE block 3699656 on md0 (8 sectors)
[152713.520204] md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
[152713.520263] md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)
[152715.425875] rnutil(18303): dirtied inode 7065 (event.sq3-journal) on md0
[152715.490575] rnutil(18306): dirtied inode 7065 (event.sq3-journal) on md0
[153016.420218] md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
[153016.420303] md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)
[153018.531622] rnutil(18314): dirtied inode 7065 (event.sq3-journal) on md0
[153019.125033] readynasd(2303): dirtied inode 69756 (blkid.tab) on tmpfs
[153022.030313] jbd2/md0-8(887): WRITE block 3699784 on md0 (8 sectors)
[153022.030396] md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
[153022.030468] md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)
[153024.473808] jbd2/md0-8(887): WRITE block 3699792 on md0 (8 sectors)
[153024.473841] jbd2/md0-8(887): WRITE block 3699800 on md0 (8 sectors)
[153024.473859] jbd2/md0-8(887): WRITE block 3699808 on md0 (8 sectors)
[153024.473875] jbd2/md0-8(887): WRITE block 3699816 on md0 (8 sectors)
[153024.473890] jbd2/md0-8(887): WRITE block 3699824 on md0 (8 sectors)
[153024.473906] jbd2/md0-8(887): WRITE block 3699832 on md0 (8 sectors)
[153024.473924] jbd2/md0-8(887): WRITE block 3699840 on md0 (8 sectors)
[153024.476758] jbd2/md0-8(887): WRITE block 3699848 on md0 (8 sectors)
[153024.700232] md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
[153024.700310] md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)
[153025.826268] rnutil(18317): dirtied inode 7065 (event.sq3-journal) on md0
[153025.890786] rnutil(18320): dirtied inode 7065 (event.sq3-journal) on md0
[153025.895052] rnutil(18320): READ block 414560 on md0 (8 sectors)

Looking at /etc/noflushd/spindown.sh (spinup.sh is the same):

#!/bin/sh

MSG='Disks sleeping..'
DURATION=60 # Time in seconds.

# Show message on LCD.
/usr/bin/rnutil rn_lcd -s "$MSG" -p 1 -e $DURATION -k 478

rnutil shows something the LCD. I just bluntly commented that line and now my disks spin down perfectly (at least they spin down and stay for 10+ hours).

Do I need that command? I'm on rn102.

mdgm-ntgr · ‎2016-10-10

That command is not essential, but it would be nice to get to the bottom of this. Writing to the LCD should not spin up the disks. We will check if we can reproduce this.

It would be helpful if we could confirm if others with spin down problems on 6.6.0 are also running into the same cause.

Also with problems like this the verbose logging from the block_dump option should only be used to identify the problem and then be switched off again.

mdgm-ntgr · ‎2016-10-11

I can see similar messages in hawke84's logs.

mdgm-ntgr · ‎2016-10-11

hawke84 I have disabled the LCD messages for spindown on your system too. Please see if this helps.

dacwe · ‎2016-10-11

I think there are some other stuff spinning up time disks too. I ran it through the night when I'm doing my backups (a couple at 4:05 and one at 5:05).

This is what I saw, I have interleaved the spindown.log and the block dumps (bold is interesting):

I have no idea what radar is...

Oct 11 01:20:54 backup noflushd[19481]: Spinning down disk 1 (/dev/sda).
Oct 11 01:20:56 backup noflushd[19481]: Spinning down disk 2 (/dev/sdb).
Oct 11 02:38:38 backup noflushd[19481]: Spinning up disk 1 (/dev/sda) after 1:17:42.

2016-10-11 02:38:40: radar(19562): READ block 336888 on md0 (8 sectors)

This is my first backup, it's fine:

Oct 11 02:53:40 backup noflushd[19481]: Spinning down disk 1 (/dev/sda).
Oct 11 04:05:06 backup noflushd[19481]: Spinning up disk 1 (/dev/sda) after 1:11:24.
Oct 11 04:05:11 backup noflushd[19481]: Spinning up disk 2 (/dev/sdb) after 2:44:13.

I have no idea why it cancels the spindown here:

Oct 11 04:38:53 backup noflushd[19481]: Spinning down disk 1 (/dev/sda).
Oct 11 04:38:55 backup noflushd[19481]: Spindown of disk 1 (/dev/sda) cancelled.

2016-10-11 04:38:58: jbd2/md0-8(887): WRITE block 3704144 on md0 (8 sectors)
2016-10-11 04:38:59: md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
2016-10-11 04:38:59: md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)

This is my second backup:

Oct 11 04:38:55 backup noflushd[19481]: Spinning down disk 2 (/dev/sdb).
Oct 11 04:53:54 backup noflushd[19481]: Spinning down disk 1 (/dev/sda).
Oct 11 05:05:08 backup noflushd[19481]: Spinning up disk 1 (/dev/sda) after 0:11:12.
Oct 11 05:05:08 backup noflushd[19481]: Spinning up disk 2 (/dev/sdb) after 0:26:11.

At 6:25 it seems to try and update the software:

Oct 11 05:20:29 backup noflushd[19481]: Spinning down disk 2 (/dev/sdb).
Oct 11 05:20:51 backup noflushd[19481]: Spinning down disk 1 (/dev/sda).
Oct 11 06:25:06 backup noflushd[19481]: Spinning up disk 1 (/dev/sda) after 1:04:13.
Oct 11 06:25:41 backup noflushd[19481]: Spinning up disk 2 (/dev/sdb) after 1:05:10.

2016-10-11 06:25:06: run-parts(20339): READ block 4471424 on md0 (8 sectors)
2016-10-11 06:25:35: readynasd(2303): dirtied inode 74477 (blkid tab-S17fDz) on tmpfs
2016-10-11 06:25:39: (apt_wait)(20348): READ block 4494048 on md0 (32 sectors)
2016-10-11 06:25:39: (apt_wait)(20348): READ block 367584 on md0 (32 sectors)
2016-10-11 06:25:39: apt_wait(20348): READ block 367616 on md0 (64 sectors)
2016-10-11 06:25:39: apt_wait(20348): READ block 4501952 on md0 (24 sectors)
2016-10-11 06:25:39: apt_wait(20348): READ block 367680 on md0 (120 sectors)
2016-10-11 06:25:39: apt_wait(20348): READ block 250456 on md0 (8 sectors)
2016-10-11 06:25:39: kworker/u2:1(20349): READ block 4482704 on md0 (8 sectors)
2016-10-11 06:25:39: (pdate sh)(20351): READ block 4543352 on md0 (8 sectors)
2016-10-11 06:25:39: systemd-cgroups(20349): READ block 4718592 on md0 (32 sectors)
2016-10-11 06:25:39: systemd-cgroups(20349): READ block 4721824 on md0 (8 sectors)
2016-10-11 06:25:39: systemd-cgroups(20349): READ block 4718656 on md0 (232 sectors)
2016-10-11 06:25:39: systemd-cgroups(20349): READ block 4718968 on md0 (40 sectors)
2016-10-11 06:25:39: systemd-cgroups(20349): READ block 4719064 on md0 (16 sectors)
2016-10-11 06:25:39: systemd-cgroups(20349): READ block 4719096 on md0 (72 sectors)
2016-10-11 06:25:39: systemd-cgroups(20349): READ block 4718624 on md0 (32 sectors)
2016-10-11 06:25:42: apt-update sh(20352): READ block 4465000 on md0 (32 sectors)
2016-10-11 06:25:42: grep(20352): READ block 4465224 on md0 (136 sectors)
2016-10-11 06:25:42: grep(20352): READ block 4465032 on md0 (192 sectors)
2016-10-11 06:25:42: apt-update sh(20353): READ block 4459328 on md0 (32 sectors)
2016-10-11 06:25:42: sleep(20353): READ block 4459360 on md0 (24 sectors)

Here it spins down but quickly spins up again, I have no idea why:

Oct 11 06:58:43 backup noflushd[19481]: Spinning down disk 1 (/dev/sda).
Oct 11 06:58:46 backup noflushd[19481]: Spinning down disk 2 (/dev/sdb).
Oct 11 06:58:53 backup noflushd[19481]: Spinning up disk 1 (/dev/sda) after 0:00:07.
Oct 11 06:58:53 backup noflushd[19481]: Spinning up disk 2 (/dev/sdb) after 0:00:05.

2016-10-11 06:58:54: jbd2/md0-8(887): WRITE block 3706664 on md0 (8 sectors)
2016-10-11 06:58:54: md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
2016-10-11 06:58:54: md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)
2016-10-11 06:58:56: jbd2/md0-8(887): WRITE block 3706672 on md0 (8 sectors)
2016-10-11 06:58:56: jbd2/md0-8(887): WRITE block 3706680 on md0 (8 sectors)
2016-10-11 06:58:56: jbd2/md0-8(887): WRITE block 3706688 on md0 (8 sectors)
2016-10-11 06:58:56: md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
2016-10-11 06:58:56: md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)

Again:

Oct 11 07:13:54 backup noflushd[19481]: Spinning down disk 1 (/dev/sda).
Oct 11 07:13:56 backup noflushd[19481]: Spinning down disk 2 (/dev/sdb).
Oct 11 07:14:03 backup noflushd[19481]: Spinning up disk 1 (/dev/sda) after 0:00:07.
Oct 11 07:14:03 backup noflushd[19481]: Spinning up disk 2 (/dev/sdb) after 0:00:05.

2016-10-11 07:14:04: jbd2/md0-8(887): WRITE block 3706840 on md0 (8 sectors)
2016-10-11 07:14:04: md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
2016-10-11 07:14:04: md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)
2016-10-11 07:14:06: jbd2/md0-8(887): WRITE block 3706848 on md0 (8 sectors)
2016-10-11 07:14:06: jbd2/md0-8(887): WRITE block 3706856 on md0 (8 sectors)
2016-10-11 07:14:06: jbd2/md0-8(887): WRITE block 3706864 on md0 (8 sectors)
2016-10-11 07:14:06: md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
2016-10-11 07:14:06: md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)

Here it successfully spins down, but it's dangerously close to not:

Oct 11 07:29:04 backup noflushd[19481]: Spinning down disk 1 (/dev/sda).
Oct 11 07:29:07 backup noflushd[19481]: Spinning down disk 2 (/dev/sdb).

2016-10-11 07:29:09: jbd2/md0-8(887): WRITE block 3707096 on md0 (8 sectors)
2016-10-11 07:29:09: md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
2016-10-11 07:29:09: md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)

Here I go in and check the logs:

Oct 11 13:27:08 backup noflushd[19481]: Spinning up disk 1 (/dev/sda) after 5:58:01.
Oct 11 13:27:08 backup noflushd[19481]: Spinning up disk 2 (/dev/sdb) after 5:57:59.

dacwe · ‎2016-10-11

> Writing to the LCD should not spin up the disks.

Just to comment on this. Writing to the LCD using:

root@backup:~# rnutil rn_lcd -s "Testing" -p 1 -e 10 -k 478

writes to the event_push.log file:

root@backup:~# grep Testing /var/log/readynasd/event_push.log 
  <lcd expiration="1476192972" priority="1" key="478" string="Testing"/></xs:add-s>

...and as far as I can see that file is placed on disk and not in memory.

hawke84 · ‎2016-10-11

mdgm it seems to have made it a lot better, its not completly fixed it but its got a lot better.

Oct 11 12:42:35 Readynas noflushd[14991]: Enabling spindown for disk 3 [sda,0:2:ST2000DL003-9VT166:5YD3KGQ0:CC32:5900]
Oct 11 12:42:35 Readynas noflushd[14991]: Enabling spindown for disk 2 [sdb,0:1:WDC_WD10EFRX-68PJCN0:WD-WCC4J6AX24A6:82.00A82:5400]
Oct 11 12:42:35 Readynas noflushd[14991]: Error: Readahead /etc/resolv.conf failed.
Oct 11 12:52:46 Readynas noflushd[14991]: Error: Readahead /etc/resolv.conf failed.
Oct 11 12:52:46 Readynas noflushd[14991]: Spinning down disk 3 (/dev/sda).
Oct 11 12:52:49 Readynas noflushd[14991]: Spinning down disk 2 (/dev/sdb).
Oct 11 12:52:57 Readynas noflushd[14991]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 11 12:53:03 Readynas noflushd[14991]: Spinning up disk 3 (/dev/sda) after 0:00:14.
Oct 11 13:03:04 Readynas noflushd[14991]: Spinning down disk 3 (/dev/sda).
Oct 11 13:03:07 Readynas noflushd[14991]: Spinning down disk 2 (/dev/sdb).
Oct 11 13:03:14 Readynas noflushd[14991]: Spinning up disk 3 (/dev/sda) after 0:00:07.
Oct 11 13:03:15 Readynas noflushd[14991]: Spinning up disk 2 (/dev/sdb) after 0:00:06.
Oct 11 13:19:25 Readynas noflushd[14991]: Spinning down disk 3 (/dev/sda).
Oct 11 13:19:28 Readynas noflushd[14991]: Spinning down disk 2 (/dev/sdb).
Oct 11 13:19:35 Readynas noflushd[14991]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 11 13:19:41 Readynas noflushd[14991]: Spinning up disk 3 (/dev/sda) after 0:00:13.
Oct 11 13:29:42 Readynas noflushd[14991]: Spinning down disk 3 (/dev/sda).
Oct 11 13:29:45 Readynas noflushd[14991]: Spinning down disk 2 (/dev/sdb).
Oct 11 13:29:52 Readynas noflushd[14991]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 11 13:29:58 Readynas noflushd[14991]: Spinning up disk 3 (/dev/sda) after 0:00:13.
Oct 11 13:39:59 Readynas noflushd[14991]: Spinning down disk 3 (/dev/sda).
Oct 11 13:40:02 Readynas noflushd[14991]: Spinning down disk 2 (/dev/sdb).
Oct 11 13:40:09 Readynas noflushd[14991]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 11 13:40:15 Readynas noflushd[14991]: Spinning up disk 3 (/dev/sda) after 0:00:13.
Oct 11 13:50:16 Readynas noflushd[14991]: Spinning down disk 3 (/dev/sda).
Oct 11 13:50:19 Readynas noflushd[14991]: Spinning down disk 2 (/dev/sdb).
Oct 11 13:50:26 Readynas noflushd[14991]: Spinning up disk 3 (/dev/sda) after 0:00:07.
Oct 11 13:50:26 Readynas noflushd[14991]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 11 14:00:27 Readynas noflushd[14991]: Spinning down disk 3 (/dev/sda).
Oct 11 14:00:30 Readynas noflushd[14991]: Spinning down disk 2 (/dev/sdb).
Oct 11 16:32:25 Readynas noflushd[14991]: Spinning up disk 2 (/dev/sdb) after 2:31:53.
Oct 11 16:32:30 Readynas noflushd[14991]: Spinning up disk 3 (/dev/sda) after 2:32:00.
Oct 11 16:42:33 Readynas noflushd[14991]: Spinning down disk 3 (/dev/sda).
Oct 11 16:42:36 Readynas noflushd[14991]: Spinning down disk 2 (/dev/sdb).
Oct 11 16:42:43 Readynas noflushd[14991]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 11 16:42:49 Readynas noflushd[14991]: Spinning up disk 3 (/dev/sda) after 0:00:13.
Oct 11 16:52:50 Readynas noflushd[14991]: Spinning down disk 3 (/dev/sda).
Oct 11 16:52:53 Readynas noflushd[14991]: Spinning down disk 2 (/dev/sdb).
Oct 11 18:13:15 Readynas noflushd[14991]: Spinning up disk 2 (/dev/sdb) after 1:20:20.
Oct 11 18:23:17 Readynas noflushd[14991]: Spinning down disk 2 (/dev/sdb).
Oct 11 19:33:48 Readynas noflushd[14991]: Spinning up disk 2 (/dev/sdb) after 1:10:29.
Oct 11 19:33:58 Readynas noflushd[14991]: Spinning up disk 3 (/dev/sda) after 2:41:05.

dacwe · ‎2016-10-11

I skimmed through the noflushd code. I'm going out on a limb here but I don't think it accounts for "raid relationships" between disks.

Also, a project called pynoflushd on github writes this:

pynoflushd - hard disk drive spindown control daemon

Inspired by noflushd.

The problem I have with noflushd is I use soft raid. noflushd is not aware of
(virtual) block device dependencies, so it flushes any device it didn't ask to
spin down. The result is properly spinning down a physical drive, and right
next flush a raid device, spinning up disk again as raid superblock gets
refreshed.

The author has software raid but with my limited understanding I don't understand the difference in this case between software and hardware raid.

But, regardless, keeping as few writes as possible before and during the actual spindown (for instance to log files) should make this case pretty slim...

dacwe · ‎2016-10-11

Sorry for writing so many replies. But I have a question about noflushd and ext4 (which my readynas uses). According to noflushd man page under "bugs":

> Journaling filesystems like ext3, or reiserfs bypass the kernel's delayed write mechanisms and write straight to disk. noflushd is unable to postpone writing of journaling data. As a result, expect lousy spindown behaviour when working off ext3/reiserfs/... partitions.

If there is no point of using noflushd on journaling filesystem why not just set the disks standby (spindown) timeout using hdparm directly?

Skywalker · ‎2016-10-12

The "noflushd" we use on ReadyNAS is heavily modified, and is vastly different from the noflushd you may read about on the internet. Our version is RAID-aware, and of course works with journaling filesystems. Otherwise you'd never see disks spin down for longer than 30 seconds.

Writes to the filesystem are not a problem, unless they are synchronous writes. The flush to disk gets deferred until the disks *really* need to spin up, like for a sync write or a read request. So writing to a log file, or dirtying inodes, will not make the disks spin up.

Doc_Holliday · ‎2016-10-13

Hi, same problem here with RN102 after upgrade to 6.6. Anything I can do at the moment? Or just wait for the next update?

dacwe · ‎2016-10-14

Thanks for the explanation Skywalker, makes sense.

I've ran my modded versions of spin{up,down}.sh for two days now. And it still writes to disk for no reason just during spin down, these three instances for example:

Oct 14 12:00:27 backup noflushd[3375]: Spinning down disk 1 (/dev/sda).
Oct 14 12:00:29 backup noflushd[3375]: Spinning down disk 2 (/dev/sdb).
Oct 14 12:00:37 backup noflushd[3375]: Spinning up disk 1 (/dev/sda) after 0:00:08.
Oct 14 12:00:37 backup noflushd[3375]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 14 12:15:38 backup noflushd[3375]: Spinning down disk 1 (/dev/sda).
Oct 14 12:15:40 backup noflushd[3375]: Spinning down disk 2 (/dev/sdb).
Oct 14 12:15:47 backup noflushd[3375]: Spinning up disk 1 (/dev/sda) after 0:00:07.
Oct 14 12:15:47 backup noflushd[3375]: Spinning up disk 2 (/dev/sdb) after 0:00:05.
Oct 14 12:30:48 backup noflushd[3375]: Spinning down disk 1 (/dev/sda).
Oct 14 12:30:50 backup noflushd[3375]: Spinning down disk 2 (/dev/sdb).

With the block dumps for each (the last was successful?):

okt 14 12:00:39: jbd2/md0-8(887): WRITE block 3686872 on md0 (8 sectors)
okt 14 12:00:39: md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
okt 14 12:00:39: md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)
okt 14 12:00:41: jbd2/md0-8(887): WRITE block 3686880 on md0 (8 sectors)
okt 14 12:00:41: jbd2/md0-8(887): WRITE block 3686888 on md0 (8 sectors)
okt 14 12:00:41: jbd2/md0-8(887): WRITE block 3686896 on md0 (8 sectors)
okt 14 12:00:41: md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
okt 14 12:00:41: md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)
okt 14 12:15:50: jbd2/md0-8(887): WRITE block 3687048 on md0 (8 sectors)
okt 14 12:15:50: md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
okt 14 12:15:50: md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)
okt 14 12:15:52: jbd2/md0-8(887): WRITE block 3687056 on md0 (8 sectors)
okt 14 12:15:52: jbd2/md0-8(887): WRITE block 3687064 on md0 (8 sectors)
okt 14 12:15:52: jbd2/md0-8(887): WRITE block 3687072 on md0 (8 sectors)
okt 14 12:15:52: md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
okt 14 12:15:52: md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)
okt 14 12:30:54: jbd2/md0-8(887): WRITE block 3687304 on md0 (8 sectors)
okt 14 12:30:54: md0_raid1(872): WRITE block 8 on sda1 (1 sectors)
okt 14 12:30:54: md0_raid1(872): WRITE block 8 on sdb1 (1 sectors)

I have about 15 spinups daily, 5 of which I can explain (updating software, doing backups etc).

Maybe the modified noflushd needs some kind of grace period (or synchronous wait) before spinning down the drives to let the writes settle? Because, I still feel that there is a race here.

mdgm-ntgr · ‎2016-10-18

We are looking into the issues that have been reported with disk spin-down on ARM systems.

yuan_1202 · ‎2016-10-21

Am having the same problem after 6.6 update. 😞

-- Logs begin at Fri 2016-10-21 19:33:46 WEST, end at Fri 2016-10-21 21:02:09 WEST. --
Oct 21 19:37:26 YUAN-NAS noflushd[3976]: Enabling spindown for disk 1 [sda,0:0:TOSHIBA_HDWE140:Z5M8KE82F58D:FP2A:7200]
Oct 21 19:37:26 YUAN-NAS noflushd[3976]: Error: Readahead /etc/resolv.conf failed.
Oct 21 19:37:34 YUAN-NAS noflushd[3976]: Quitting on signal...
Oct 21 19:37:34 YUAN-NAS noflushd[4012]: Enabling spindown for disk 1 [sda,0:0:TOSHIBA_HDWE140:Z5M8KE82F58D:FP2A:7200]
Oct 21 19:37:34 YUAN-NAS noflushd[4012]: Error: Readahead /etc/resolv.conf failed.
Oct 21 19:48:11 YUAN-NAS noflushd[4012]: Error: Readahead /etc/resolv.conf failed.
Oct 21 19:48:11 YUAN-NAS noflushd[4012]: Spinning down disk 1 (/dev/sda).
Oct 21 19:48:19 YUAN-NAS noflushd[4012]: Spinning up disk 1 (/dev/sda) after 0:00:05.
Oct 21 20:04:52 YUAN-NAS noflushd[4012]: Spinning down disk 1 (/dev/sda).
Oct 21 20:04:59 YUAN-NAS noflushd[4012]: Spinning up disk 1 (/dev/sda) after 0:00:05.
Oct 21 20:15:00 YUAN-NAS noflushd[4012]: Spinning down disk 1 (/dev/sda).
Oct 21 20:17:13 YUAN-NAS noflushd[4012]: Spinning up disk 1 (/dev/sda) after 0:02:10.
Oct 21 20:27:14 YUAN-NAS noflushd[4012]: Spinning down disk 1 (/dev/sda).
Oct 21 20:44:49 YUAN-NAS noflushd[4012]: Spinning up disk 1 (/dev/sda) after 0:17:32.
Oct 21 20:51:04 YUAN-NAS noflushd[4012]: Quitting on signal...
Oct 21 20:51:04 YUAN-NAS noflushd[6531]: Enabling spindown for disk 1 [sda,0:0:TOSHIBA_HDWE140:Z5M8KE82F58D:FP2A:7200]
Oct 21 20:51:04 YUAN-NAS noflushd[6531]: Error: Readahead /etc/resolv.conf failed.

yuan_1202 · ‎2016-10-28

Any update guys?

yuan_1202 · ‎2016-10-29

The nas does not just wont spin down, it is constantly doing stuff on the hard drive which is not logged. So you hear the bloody hard drive "dip" reading/writing every few seconds.

This annoys me so much, especially when i tried to resolve this issue by rolling back to earlier readynas os version, which is not allowed.

So here comes the question to netgear, if you want to force stuff on ur customer, at least get the basics stuff correct?