[分享] Synology NAS 休眠模式 debug tool

現今 NAS 雖然大多採用較為省電的 Intel Atom or Marvell CPU, 更提供了休眠模式設定, 以使 NAS idle 時可以停止 HD 運轉達到更節能的目的.

節能做法
設定排程: 設定系統在指定的時間自動開機或關機, 例如 NAS 只在上班時間或是備份運作期間開機, 並於指定時間到達自動關機.


硬碟休眠:設定系統內部硬碟和外接的 eSATA 或 USB 硬碟在閒置一段時間後，停止運轉並進入休眠狀態。;可節省電源和延長硬碟的使用壽命。


常見問題
Hibernation mode 最常遇到的問題就是 NAS 即使未存取, 但於指定時間到達時未進入休眠模式, 造成此狀況通常是 NAS 在 background 仍有一些程序 (process) 在執行. 解決方法可以參考官方論壇上面的說明.

官方提供的說明
非官方提供的解決問題實施步施

上面的內容就不再翻譯, 網友請自行參考.

Debug tool
遇到問題最快的解決方法就是直接連絡客服, 請客服協助處理, 若喜歡追根究底的 User 可以參考下述的方法,　開啟 hibernate debug mode, 此時系統會紀錄下此段期間所有 process 的內容, 以方便原廠或 user 找出造成系統無法進入休眠模式的主因.

詳細的操作過程請參考附件. 大致過程如下.
1.ssh 進入 NAS command mode
2.enter syno_hibernate_debug_tool --enable 1
3.離開 ssh, 並停止對 NAS 做任何存取動作.
4.於指定的休眠時間到達後, 重新 ssh 進入 nas
5.enter syno_hibernate_debug_tool --disable
6.check /var/log/messages 檔案, 並檢視於 enable 至 disable 期間內所有的 log.
範例一: DS213+ 正常進入 HD hibernation mode


範例二: DS213+ 在 11:39 嘗試進入 deep sleep 模式, 但產生一些問題 (明顯 log 就多了一大堆,但應該只有原廠看的懂, 畢竟進階休眠(deep sleep)模式是 DS213+/DS413 特有的)

