Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

How do I convert dmesg timestamp to custom date format?

People also ask

What is the dmesg time format?

Understanding dmesg timestamp is pretty simple: it is time in seconds since the kernel started. So, having time of startup ( uptime ), you can add up the seconds and show them in whatever format you like. Or better, you could use the -T command line option of dmesg and parse the human readable format.

What is the difference between dmesg and VAR log messages?

We can say that dmesg is the subset of /var/log/messages and is maintained in ring buffer. /var/log/messages includes all the system messages including from starting of the system along with the messages in dmesg . In a nutshell logs from dmesg are dumped in /var/log/messages .

How do I view dmesg logs?

Read dmesg Log File Each time the system boots up, the messages from the kernel ring buffer are stored in the /var/log/dmesg file. The dmesg command shows the log file contents. If you have issues using the dmesg command, open the log file in a text editor to view the contents.


Understanding dmesg timestamp is pretty simple: it is time in seconds since the kernel started. So, having time of startup (uptime), you can add up the seconds and show them in whatever format you like.

Or better, you could use the -T command line option of dmesg and parse the human readable format.

From the man page:

-T, --ctime
    Print human readable timestamps. The timestamp could be inaccurate!

    The time source used for the logs is not updated after system SUSPEND/RESUME.

With the help of dr answer, I wrote a workaround that makes the conversion to put in your .bashrc. It won't break anything if you don't have any timestamp or already correct timestamps.

dmesg_with_human_timestamps () {
    $(type -P dmesg) "$@" | perl -w -e 'use strict;
        my ($uptime) = do { local @ARGV="/proc/uptime";<>}; ($uptime) = ($uptime =~ /^(\d+)\./);
        foreach my $line (<>) {
            printf( ($line=~/^\[\s*(\d+)\.\d+\](.+)/) ? ( "[%s]%s\n", scalar localtime(time - $uptime + $1), $2 ) : $line )
        }'
}
alias dmesg=dmesg_with_human_timestamps

Also, a good reading on the dmesg timestamp conversion logic & how to enable timestamps when there are none: https://supportcenter.checkpoint.com/supportcenter/portal?eventSubmit_doGoviewsolutiondetails=&solutionid=sk92677


For systems without "dmesg -T" such as RHEL/CentOS 6, I liked the "dmesg_with_human_timestamps" function provided by lucas-cimon earlier. It has a bit of trouble with some of our boxes with large uptime though. Turns out that kernel timestamps in dmesg are derived from an uptime value kept by individual CPUs. Over time this gets out of sync with the real time clock. As a result, the most accurate conversion for recent dmesg entries will be based on the CPU clock rather than /proc/uptime. For example, on a particular CentOS 6.6 box here:

# grep "\.clock" /proc/sched_debug  | head -1
  .clock                         : 32103895072.444568
# uptime
 15:54:05 up 371 days, 19:09,  4 users,  load average: 3.41, 3.62, 3.57
# cat /proc/uptime
32123362.57 638648955.00

Accounting for the CPU uptime being in milliseconds, there's an offset of nearly 5 1/2 hours here. So I revised the script and converted it to native bash in the process:

dmesg_with_human_timestamps () {
    FORMAT="%a %b %d %H:%M:%S %Y"

    now=$(date +%s)
    cputime_line=$(grep -m1 "\.clock" /proc/sched_debug)

    if [[ $cputime_line =~ [^0-9]*([0-9]*).* ]]; then
        cputime=$((BASH_REMATCH[1] / 1000))
    fi

    dmesg | while IFS= read -r line; do
        if [[ $line =~ ^\[\ *([0-9]+)\.[0-9]+\]\ (.*) ]]; then
            stamp=$((now-cputime+BASH_REMATCH[1]))
            echo "[$(date +"${FORMAT}" --date=@${stamp})] ${BASH_REMATCH[2]}"
        else
            echo "$line"
        fi
    done
}

alias dmesgt=dmesg_with_human_timestamps

So KevZero requested a less kludgy solution, so I came up with the following:

sed -r 's#^\[([0-9]+\.[0-9]+)\](.*)#echo -n "[";echo -n $(date --date="@$(echo "$(grep btime /proc/stat|cut -d " " -f 2)+\1" | bc)" +"%c");echo -n "]";echo -n "\2"#e'

Here's an example:

$ dmesg|tail | sed -r 's#^\[([0-9]+\.[0-9]+)\](.*)#echo -n "[";echo -n $(date --date="@$(echo "$(grep btime /proc/stat|cut -d " " -f 2)+\1" | bc)" +"%c");echo -n "]";echo -n "\2"#e'
[2015-12-09T04:29:20 COT] cfg80211:   (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 0 mBm), (N/A)
[2015-12-09T04:29:23 COT] wlp3s0: authenticate with dc:9f:db:92:d3:07
[2015-12-09T04:29:23 COT] wlp3s0: send auth to dc:9f:db:92:d3:07 (try 1/3)
[2015-12-09T04:29:23 COT] wlp3s0: authenticated
[2015-12-09T04:29:23 COT] wlp3s0: associate with dc:9f:db:92:d3:07 (try 1/3)
[2015-12-09T04:29:23 COT] wlp3s0: RX AssocResp from dc:9f:db:92:d3:07 (capab=0x431 status=0 aid=6)
[2015-12-09T04:29:23 COT] wlp3s0: associated
[2015-12-09T04:29:56 COT] thinkpad_acpi: EC reports that Thermal Table has changed
[2015-12-09T04:29:59 COT] i915 0000:00:02.0: BAR 6: [??? 0x00000000 flags 0x2] has bogus alignment
[2015-12-09T05:00:52 COT] thinkpad_acpi: EC reports that Thermal Table has changed

If you want it to perform a bit better, put the timestamp from proc into a variable instead :)


In recent versions of dmesg, you can just call dmesg -T.