黑群晖硬盘灯问题导致无法硬盘休眠处理

参考：

黑群晖各种问题修正（黑裙洗白、黑裙休眠、硬盘顺序） - wukongroot - 博客园

黑群晖之硬盘休眠 

---

休眠

1. 打开休眠调试日志

这个选项藏得比较深,在左上角菜单→技术支持中心→左边技术支持服务→启动系统休眠调试模式

 

2. 等待触发休眠问题

保持 NAS 空闲到设定的时间即可.记得把 NAS 的网页和各种客户端都关掉,不然接下来的日志可能会很长没法分析.我自己是在睡觉之前打开日志,起来分析.睡觉的时候除了 NAS 和路由器就没有其他设备开机了,日志很准确.

3. 分析日志

会产生两份日志,分别是 /var/log/hibernation.log 和 /var/log/hibernationFull.log. 后者是原始数据,前者是去除了一些无价值“连锁性”操作的精简版,但它有的时候会精简过头,所以我这里以后者为例来分析.

首先,将脏块写入磁盘的日志手动排除掉.通常内核不会自发进行大量的磁盘操作,大多数 write block 是用户态 dirty block 导致的结果,因此可以把包含 WRITE block 和 sync 的行删除,节省大量的版面.

其次,将非硬盘的写入排除掉.将包含 on tmpfs 或 on proc 的行删除即可,剩下的非硬盘文件系统肉眼忽略.

剩下的条目可以进入分析了.比如我这里在午睡时每段记录都差不多是这个样子:

 1 ***********Clear*********
 2 [140146.388709] btsync(15253): dirtied inode 11404 (sync.log) on md2
 3 [140146.388721] btsync(15253): dirtied inode 11404 (sync.log) on md2
 4 [140146.388723] btsync(15253): dirtied inode 11404 (sync.log) on md2
 5 [140151.820668] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
 6 [140151.820682] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
 7 [140151.820684] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
 8 [140152.332689] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
 9 [140152.332696] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
