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.
{ 7 comments… read them below or add one }
I would like to see a continuation of discussions on this topic.
thanks for the tips, and info.
Cheers
Interesting site, but much advertisments on him. Shall read as subscription, rss.
Came up with this instead, it’ll print the timestamp in a useful readable format, but thanks to Jeff’s page for the inspiration for it.
date -d “-`awk ‘{print $1}’ /proc/uptime` seconds + `dmesg | grep ‘Buffer I/O’ | tail -n 1 | egrep -o ‘[0-9]+\.[0-9]+’` seconds”
Doesn’t require BC as date can do addition/subtraction for us.
It’s a shame you don’t post more often. Lots of great tips here!
Cheers,
André
Just a minor correction. I’m running RHEL5.5 (kernel 2.6.18), and it does NOT have PRINTK_TIME compiled in by default.
I use this
#!/usr/bin/perl -w
use strict;
chomp (my $uptime = `cat /proc/uptime`);
$uptime =~ s/^([\d\.]+)\s+.*/$1/;
my $time = time;
open(CMD,”dmesg|”) || die “$!\n”;
while() {
if (/^\[\s*(\d+)\.\d+\s*\]\s+(.*$)/) {
my $event = $time – ($uptime – $1);
$event = scalar(localtime($event));
print “$event: $2\n”;
} else { print; }
}
close;