Aug 30 11:27:54 syno_hibernate_debug_tool: (115): Start Hibernation Debug with second [1]
Aug 30 11:27:54 kernel: [ 2565.512974] [/etc/passwd] opened by pid 9359 [u:(-ash), comm:(ash)]
Aug 30 11:27:56 kernel: [ 2567.692348] [/etc/passwd] opened by pid 9353 [u:(sshd: root@pts/0), comm:(sshd)]
Aug 30 11:38:19 kernel: [ 3190.669400] [/etc/localtime] opened by pid 5212 [u:(/usr/syno/bin/scemd), comm:(scemd)]
Aug 30 11:39:19 kernel: [ 3251.625705] [/etc/localtime] opened by pid 5212 [u:(/usr/syno/bin/scemd), comm:(scemd)]
Aug 30 11:39:20 kernel: [ 3252.024968] drivers/scsi/sd.c[443]:syno_hibernation_timer_update(), sda: cmd 0x0 spin up by pid=8, comm=events/1
Aug 30 11:39:20 kernel: [ 3252.035407] drivers/scsi/sd.c[443]:syno_hibernation_timer_update(), sdb: cmd 0x0 spin up by pid=8, comm=events/1
Aug 30 11:39:21 hotplugd: usb_get_device_id.c:49 Get usb info failed, DEVICE=/proc/bus/usb/002/001
Aug 30 11:39:21 hotplugd: hotplugd.c:980 failed get usb device id from usb config, DEVICE=/proc/bus/usb/002/001
Aug 30 11:39:21 hotplugd: ##### ACTION:remove
Aug 30 11:39:35 kernel: [ 3266.709383] [/var/log/messages] opened by pid 3114 [u:(/sbin/syslogd), comm:(syslogd)]
Aug 30 11:39:35 hotplugd: DEVICE:/proc/bus/usb/002/001
Aug 30 11:39:35 hotplugd: DEVPATH:2-0:1.0
Aug 30 11:39:35 hotplugd: SUBSYSTEM:usb
Aug 30 11:39:35 hotplugd: INTERFACE:9/0/0
Aug 30 11:39:35 hotplugd: usb_get_device_id.c:49 Get usb info failed, DEVICE=/proc/bus/usb/002/001
Aug 30 11:39:35 hotplugd: hotplugd.c:980 failed get usb device id from usb config, DEVICE=/proc/bus/usb/002/001
Aug 30 11:39:35 hotplugd: ##### ACTION:remove
Aug 30 11:39:35 hotplugd: DEVICE:/proc/bus/usb/002/001
Aug 30 11:39:35 hotplugd: DEVPATH:usb2
Aug 30 11:39:35 hotplugd: SUBSYSTEM:usb
Aug 30 11:39:35 hotplugd: ##### ACTION:remove
Aug 30 11:39:35 hotplugd: DEVICE:/proc/bus/usb/001/002
Aug 30 11:39:35 hotplugd: DEVPATH:1-1:1.0
Aug 30 11:39:35 hotplugd: SUBSYSTEM:usb
Aug 30 11:39:35 hotplugd: INTERFACE:9/0/0
Aug 30 11:39:35 hotplugd: ##### ACTION:remove
Aug 30 11:39:35 hotplugd: DEVICE:/proc/bus/usb/001/002
Aug 30 11:39:35 hotplugd: DEVPATH:1-1
Aug 30 11:39:35 hotplugd: SUBSYSTEM:usb
Aug 30 11:39:35 hotplugd: usb_get_device_id.c:49 Get usb info failed, DEVICE=/proc/bus/usb/001/001
Aug 30 11:39:35 hotplugd: hotplugd.c:980 failed get usb device id from usb config, DEVICE=/proc/bus/usb/001/001
Aug 30 11:39:35 hotplugd: ##### ACTION:remove
Aug 30 11:39:35 hotplugd: DEVICE:/proc/bus/usb/001/001
Aug 30 11:39:35 hotplugd: DEVPATH:1-0:1.0
Aug 30 11:39:35 hotplugd: SUBSYSTEM:usb
Aug 30 11:39:35 hotplugd: INTERFACE:9/0/0
Aug 30 11:39:35 hotplugd: usb_get_device_id.c:49 Get usb info failed, DEVICE=/proc/bus/usb/001/001
Aug 30 11:39:35 hotplugd: hotplugd.c:980 failed get usb device id from usb config, DEVICE=/proc/bus/usb/001/001
Aug 30 11:39:35 hotplugd: ##### ACTION:remove
Aug 30 11:39:35 hotplugd: DEVICE:/proc/bus/usb/001/001
Aug 30 11:39:35 hotplugd: DEVPATH:usb1
Aug 30 11:39:35 hotplugd: SUBSYSTEM:usb
Aug 30 11:39:35 kernel: [ 3266.780030] done.
Aug 30 11:39:47 kernel: [ 3266.781971] Freezing user space processes ... (elapsed 0.00 seconds) done.
Aug 30 11:39:47 kernel: [ 3266.789099] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done.
Aug 30 11:39:47 kernel: [ 3266.796472] Suspending console(s) (use no_console_suspend to debug)

Aug 30 11:39:47 kernel: [ 3267.021110] Disabling non-boot CPUs ...
Aug 30 11:39:47 kernel: [ 3267.047855] Cannot set affinity for irq 247
Aug 30 11:39:47 kernel: [ 3267.548613] Enabling non-boot CPUs ...