10 [140152.332698] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
11 [140153.783855] btsync(15253): dirtied inode 11404 (sync.log) on md2
12 [140153.783870] btsync(15253): dirtied inode 11404 (sync.log) on md2
13 [140153.783872] btsync(15253): dirtied inode 11404 (sync.log) on md2
14 [140170.602870] synologrotated(4963): dirtied inode 28083 (.SYNOSYSDB-wal) on md0
15 [140170.602888] synologrotated(4963): dirtied inode 29789 (.SYNOSYSDB-shm) on md0
16 [140170.603221] synologrotated(4963): dirtied inode 21538 (.SYNOCONNDB-wal) on md0
17 [140170.603235] synologrotated(4963): dirtied inode 22044 (.SYNOCONNDB-shm) on md0
18 [140173.443684] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
19 [140173.443696] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
20 [140173.443698] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
21 [140173.955999] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
22 [140173.956006] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
23 [140173.956009] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
24 [140272.465248] btsync(15253): dirtied inode 11404 (sync.log) on md2
25 [140272.465265] btsync(15253): dirtied inode 11404 (sync.log) on md2
26 [140272.465267] btsync(15253): dirtied inode 11404 (sync.log) on md2
27 [140278.386378] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
28 [140278.386390] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
29 [140278.386393] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
30 [140278.898561] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
31 [140278.898569] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
32 [140278.898571] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
33 [140631.564198] btsync(15253): dirtied inode 11404 (sync.log) on md2
34 [140631.564209] btsync(15253): dirtied inode 11404 (sync.log) on md2
35 [140631.564211] btsync(15253): dirtied inode 11404 (sync.log) on md2
36 [140637.298101] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
37 [140637.298113] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
38 [140637.298115] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
39 [140637.811061] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
40 [140637.811068] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
41 [140637.811071] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
42 [141346.340822] btsync(15253): dirtied inode 11404 (sync.log) on md2
43 [141346.340833] btsync(15253): dirtied inode 11404 (sync.log) on md2
44 [141346.340836] btsync(15253): dirtied inode 11404 (sync.log) on md2
45 [141351.508216] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
46 [141351.508226] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
47 [141351.508228] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
48 [141352.021228] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
49 [141352.021235] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
50 [141352.021238] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
51 [141352.494749] btsync(15253): dirtied inode 11404 (sync.log) on md2
52 [141352.494758] btsync(15253): dirtied inode 11404 (sync.log) on md2
53 [141352.494760] btsync(15253): dirtied inode 11404 (sync.log) on md2
54 [141371.039633] synologrotated(4963): dirtied inode 28083 (.SYNOSYSDB-wal) on md0
55 [141371.039654] synologrotated(4963): dirtied inode 29789 (.SYNOSYSDB-shm) on md0
56 [141371.039992] synologrotated(4963): dirtied inode 21538 (.SYNOCONNDB-wal) on md0
57 [141371.040007] synologrotated(4963): dirtied inode 22044 (.SYNOCONNDB-shm) on md0
58 [141377.244527] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
59 [141377.244539] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
60 [141377.244541] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
61 [141377.757046] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
62 [141377.757054] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
63 [141377.757056] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
64 [141535.911703] dhclient(16778): dirtied inode 19635 (sh) on md0
65 [141535.911717] dhclient(16778): dirtied inode 19626 (bash) on md0
66 [141535.911909] dhclient-script(16778): dirtied inode 14958 (libncursesw.so.5) on md0
67 [141535.911917] dhclient-script(16778): dirtied inode 13705 (libncursesw.so.5.9) on md0
68 [141535.914460] awk(16782): dirtied inode 13819 (libm.so.6) on md0
69 [141535.914470] awk(16782): dirtied inode 11177 (libm-2.20-2014.11.so) on md0
70 [141542.431766] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
71 [141542.431778] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
72 [141542.431781] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
73 [141542.944314] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
74 [141542.944322] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
75 [141542.944324] syno_hibernatio(25655): dirtied inode 5348 (hibernation.log) on md0
76 [142073.169495] btsync(15253): dirtied inode 11404 (sync.log) on md2
77 [142073.169512] btsync(15253): dirtied inode 11404 (sync.log) on md2
78 [142073.169515] btsync(15253): dirtied inode 11404 (sync.log) on md2
79 [142078.947137] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
80 [142078.947150] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
81 [142078.947152] syno_hibernatio(25655): dirtied inode 5885 (hibernationFull.log) on md0
82 uptime : [142078.753468]
83 ======Idle 536 seconds======
84 Sat Oct 27 14:34:19 CST 2018

进程不多,逐个判断:

btsync:BTSync 套件,sync.log 顾名思义好了.这样看来,它频繁写日志是一个很明显的阻碍休眠的原因.我反正只是装着,没配置它,可以把它删掉.

syno_hibernatio:ps | grep 看一下发现全称是 syno_hibernation_debug,加之操作的文件名,确定是记录休眠日志的工具自身,以后关了就没了

synologrotated:应该是记录系统日志的工具,如果正经休眠了应该就不会有日志了,这也是个被动来源

dhclient 和 dhclient-script:DHCP 客户端常规操作,阻挡不了

那么这一轮下来只能得出需要停止 BTSync 的结论.先这么做了再说.休眠日志可以不急着关掉.
再放一天试试.查看系统日志:

 

从日志来看,上面的操作是有效的,硬盘终于能进入休眠了,出现了很多“Internal disks woke up from hibernation”.但是这每半小时一条,相当于休眠没几秒又被唤醒了.

