DSM6: syno_hibernation_debug

[dirkolus]

Moin,

Ich möchte mit Euch meine Erfahrungen mit DSM6 und dem Tool /usr/syno/sbin/syno_hibernation_debug teilen. Dieses Tool habe ich auf meiner DS 416j gefunden, nachdem ich erfolglos das (Vorgänger?-) Tool syno_hibernate_debug_tool gesucht habe, das auf der DSM6 aber offenbar nicht mehr installiert ist.

Zuerst muss man das Tool patchen, sonst ist es vollkommen wirkungslos:

• 
  Erst die originale Datei als syno_hibernation_debug.org zur Sicherheit kopieren
  In der originalen Datei ab Zeile 77 zwei Zeilen nachtragen, damit die Funktion wie folgt aussieht:
  

  keyin_value()
  {
      Support_hibernation=`/bin/get_key_value /etc.defaults/synoinfo.conf ${support_hibernation}`
      if [ "x${Support_hibernation}" != "xyes" ]; then
          exit 0
      else
          hibernation_mode="yes"
      fi
  
      hibernation_mode=`/bin/get_key_value /etc/synoinfo.conf ${deubg_key}`
      if [ 1 -ne $? ]; then
          # no key found
  ...

  DIe fetten Zeilen sind der Code, der eingefügt werden müsste

Hibernation wird aktiviert mit:

• 
  In /etc/synoinfo.conf die folgenden Parameter kontrollieren (Sie stimmen im default-Fall):
  

  enable_hibernation_debug="1"
  hibernation_debug_level="2"

  Aufruf auf der Shell als root: /usr/syno/sbin/syno_hibernation_debug

Die beiden Parameter bedeuten (hibernation_debug_level):
„1“ Wake up frequently.
„2“ Determine, why the system can't enter hibernation.
Geloggt wird in die Logfiles: /var/log/hibernation.log und /var/log/hibernationFull.log

Deaktiviert wird das Log mit:

• 
  in /etc/synoinfo.conf ? enable_hibernation_debug=„0“;
  /usr/syno/sbin/syno_hibernation_debug
  oder unsauber mit: kill $(cat /tmp/hibernation.debug)

Dirk

 

[dil88]

Danke fürs Teilen!

 

[shred]

Es geht auch ganz ohne Patchen des Tools...

Als erstes sollte man sicher stellen, dass in der /etc.defaults/synoinfo.conf die folgende Zeile vorhanden ist:

support_disk_hibernation="yes"

In der /etc/synoinfo.conf habe ich dann folgendes eingetragen:

enable_hibernation_debug="yes"
hibernation_debug_level="1"

Auf meinem System fehlten die Einträge in der Datei, ich habe sie ergänzt. Wenn sie schon vorhanden sind, müssen sie einfach nur verändert werden.

Anschließend habe ich syno_hibernation_debug aufgerufen.

Zum Abschalten einfach enable_hibernation_debug="no" setzen und das Tool wieder aufrufen.

Als Debuglevel gibt es zwei Möglichkeiten:

• 1 = "Cannot Enter Hibernation"
• 2 = "Which Interrupt Hibernation"

 

[dirkolus]

Ja, das ist der sauberere Weg. Patches werden auch überschrieben, deswegen besser enable_hibernation_debug = "yes" (anstelle "0")

Dirk

 

[claas]

Hallo,

bei mir gibt's die Datei nicht.
Wo findet ihr die genau?

Danke

Claas

 

[Kurt-oe1kyw]

Grundvoraussetzung:
Du musst als "root" auf die Oberfläche der DS einsteigen, ich mache das zB mit winSCP aktuelle Version 5.9.6 und der Schlüsseldatei .ppk zur Authentifizierung.

Danach als "root" einsteigen und wie in den vorangegangen Beiträgen aufgelistet von den diversen Usern einsteigen (Hinweis, meistens bist du im Ordner "root"! dh. du musst einmal oben auf den Ordner klicken mit dem schwarzen Pfeil um eine Ebene nach oben zu gelangen!) nach:

/etc.defaults/synoinfo.conf
/etc/synoinfo.conf
/usr/syno/sbin/syno_hibernation_debug

zumindest auf meiner DS 916+ sind alle Ordner und Dateien vorhanden.
Auch von mir Danke für das Teilen und die Tipps.

 

[claas]

Hallo Kurt,

ich war kein root. Daher hab ich sie nicht gesehen. Danke

 

[Roland_68]

Hi @ all,
da ich neu hier bin, möchte ich mal kurz ein nettes "Hallo" in die Runde schmeißen!

Frage: "Wie" und "Wo" kann ich die aufgezeichneten Daten einsehen? Habe darüber im Forum für die "DSM6" leider nix gefunden.

DS216+ii / DSM 6.1.3-15152

Danke schon mal an dieser Stelle

 

[Roland_68]

Sry Leute,

ich habe es einfach überlesen. #1
Es steht zwar nicht "fett" und "b r e i t" da, aber es steht da!

Roland

 

[Adimarantis]

Geloggt wird in die Logfiles: /var/log/hibernation.log und /var/log/hibernationFull.log

Hint: Das geht ganz ohne shell und config files patchen auch über die Oberfläche im "Support Center"

Da steht bei mir dann haufenweise was von Lese- und Schreibzugriffen diverser Synology Prozesse drin. z.B.:
[119783.652817] sync(4673): WRITE block 267792 on md0 (8 sectors)
[119830.768769] synocgid(7248): dirtied inode 22970 (6OSCDBLoGA5921470MGN820500) on md0
[119830.780543] postgres(4826): dirtied inode 2280476 (oom_score_adj) on proc
uptime : [119836.196812]
======Idle 53 seconds======

Hilft mir leider wenig weiter rauszufinden, was hier Probleme macht. Gibt es Tipps wie man das liest? Mehr als 20-60 Sekunden idle bringt mein System laut den logfiles nicht zusammen (und bräuchte wahrscheinlich mind. 10 Minuten)
Meine ds415play weigert sich nach wie vor standhaft in hibernate zu gehen - läuft fast nichts mehr drauf und ich hab auch schon mal für eine Stunde den Netzwerkstecker gezogen (und alle Settings auf 10 Minuten)

 

[bvrulez]

Super Fred und super Beitrag von Adminarantis!

 

[Th0u]

ich schaue mir gerade das Hibernationverhalten an meiner DS218+ und DS215J an und fand die Information hier im Thread schon mal sehr hilfreich.
Da das Lesen/Auswerten der Hibernation Logs nicht unbedingt trivial ist, hab ich mir vorgenommen, hier mal mein Blick auf meine Logs zu dokumentieren, da das ggfs. anderen weiter hilft. Allerdings können meine Rückschlüsse ganz oder teilweise fehlerhaft sein.

Nochmal ein paar Gedanken vorweg:
HDD Hibernation in Kurzfassung: das anhalten der internen bzw. der angeschlossenen USB Festplatten.
HDD Hibernation kann dann erfolgen, wenn über eine voreingestellte Zeit, z.B 10min, keine Zugriffe auf die Festplatten erfolgte. Dann kann das System die Platten schlafen legen.

Grundsätzlich gibt es für Hibernation zwei Stördimensionen:
1. Hibernation Timeout wird nicht erreicht, da vor erreichen des Timeouts was auf die Platten geschrieben wird.
2. Hibernation wird beendet (wake up). Die Platten schlafen, aber es soll was geschrieben werden.
Das oben genannte Debuggingtool /usr/syno/sbin/syno_hibernation_debug kann anscheinend für beide Fälle konfiguriert werden (siehe Debuglevel).

Funktionalität vs Hibernation
Meine beiden DS haben bei mir unterschiedliche Aufgabenschwerpunkte:
* Die DS218+ ist extern erreichbar, sie nimmt von meinen Smartphones die Bilder entgegen, ist Backupziel verschiedenster Rechner und dient als zentraler Ablageort für Daten (Shares).

* Meine DS216J ist extern erreichbar und dient via Hyper Backup Vault der DS218+ als Backupziel. Sonst hat sie keine weiteren Aufgaben.

Bei meiner DS218 macht Hibernation nicht wirklich Sinn, da in meinem Haushalt immer irgendwie darauf zugegriffen wird und Hibernation gestört wird. Wogegen meine DS216J nur 1x pro Tag ein Backup aufnimmt. Hier ist das vielleicht 1h Betrieb und 23h idle und eigentlich könnten die Platten in der DS216j 23h schlafen.

Internes Datenmanagement vs Hibernation
Neben den Diensten die eine Syno für den User bereit stellt, verrichten etliche interne Dienste ihr Werk, die ggfs auch Daten schreiben(müssen).
Beispielsweise Logeinträge (Anmeldung, Abmeldungen etc), S.M.A.R.T, Log Rotation, Bash History, Datenbank Maintenance, Histogrammdaten.

Während es für den Anwender nachvollziehbar ist, dass z.B. Zugriffe auf die von der DS gehosteten Fotos den Schlafmodus stört, ist es z.B. bei Logrotation oder bash history nicht zwingend offensichtlich.

Mittels der Debug logs kann man aber hier sich ein besseres Bild verschaffen, wohin Prozesse Daten schreiben.

Weiteres dazu folgt im Teil#2.

 

[Th0u]

Teil#2
Vorbereitung
Wie im ersten Post in diesem Thread beschrieben, müsst ihr das Debugging aktivieren (synoinfo.conf) und dann auch starten (/usr/syno/sbin/syno_hibernation_debug).

Prüfen, ob debugging läuft:
bash-4.3# ps axf | grep syno_hibernation_debug
6060 pts/10 S+ 0:00 | \_ grep syno_hibernation_debug
16243 pts/10 S 0:25 /bin/sh /usr/syno/sbin/syno_hibernation_debug

falls nur "grep syno_hibernation_debug" erscheint, dann läuft das debugging tool nicht.
Wenn ihr wie oben zusätzlich eine Zeile mit "/bin/sh /usr/syno/sbin/syno_hibernation_debug" findet, dann läuft das Debugging und es werden die 2 Dateien /var/log/hibernationFull.log und /var/log/hibernation.log geschrieben.

Falls ihr das Debugging vorzeitig beenden wollt, könnt ihr das z.B. mittels kill -HUP PID_von_syno_hibernation_debug machen. Das ist hilfreich wenn man den Debugparameter in der synoinfo.conf geändert hat.


Überblick verschaffen
Um mir einen guten Überblick zu verschaffen, was/wann in die Logs reingeschrieben wird, nutze ich mehrere Konsolenfenster und verbinde mich jeweils per SSH auf die DS und wechsle per sudo bash in root.
Da die Logfiles oft sehr viele Einträge aufnehmen, filtere ich in den verschiedenen Konsolen auf unterschiedliche Inhalte, damit ich besser den Überblick habe.
Am Ende habe folgende Konsolen:
Konsole#1 : Eingabekonsole für Commands

Konsole#2: Zeigt mir nur Zeilen mit Inhalt "Only idle xxx seconds, pass". Warum? Hier sehe ich schnell die Idle Seconds.
tail -f /var/log/hibernation* | grep "idle"

Konsole#3: Zeigt mir nur Zeilen die "md0" enthalten. Warum? md0 ist bei mir das Volume gebildet aus /dev/sda1 und /dev/sdb1. Alles was sich auf md0 bezieht (z.B wer schreibt?), interessiert mich.
tail -f /var/log/hibernation* | grep "md0"

Konsole#4: Zeigt mir nur Zeilen aus hibernation.log
tail -f /var/log/hibernation.log

Konsole#5: Zeigt mir nur Zeilen aus hibernationFull.log
tail -f /var/log/hibernationFull.log

Konsole#6: Zeigt mir nur Zeilen die "wake up" enthalten. Warum? hier sehe ich die verschiedenen "Wake up" Eventzeilen
tail -f /var/log/hibernation* | grep "wake"


Dank zweier großer Monitore, kann ich die Konsolen gut verteilen.


Im Teil#3 schreibe ich etwas über die Inhalte der hibernation logs.

 

[Th0u]

Teil#3
Erste Bestandsaufnahme
Da meine DS216 "nichts" macht, ist es in den Logs sehr ruhig.

Ein konkretes Beispiel:
In der Konsole#3 "md0" fallen mir folgende Zeilen auf.
[10060.249618] ppid:1(init), pid:16243(syno_hibernatio), dirtied inode 32223 (hibernationFull.log) on md0
[10060.249658] ppid:1(init), pid:16243(syno_hibernatio), dirtied inode 32223 (hibernationFull.log) on md0
[10060.249677] ppid:1(init), pid:16243(syno_hibernatio), dirtied inode 32223 (hibernationFull.log) on md0

Das kann "reduziert" so gelesen werden: der Parentprozess "init" (ppid:1) hat einen Prozess "syno_hibernatio[n_debug]" (pid:16234), der in die Datei "hibernationFull.log", die auf "md0" liegt, geschrieben hat. "dirtied inode xxxx" bedeutet grob, dass sich inode xxxx geändert hat.

Das schreiben auf Disk kann man im meinem Fall hier ablesen:
[10060.411326] ppid:2(kthreadd), pid:884(md0_raid1), WRITE block 4980352 on sda1 (8 sectors)
[10060.411443] ppid:2(kthreadd), pid:884(md0_raid1), WRITE block 4980352 on sdb1 (8 sectors)

Also: Unser syno_hibernation_debug hat was in sein Log geschrieben, was logischerweise Hibernation stört.

Nach diesem Muster gibt es noch weitere Störer:
[10054.320149] ppid:1(init), pid:8156(synocrond), dirtied inode 26118 (synocrond-execute.log) on md0
[10054.320187] ppid:1(init), pid:8156(synocrond), dirtied inode 26118 (synocrond-execute.log) on md0
[10054.320205] ppid:1(init), pid:8156(synocrond), dirtied inode 26118 (synocrond-execute.log) on md0


In meiner Konsole#6 "wake" sieht es sehr ruhig aus:

bash-4.3# tail -n 1000 -f /var/log/hibernation* | grep "wake"
[ 4178.376746] ata2: wake up from deepsleep, reset link now
[ 9393.309486] ata1: wake up from deepsleep, reset link now
[ 9393.309486] ata1: wake up from deepsleep, reset link now
[ 9393.309486] ata1: wake up from deepsleep, reset link now
[ 9400.306596] ata2: wake up from deepsleep, reset link now
[ 9404.449745] ata1: wake up successful, the reset fail can be ignored
[ 9411.036982] ata2: wake up successful, the reset fail can be ignored
[ 9393.309486] ata1: wake up from deepsleep, reset link now
[ 9400.306596] ata2: wake up from deepsleep, reset link now
[ 9404.449745] ata1: wake up successful, the reset fail can be ignored
[ 9411.036982] ata2: wake up successful, the reset fail can be ignored

Da in den hibernation-logs schon seit längerem kein neuer Content mehr zu sehen ist (vermutlich schlafen die Platten), gehe ich mal in die Command "Konsole#1" und tippe "ls -la". Damit wird in meinem Fall die bash history geschrieben und hibernation wird gestört.

Wie sich das in den Logs niederschlägt, zeige ich in Teil#4.

 

[Th0u]

Teil#4 "Wake Up" getriggert

Nachdem ich ein Update der Bash-history erzwungen habe, gibt es in den Konsolen neuen Input. Teilweise auch interessanten Input.

Wake Konsole#6
bash-4.3# tail -n 1000 -f /var/log/hibernation* | grep "wake"
[ 9393.309486] ata1: wake up from deepsleep, reset link now
[ 9400.306596] ata2: wake up from deepsleep, reset link now
[ 9404.449745] ata1: wake up successful, the reset fail can be ignored
[ 9411.036982] ata2: wake up successful, the reset fail can be ignored
[12744.104145] ata1: wake up from deepsleep, reset link now
[12744.104145] ata1: wake up from deepsleep, reset link now
[12744.104145] ata1: wake up from deepsleep, reset link now
[12751.101313] ata2: wake up from deepsleep, reset link now
[12755.224150] ata1: wake up successful, the reset fail can be ignored
[12759.372589] ata2: wake up successful, the reset fail can be ignored

Zum Zeitstempel 12744.xxx wurde ein Wake up geloggt.

In der Konsole#3 (md0) scolle ich etwas zurück und sehe ....
[10060.249618] ppid:1(init), pid:16243(syno_hibernatio), dirtied inode 32223 (hibernationFull.log) on md0
[10060.249658] ppid:1(init), pid:16243(syno_hibernatio), dirtied inode 32223 (hibernationFull.log) on md0
[10060.249677] ppid:1(init), pid:16243(syno_hibernatio), dirtied inode 32223 (hibernationFull.log) on md0
[10060.411326] ppid:2(kthreadd), pid:884(md0_raid1), WRITE block 4980352 on sda1 (8 sectors)
[10060.411443] ppid:2(kthreadd), pid:884(md0_raid1), WRITE block 4980352 on sdb1 (8 sectors)
[12738.759698] ppid:1(init), pid:1515(syslog-ng), dirtied inode 31994 (bash_history.log) on md0
[12744.103974] ppid:2(kthreadd), pid:1405(jbd2/md0-8), WRITE block 1489328 on md0 (8 sectors)
[12744.104062] ppid:2(kthreadd), pid:884(md0_raid1), WRITE block 4980352 on sda1 (8 sectors)
[12744.104131] ppid:2(kthreadd), pid:884(md0_raid1), WRITE block 4980352 on sdb1 (8 sectors)
[12744.115108] ppid:1(init), pid:1515(syslog-ng), dirtied inode 23859 (disk.log) on md0
[12744.115484] ppid:1(init), pid:1515(syslog-ng), dirtied inode 23856 (kern.log) on md0
[12744.115895] ppid:1(init), pid:1515(syslog-ng), dirtied inode 23857 (messages) on md0
[12744.519196] ppid:1(init), pid:16243(syno_hibernatio), dirtied inode 32162 (hibernation.log) on md0
[12744.519234] ppid:1(init), pid:16243(syno_hibernatio), dirtied inode 32162 (hibernation.log) on md0
[12744.519253] ppid:1(init), pid:16243(syno_hibernatio), dirtied inode 32162 (hibernation.log) on md0
[12744.519864] ppid:1(init), pid:16243(syno_hibernatio), dirtied inode 32223 (hibernationFull.log) on md0
[12744.519899] ppid:1(init), pid:16243(syno_hibernatio), dirtied inode 32223 (hibernationFull.log) on md0
[12744.519918] ppid:1(init), pid:16243(syno_hibernatio), dirtied inode 32223 (hibernationFull.log) on md0

die alten Einträge 10060.xxx vom letzen Schreiben ins hibernationFull.log und dann die neuen 12738.xxx ff Einträge für die bash_history.log.
Man erkennt das Muster: Eine Datei auf md0 wird geschrieben, das aktive hibernation debug Logging schreibt folglich ins eigene hibernation log.

Nachdem man sich etwas mit den Logeinträgen vertraut gemacht hat, kann man weitere Zeilen herausfiltern, die in der Betrachtung keinen Mehrwert bringen.
z.B. mit
tail -f /var/log/hibernation* | grep -v "kthreadd" | grep -v "syno_hibernatio" | grep "md0"

lassen sich aktuell uninteressante Zeilen mit "kthreadd" oder "syno_hibernatio" herausfiltern, um den Blick gezielt auf die "unbekannten" Störer zu haben.


Ich hoffe, ihr konntet das alles soweit nachvollziehen und vielleicht hilft es beim Durchwühlen euerer Hibernation Logs.

Gruß, T.