Aug 30 11:39:47 kernel: [ 3267.548642] setting frequency for cpu 0 to 1066666 kHz, PLL ratio is 4/2
Aug 30 11:39:47 kernel: [ 3267.548650] PMJCR request 04043c00 at CPU 0
Aug 30 11:39:47 kernel: [ 3267.548656] PORPLLSR core freq 1066MHz at CPU 0
Aug 30 11:39:47 kernel: [ 3267.555827] Processor 1 found.
Aug 30 11:39:47 kernel: [ 3267.631940] 0: 533333kHz
Aug 30 11:39:47 kernel: [ 3267.631944] 1: 799999kHz
Aug 30 11:39:48 kernel: [ 3267.631948] 2: 1066666kHz
Aug 30 11:39:48 kernel: [ 3267.631951] 3: 1333332kHz
Aug 30 11:39:48 kernel: [ 3267.631955] 4: 1599999kHz
Aug 30 11:39:48 kernel: [ 3267.631958] 5: 1866665kHz
Aug 30 11:39:48 kernel: [ 3267.631962] 6: 2133332kHz
Aug 30 11:39:48 kernel: [ 3267.632006] setting frequency for cpu 1 to 1066666 kHz, PLL ratio is 4/2
Aug 30 11:39:48 kernel: [ 3267.632013] PMJCR request 04043c00 at CPU 1
Aug 30 11:39:48 kernel: [ 3267.632018] PORPLLSR core freq 1066MHz at CPU 1
Aug 30 11:39:48 kernel: [ 3267.632052] setting frequency for cpu 1 to 1066666 kHz, PLL ratio is 4/2
Aug 30 11:39:48 kernel: [ 3267.632057] PMJCR request 04043c00 at CPU 1
Aug 30 11:39:48 kernel: [ 3267.632062] PORPLLSR core freq 1066MHz at CPU 1
Aug 30 11:39:48 kernel: [ 3267.632067] CPU1 is up
Aug 30 11:39:48 kernel: [ 3268.155826] ata4: No Device OR PHYRDY change,Hstatus = 0xa0000000
Aug 30 11:39:48 kernel: [ 3268.155857] ata3: No Device OR PHYRDY change,Hstatus = 0xa0000000
Aug 30 11:39:48 kernel: [ 3277.651829] ata2: softreset failed (timeout)
Aug 30 11:39:48 kernel: [ 3277.651834] ata2: softreset failed, set srst fail flag
Aug 30 11:39:48 kernel: [ 3279.851861] ata2: link reset sucessfully clear error flags
Aug 30 11:39:48 kernel: [ 3280.046012] Restarting tasks ... [/etc/localtime] opened by pid 3119 [u:(/sbin/klogd), comm:(klogd)]
Aug 30 11:39:48 kernel: [ 3280.050992] done.
Aug 30 11:39:48 kernel: [ 3280.051943] [/] opened by pid 10406 [u:(sh), comm:(sh)]
Aug 30 11:39:48 scemd: modules/disk_hibernation.c:286 Fail to insert the usb module: ehci_hcd
Aug 30 11:39:48 scemd: modules/disk_hibernation.c:289 Fail to insert the usb module: ohci_hcd
Aug 30 11:39:48 kernel: [ 3280.223307] usb usb2: No SuperSpeed endpoint companion for config 1 interface 0 altsetting 0 ep 129: using minimum values
Aug 30 11:39:48 scemd: modules/disk_hibernation.c:292 Fail to insert the usb module: xhci_hcd
Aug 30 11:39:48 scemd: SCEMD: disk 1 wake up from hibernation
Aug 30 11:39:48 scemd: modules/disk_hibernation.c:1870 Diskstation wakes up from deep sleep.
Aug 30 11:39:48 kernel: [ 3280.594175] Got empty serial number. Generate serial number from product.
Aug 30 11:39:57 scemd: SCEMD: disk 2 wake up from hibernation
Aug 30 11:39:57 hotplugd: usb_get_device_id.c:56 failed get usb id Vendor=0000, ProdID=0000, SN=000000009910
Aug 30 11:39:57 hotplugd: hotplugd.c:980 failed get usb device id from usb config, DEVICE=/proc/bus/usb/000/000
Aug 30 11:39:57 hotplugd: ##### ACTION:remove
Aug 30 11:39:57 hotplugd: DEVNAME:sdq
Aug 30 11:39:57 hotplugd: DEVICE:/proc/bus/usb/000/000
Aug 30 11:39:57 hotplugd: DEVPATH:sdq
Aug 30 11:39:57 hotplugd: SUBSYSTEM:block
Aug 30 11:39:57 hotplugd: PHYSDEVPATH:/devices/platform/fsl-ehci.0/usb1/1-1/1-1.3/1-1.3:1.0/host4/target4:0:0/4:0:0:0
Aug 30 11:39:57 hotplugd: hotplugd.c (1420) ==== USB disk [sdq] plugged out====
Aug 30 11:39:57 backup_local_hotpull: backup_local_hotpull.c:18 No backup info in shared memory.
Aug 30 11:39:57 backup_local_hotpull: backup_local_hotpull.c:67 LocalBkpUSBHotPullOutProcess() failed.
Aug 30 11:39:57 hotplugd: SYNOReadOneSectorFromDev(56): failed to open device [/dev/sdq] (errno = 6)
Aug 30 11:39:57 hotplugd: volume_parts_info_get_by_dev.c:90 Dev:sdq cannot find PostfixNumber.
Aug 30 11:39:57 hotplugd: SYNOReadOneSectorFromDev(56): failed to open device [/dev/sdq] (errno = 6)
Aug 30 11:39:57 hotplugd: usbbkp_is_dev_bkp_disk.c:85 SYNOReadOneSectorFromDev failed. szDevPath=[sdq], errno=[0x0900]
Aug 30 11:39:57 hotplugd: volume_parts_info_get_by_dev.c:304 failed to get disk '/dev/sdq' size
Aug 30 11:39:57 hotplugd: usbbkp_hot_pull_out_ex.c:66 Remove /tmp/usbtab [sdq] failed. (0x2000)
Aug 30 11:39:57 hotplugd: hotplugd.c (1424) Failed to handle USB disk hotplug out.
Aug 30 11:39:57 hotplugd: usb_get_device_id.c:56 failed get usb id Vendor=0000, ProdID=0000, SN=000000009910
Aug 30 11:39:57 hotplugd: hotplugd.c:980 failed get usb device id from usb config, DEVICE=/proc/bus/usb/000/000
Aug 30 11:39:57 hotplugd: ##### ACTION:remove
Aug 30 11:39:57 hotplugd: DEVNAME:sdr
Aug 30 11:39:57 hotplugd: DEVICE:/proc/bus/usb/000/000
Aug 30 11:39:57 hotplugd: DEVPATH:sdr
Aug 30 11:39:57 hotplugd: SUBSYSTEM:block
Aug 30 11:39:57 hotplugd: PHYSDEVPATH:/devices/platform/fsl-ehci.0/usb1/1-1/1-1.3/1-1.3:1.0/host4/target4:0:0/4:0:0:1
Aug 30 11:39:57 hotplugd: hotplugd.c (1420) ==== USB disk [sdr] plugged out====
Aug 30 11:39:58 backup_local_hotpull: backup_local_hotpull.c:18 No backup info in shared memory.
Aug 30 11:39:58 backup_local_hotpull: backup_local_hotpull.c:67 LocalBkpUSBHotPullOutProcess() failed.
Aug 30 11:39:58 hotplugd: SYNOReadOneSectorFromDev(56): failed to open device [/dev/sdr] (errno = 6)
Aug 30 11:39:58 hotplugd: volume_parts_info_get_by_dev.c:90 Dev:sdr cannot find PostfixNumber.
Aug 30 11:39:58 hotplugd: SYNOReadOneSectorFromDev(56): failed to open device [/dev/sdr] (errno = 6)
Aug 30 11:39:58 hotplugd: usbbkp_is_dev_bkp_disk.c:85 SYNOReadOneSectorFromDev failed. szDevPath=[sdr], errno=[0x0900]
Aug 30 11:39:58 hotplugd: volume_parts_info_get_by_dev.c:304 failed to get disk '/dev/sdr' size
Aug 30 11:39:58 hotplugd: usbbkp_hot_pull_out_ex.c:66 Remove /tmp/usbtab [sdr] failed. (0x2000)
Aug 30 11:39:58 hotplugd: hotplugd.c (1424) Failed to handle USB disk hotplug out.
Aug 30 11:39:58 hotplugd: hotplugd.c:988 failed get usb status from usb config, DEVICE=/proc/bus/usb/001/001, usbid=1d6b:0002:fsl-ehci.0
Aug 30 11:39:58 hotplugd: ##### ACTION:add
Aug 30 11:39:58 hotplugd: DEVICE:/proc/bus/usb/001/001
Aug 30 11:39:58 hotplugd: DEVPATH:usb1
Aug 30 11:39:58 hotplugd: SUBSYSTEM:usb
Aug 30 11:39:58 hotplugd: hotplugd.c:763 Fail to recognize usb DEVNAME=, DEVPATH=usb1
Aug 30 11:39:58 hotplugd: hotplugd.c:1289 failed to setup usb config, (DEVPATH, DEVICE, ACTION, DEVNAME, INTERFACE)=(usb1, /proc/bus/usb/001/001, add, , )
Aug 30 11:39:58 hotplugd: hotplugd.c:988 failed get usb status from usb config, DEVICE=/proc/bus/usb/001/001, usbid=1d6b:0002:fsl-ehci.0
Aug 30 11:39:58 hotplugd: ##### ACTION:add
Aug 30 11:39:58 hotplugd: DEVICE:/proc/bus/usb/001/001
Aug 30 11:39:58 hotplugd: DEVPATH:1-0:1.0
Aug 30 11:39:58 hotplugd: SUBSYSTEM:usb
Aug 30 11:39:58 hotplugd: INTERFACE:9/0/0
Aug 30 11:39:58 hotplugd: hotplugd.c:988 failed get usb status from usb config, DEVICE=/proc/bus/usb/002/001, usbid=1d6b:0003:0002:05:00.0
Aug 30 11:39:58 hotplugd: ##### ACTION:add
Aug 30 11:39:58 hotplugd: DEVICE:/proc/bus/usb/002/001
Aug 30 11:39:58 hotplugd: DEVPATH:usb2
Aug 30 11:39:58 hotplugd: SUBSYSTEM:usb
Aug 30 11:39:58 hotplugd: hotplugd.c:763 Fail to recognize usb DEVNAME=, DEVPATH=usb2
Aug 30 11:39:58 hotplugd: hotplugd.c:1289 failed to setup usb config, (DEVPATH, DEVICE, ACTION, DEVNAME, INTERFACE)=(usb2, /proc/bus/usb/002/001, add, , )
Aug 30 11:39:58 hotplugd: hotplugd.c:988 failed get usb status from usb config, DEVICE=/proc/bus/usb/002/001, usbid=1d6b:0003:0002:05:00.0
Aug 30 11:39:58 hotplugd: ##### ACTION:add
Aug 30 11:39:58 hotplugd: DEVICE:/proc/bus/usb/002/001
Aug 30 11:39:58 hotplugd: DEVPATH:2-0:1.0
Aug 30 11:39:58 hotplugd: SUBSYSTEM:usb
Aug 30 11:39:58 hotplugd: INTERFACE:9/0/0
Aug 30 11:39:58 hotplugd: ##### ACTION:add
Aug 30 11:39:58 hotplugd: DEVICE:/proc/bus/usb/001/002
Aug 30 11:39:58 hotplugd: DEVPATH:1-1
Aug 30 11:39:58 hotplugd: SUBSYSTEM:usb
Aug 30 11:39:58 hotplugd: ##### ACTION:add
Aug 30 11:39:58 hotplugd: DEVICE:/proc/bus/usb/001/002
Aug 30 11:39:58 hotplugd: DEVPATH:1-1:1.0
Aug 30 11:39:58 hotplugd: SUBSYSTEM:usb
Aug 30 11:39:58 hotplugd: INTERFACE:9/0/0
Aug 30 11:39:58 hotplugd: hotplugd.c:790 ##### complete device hotplug!!
Aug 30 11:40:02 kernel: [ 3286.041140] [/etc/localtime] opened by pid 3119 [u:(/sbin/klogd), comm:(klogd)]
Aug 30 11:40:02 kernel: [ 3286.041329] drivers/scsi/sd.c (2344) Got USB disk
Aug 30 11:40:02 kernel: [ 3286.041690] [/sbin/hotplug] opened by pid 11080 [u:(/bin/sh), comm:(hotplug)]
Aug 30 11:40:02 kernel: [ 3286.084792] drivers/scsi/sd.c (2344) Got USB disk
Aug 30 11:44:54 kernel: [ 3578.200595] [/etc/ld.so.cache] opened by pid 11385 [u:(/usr/syno/sbin/sshd), comm:(sshd)]
Aug 30 11:44:55 kernel: [ 3579.345334] [/etc/localtime] opened by pid 11388 [u:(sshd: [net]), comm:(sshd)]
Aug 30 11:44:57 kernel: [ 3581.393328] [/etc/shadow] opened by pid 11385 [u:(sshd: root [priv]), comm:(sshd)]
Aug 30 11:45:05 kernel: [ 3589.692938] [/sbin/syno_hibernate_debug_tool] opened by pid 11391 [u:(-ash), comm:(ash)]
Aug 30 11:45:05 syno_hibernate_debug_tool: (154): End Hibernation Debug
DiskStation>

IRQ247?


附加壓縮檔: 201208/mobile01-9a28132043817e957b75de6068578a01.zip