于是继续分析休眠日志:

 1 ***********Clear*********
 2 [236666.547745] syslog-ng(4331): dirtied inode 18 (scemd.log) on md0
 3 [236687.650564] syslog-ng(13085): dirtied inode 18 (scemd.log) on md0
 4 [236687.650585] syslog-ng(13085): dirtied inode 18 (scemd.log) on md0
 5 [236687.650592] syslog-ng(13085): dirtied inode 18 (scemd.log) on md0
 6 [236687.658884] syslog-ng(5016): dirtied inode 28581 (.SYNOSYSDB-shm) on md0
 7 [236687.658893] syslog-ng(5016): dirtied inode 28581 (.SYNOSYSDB-shm) on md0
 8 [236687.658946] syslog-ng(5016): dirtied inode 24584 (.SYNOSYSDB-wal) on md0
 9 [236687.658952] syslog-ng(5016): dirtied inode 24584 (.SYNOSYSDB-wal) on md0
10 [236687.658954] syslog-ng(5016): dirtied inode 24584 (.SYNOSYSDB-wal) on md0
11 [236687.664164] logrotate(13090): dirtied inode 41594 (synolog) on md0
12 [236687.666146] logrotate(13090): dirtied inode 6900 (logrotate.status) on md0
13 [236687.671082] logrotate(13090): dirtied inode 7905 (logrotate.status.tmp) on md0
14 [236689.662143] synologaccd(4840): dirtied inode 22952 (.SYNOACCOUNTDB) on md0
15 [236689.662355] synologaccd(4840): dirtied inode 6900 (.SYNOACCOUNTDB-wal) on md0
16 [236689.662383] synologaccd(4840): dirtied inode 21526 (.SYNOACCOUNTDB-shm) on md0
17 [236689.763593] synologaccd(4840): dirtied inode 22952 (.SYNOACCOUNTDB) on md0
18 [236689.763629] synologaccd(4840): dirtied inode 22952 (.SYNOACCOUNTDB) on md0
19 [236691.547334] synologrotated(5000): dirtied inode 28581 (.SYNOSYSDB-shm) on md0
20 [236691.547681] synologrotated(5000): dirtied inode 23485 (.SYNOCONNDB-wal) on md0
21 [236691.547695] synologrotated(5000): dirtied inode 24677 (.SYNOCONNDB-shm) on md0
22 [238511.431135] syslog-ng(4331): dirtied inode 18 (scemd.log) on md0
23 uptime : [238516.475108]
24 ======Idle 1807 seconds======
25 Wed Oct 24 03:52:06 CST 2018
26 #####################################################
27 Only idle 44 seconds, pass
28 Wed Oct 24 03:52:51 CST 2018
29 #####################################################
30 ***********Clear*********
31 [238522.209123] synologrotated(5000): dirtied inode 24584 (.SYNOSYSDB-wal) on md0
32 [238522.209173] synologrotated(5000): dirtied inode 28581 (.SYNOSYSDB-shm) on md0
33 [238522.210082] synologrotated(5000): dirtied inode 23485 (.SYNOCONNDB-wal) on md0
34 [238522.210122] synologrotated(5000): dirtied inode 24677 (.SYNOCONNDB-shm) on md0
35 [238522.224252] logrotate(19321): dirtied inode 41594 (synolog) on md0
36 [238522.229880] logrotate(19321): dirtied inode 7905 (logrotate.status) on md0
37 [238522.244528] logrotate(19321): dirtied inode 6900 (logrotate.status.tmp) on md0
38 [238531.967854] syslog-ng(19324): dirtied inode 18 (scemd.log) on md0
39 [238531.967874] syslog-ng(19324): dirtied inode 18 (scemd.log) on md0
40 [238531.967882] syslog-ng(19324): dirtied inode 18 (scemd.log) on md0
41 [238531.990488] logrotate(19329): dirtied inode 6900 (logrotate.status.tmp) on md0
42 [238533.979174] synologaccd(4840): dirtied inode 22952 (.SYNOACCOUNTDB) on md0
43 [238533.979348] synologaccd(4840): dirtied inode 7905 (.SYNOACCOUNTDB-wal) on md0
44 [238533.979378] synologaccd(4840): dirtied inode 21526 (.SYNOACCOUNTDB-shm) on md0
45 [238534.076345] synologaccd(4840): dirtied inode 22952 (.SYNOACCOUNTDB) on md0
46 [238534.076385] synologaccd(4840): dirtied inode 22952 (.SYNOACCOUNTDB) on md0
47 [240368.320927] syslog-ng(4331): dirtied inode 18 (scemd.log) on md0
48 uptime : [240374.147000]
49 ======Idle 1811 seconds======
50 Wed Oct 24 04:23:02 CST 2018

