2015/09/01 Update

As I found recently, with the introduction of util-linux v2.20 the follow options where added: –ctime (short -T) which convert the timestamps to human readable.

2011/09/27 Original entry

Dmesg is a really useful tool to look at recent log messages from the kernel, especially when there is a problem. A while ago the option to include timestamps in kernel messages was added, which gives you a seconds since boot indication of when a message occurred.

[ 46.451673] Bluetooth: BNEP filters: protocol multicast [ 46.489223] Bluetooth: SCO (Voice Link) ver 0.6 [ 46.489224] Bluetooth: SCO socket layer initialized [ 46.890497] lp0: using parport0 (interrupt-driven). [ 46.927571] ppdev: user-space parallel port driver [ 50.376608] ttyS1: LSR safety check engaged! [ 50.439012] ttyS2: LSR safety check engaged! [ 50.451335] ttyS3: LSR safety check engaged! [14700.482957] loop: module loaded [14700.595479] ISO 9660 Extensions: Microsoft Joliet Level 3 [14700.608103] ISO 9660 Extensions: RRIP_1991A [15111.879308] CPU0 attaching NULL sched-domain. [15111.879311] CPU1 attaching NULL sched-domain. [15111.908068] CPU0 attaching sched-domain: [15111.908072] domain 0: span 0-1 level MC [15111.908075] groups: 0 1 [15111.908079] CPU1 attaching sched-domain: [15111.908081] domain 0: span 0-1 level MC [15111.908083] groups: 1 0 [15569.597056] Bluetooth: HIDP (Human Interface Emulation) ver 1.2

Although this provides good information, it is not really human readable. You can’t see at a glance if a problem is recent or not without knowing the boot time of the system.

A simple oneliner can take care of that.

gawk -v uptime=$( grep btime /proc/stat | cut -d ' ' -f 2 ) '/^[[ 0-9.]*]/ { print strftime("[%Y/%m/%d %H:%M:%S]", substr($0,2,index($0,".")-2)+uptime) substr($0,index($0,"]")+1) }'

Piping the output from dmesg through the onliner gives the following output:

[2011/09/27 07:07:05] Bluetooth: BNEP filters: protocol multicast [2011/09/27 07:07:05] Bluetooth: SCO (Voice Link) ver 0.6 [2011/09/27 07:07:05] Bluetooth: SCO socket layer initialized [2011/09/27 07:07:05] lp0: using parport0 (interrupt-driven). [2011/09/27 07:07:05] ppdev: user-space parallel port driver [2011/09/27 07:07:09] ttyS1: LSR safety check engaged! [2011/09/27 07:07:09] ttyS2: LSR safety check engaged! [2011/09/27 07:07:09] ttyS3: LSR safety check engaged! [2011/09/27 11:11:19] loop: module loaded [2011/09/27 11:11:19] ISO 9660 Extensions: Microsoft Joliet Level 3 [2011/09/27 11:11:19] ISO 9660 Extensions: RRIP_1991A [2011/09/27 11:18:10] CPU0 attaching NULL sched-domain. [2011/09/27 11:18:10] CPU1 attaching NULL sched-domain. [2011/09/27 11:18:10] CPU0 attaching sched-domain: [2011/09/27 11:18:10] domain 0: span 0-1 level MC [2011/09/27 11:18:10] groups: 0 1 [2011/09/27 11:18:10] CPU1 attaching sched-domain: [2011/09/27 11:18:10] domain 0: span 0-1 level MC [2011/09/27 11:18:10] groups: 1 0 [2011/09/27 11:25:48] Bluetooth: HIDP (Human Interface Emulation) ver 1.2

Much better readable :)