[Script] Zeitstempel aus dmesg in lesbare Zeitangaben umwandeln

Jeder Linux-User mit einem aktuellen Kernel auf seiner Maschine kennt sicher die Meldungen aus dem dmesg-Buffer, die u.A. zur Bootzeit generiert werden. Aber auch nach dem Bootvorgang werden teils kritische Meldungen vom Kernel in dmesg geschrieben. Ein kleines Beispiel:

[3631596.049121] e1000: eth0: e1000_watchdog: NIC Link is Down
[3631647.485033] e1000: eth0: e1000_watchdog: NIC Link is Up 100 Mbps Full Duplex, Flow Control: RX

Es war also offenbar zu irgendeinem Zeitpunkt an diesem Server die Netzwerkverbindung für einige Zeit getrennt. Nur wann genau war das? Gestern oder vor 3 Monaten? Bei Servern, die teilweise Monate (oder gar Jahre!) am Stück laufen, ist der Zeitpunkt kaum zu erraten. Die Angabe in den eckigen Klammern vor jeder Meldung stellt die Zeit seit dem Systemstart dar, leider nicht wirklich menschlich lesbar. Klar, man könnte mittels uptime und date nun die Sekunden manuell berechnen und somit einen Zeitpunkt ermitteln. Aber eigentlich gibt es dafür ja Perl!

Das kleine Perlscript dmesg.pl erledigt die Umrechnung on-the-fly für uns. Wir bekommen dann eine verständliche Ausgabe, hier für unser obiges Beispiel:

[ Wed Jul 1 10:33:11 2009 ] e1000: eth0: e1000_watchdog: NIC Link is Down
[ Wed Jul 1 10:34:02 2009 ] e1000: eth0: e1000_watchdog: NIC Link is Up 100 Mbps Full Duplex, Flow Control: RX

Legt man nun einen Alias wie z.B. alias dmesg='perl /path/to/dmesg.pl' an (z.B. gleich in der .bashrc), bekommt man immer den lesbaren Output.

Das Script liest einfach die Uptime aus /proc/uptime in Sekunden aus und errechnet aus der aktuellen Unix-Time sowie den Einträgen aus dmesg dann den korrekten Zeitstempel. Aber Vorsicht, auf Maschinen, die bereits recht lange laufen, kommt es leider zu Differenzen. Den konkreten Grund konnte ich bisher noch nicht klären, vermutlich aber liegt es daran, dass die Kernel-Uptime nicht immer korrekt hochgezählt wird, v.A. unter Last. Ein weiterer möglicher Grund sind inkorrekte Zeitmessungen nach automatischen Taktänderungen der CPU, zumindest weist ein Bugreport auf kernel.org darauf hin. Auf meinem frisch gebooteten Linux-Laptop hingegen stimmte die Umrechnung stets zu 100%.

Falls Jemand eine andere Erklärung für die Differenzen hat oder das Script optimieren möchte, freue ich mich auf Kommentare. Die Bash-Variante war leider sehr langsam, daher die Perl-Lösung.