synocrond:听起来像是任务计划程序,里面有个 DSM 自动更新检查,触发频率不高,应该不太影响

builtin-synodat:不知道是什么

logrotate:大概也是个日志程序

synologaccd:继续是日志程序

syslog-ng:我也不知道为什么群晖有那么多日志管理程序

单次日志看不出来什么,但是连着好几块都符合刚一休眠就被唤醒(空闲时间是设定的 30 分钟加十几秒),且最后一条都是对 (/var/log/)scemd.log 的写入。这就有点意思了,打开看看里面是什么:

 1 2018-10-24T07:00:13+08:00 Hamster-DS scemd: led/led_brightness.c:244 Fail to read /usr/sbin/i2cget
 2 2018-10-24T07:00:13+08:00 Hamster-DS scemd: led.c:35 SYNOGetLedBrightness fail()
 3 2018-10-24T07:00:34+08:00 Hamster-DS scemd: event_disk_hibernation_handler.c:42 The internal disks wake up, hibernate from [Oct 24 07:00:11]
 4 2018-10-24T07:31:09+08:00 Hamster-DS scemd: led/led_brightness.c:244 Fail to read /usr/sbin/i2cget
 5 2018-10-24T07:31:09+08:00 Hamster-DS scemd: led.c:35 SYNOGetLedBrightness fail()
 6 2018-10-24T07:31:30+08:00 Hamster-DS scemd: event_disk_hibernation_handler.c:42 The internal disks wake up, hibernate from [Oct 24 07:31:07]
 7 2018-10-24T08:01:53+08:00 Hamster-DS scemd: led/led_brightness.c:244 Fail to read /usr/sbin/i2cget
 8 2018-10-24T08:01:53+08:00 Hamster-DS scemd: led.c:35 SYNOGetLedBrightness fail()
 9 2018-10-24T08:02:14+08:00 Hamster-DS scemd: event_disk_hibernation_handler.c:42 The internal disks wake up, hibernate from [Oct 24 08:01:53]
10 2018-10-24T08:32:37+08:00 Hamster-DS scemd: led/led_brightness.c:244 Fail to read /usr/sbin/i2cget
11 2018-10-24T08:32:37+08:00 Hamster-DS scemd: led.c:35 SYNOGetLedBrightness fail()
12 2018-10-24T08:32:59+08:00 Hamster-DS scemd: event_disk_hibernation_handler.c:42 The internal disks wake up, hibernate from [Oct 24 08:32:37]

清晰地表明了这就是休眠后立即唤醒的原因:由于黑群没有 I2C 设备,于是 DSM 在休眠后尝试更改 LED 亮度（或者颜色、闪烁规律？)时读取 i2c 设备节点就会出错,scemd 把这条错误信息记到自己的日志里,触发了硬盘写入,硬盘就在休眠十几秒后被唤醒了.

4. 修复

根本上修复的话,得硬件上 I2C 适配器,甚至还能顺便给黑群加上白群的那么多灯.但这是不现实的,那么我们就只能采取主流方法:解决提出问题的日志.预想方案是把这个日志文件指向内存,让 scemd 往内存里写,就不会唤醒硬盘了.
找到文件:

1 vim /etc.defaults/syslog-ng/patterndb.d/scemd.conf

修改

1 destination d_scemd { file("/var/log/scemd.log"); };
2 为
3 destination d_scemd { file("/tmp/scemd.log"); };

重启系统即可完美休眠.