Timestamps are a wonderful thing. When you have systems with an uptime of hundreds of days or more, knowing when an event happened can go a long way. This post will show you how to enable and use Linux kernel printk timestamps effectively. Printk is a Linux kernel function used to send messages to the kernel log ring buffer. This is most commonly read with dmesg(1).
Enable CONFIG_PRINTK_TIME=y if you are building a custom kernel and want this feature. Most major Linux distributions enable this by default. Verify your kernel has printk time enabled like this:
jeff@beastmaster:~$ grep CONFIG_PRINTK_TIME /boot/config-$(uname -r) CONFIG_PRINTK_TIME=y jeff@beastmaster:~$ head -n1 /etc/issue Ubuntu 8.10 \n \l
Ubuntu enables timestamps by default. Some distributions such as Redhat Enterprise Linux configure their kernel to enable CONFIG_PRINTK_TIME=y, but don't enable timestamps by default. Setting it up requires some changes to the bootloader and a reboot. For CentOS / RHEL just add "time=1" to the kernel command line in /boot/grub/menu.lst and reboot.
The "time" kernel boot option was removed from the 2.6.25 kernel and superseded by "printk.time".
Enough background, lets look at how this is useful and go from there. We'll first look for a disk error.
jeff@desktopmonster:~/bin$ dmesg | grep 'Buffer I/O' | tail -n 1 [337567.060046] Buffer I/O error on device sr0, logical block 0
337567.060046 is the time in seconds.nanoseconds in relation to system uptime the Buffer I/O error happened. Breaking down exactly when this happened requires a bit of math. There are 60 seconds in 1 minute, 60 minutes in 1 hour, and 24 hours in 1 day. Figuring out when this error occurred is simple with a bit of math and our good friend bc(1). The first field of /proc/uptime is the system uptime according to proc(5) in the format of seconds.microseconds. The key is to subtract the two and divide by the time you want.
jeff@desktopmonster:~/bin$ dmesg | grep 'Buffer I/O' | tail -n 1 | egrep -o '[0-9]+\.[0-9]+'
337567.060046
jeff@desktopmonster:~/bin$ echo "$(awk '{print $1}' /proc/uptime) - $(dmesg | grep 'Buffer I/O' | tail -n 1 | egrep -o '[0-9]+\.[0-9]+')" | bc # Seconds
103376.359954
jeff@desktopmonster:~/bin$ echo "($(awk '{print $1}' /proc/uptime) - $(dmesg | grep 'Buffer I/O' | tail -n 1 | egrep -o '[0-9]+\.[0-9]+')) / 60" | bc # Minutes
1723
jeff@desktopmonster:~/bin$ echo "($(awk '{print $1}' /proc/uptime) - $(dmesg | grep 'Buffer I/O' | tail -n 1 | egrep -o '[0-9]+\.[0-9]+')) / 60 / 60" | bc # Hours
28
jeff@desktopmonster:~/bin$ echo "($(awk '{print $1}' /proc/uptime) - $(dmesg | grep 'Buffer I/O' | tail -n 1 | egrep -o '[0-9]+\.[0-9]+')) / 60 / 60 / 24" | bc # Days
1
Using this info we see that the error happened 28 hours ago. Now you can go complain to your datacenter technician for bumping your server when running new cables to another server.
{ 5 comments }
