[20200316]dmesg与时间戳2.txt

[20200316]dmesg与时间戳2.txt

--//链接提到http://blog.itpub.net/267265/viewspace-2670625/=> 计算的时间戳有问题,一直没仔细探究.
--//网上找到链接 https://stackoverflow.com/questions/13890789/convert-dmesg-timestamp-to-custom-date-format

"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.

--//金山词霸的翻译:
--//lucas-cimon早些时候提供的"dmesg_with_human_timestamps"功能。 我们的一些箱子有点麻烦但时间很长。 结果发现，dmesg中的内核
--//时间戳源自个人保存的一个实时值中央处理器。 随着时间的推移，这与实时时钟不同步。 因此，最近最准确的换算网格条目将基于
--//CPU时钟而不是/proc/uptime。

# tcpdump -i eth0 host 111.111.111.111;egrep 'ktime|_clk' /proc/sched_debug  ;cat /proc/uptime ; dmesg | tail -1
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 96 bytes
^C
0 packets captured
0 packets received by filter
0 packets dropped by kernel
--//egrep 'ktime|_clk' /proc/sched_debug 的输出.
ktime                                   : 6999352247.900510
sched_clk                               : 6985090278.168152
cpu_clk                                 : 6985090278.168226
6999352.25 167786614.36                             ===> /proc/uptime的输出
[6985090.265779] device eth0 left promiscuous mode  ===> dmesg的输出

--//很明显应该是拿cpu_clk/1000 或者 sched_clk/1000 = 6985090278.168152/1000 = 6985090.278168152 时间写入kernel ring buffer.
--//ktime/1000 = 6999352247.900510/1000 = 6999352.24790051 与/proc/uptime 接近。
--//国内许多链接使用/proc/uptime计算,随着机器uptime时间增加，误差会越来越大。
--//链接提供脚本如下:
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

--//这个版本在centos 7下执行没有问题,但是在Oracle Linux Server release 5.9的bash下运行匹配失败,原样输出.
--//BASH 版本是3.2.25(1)-release.顺便说一下这个版本的bash bug实在太多了.
--//我修改如下,满足中文输出需要,并且取消匹配判断(太麻烦了)

$ cat $(which tdmesg)
#! /bin/bash
FORMAT="%Y-%m-%d %T:"

now=$(date +%s)
cputime=$(grep -m1 "sched_clk" /proc/sched_debug | cut -f2 -d: )
uptime=$(grep -m1 "ktime" /proc/sched_debug | cut -f2 -d: )

# echo $now $cputime $uptime

dmesg|  while  read -r line; do
    offset=$( echo $line | cut -d"]" -f1 | tr -d "[")
    stamp=$( echo $now - $cputime / 1000 + $offset  | bc -l )
    echo "$(date -d "1970-01-01 00:00:00 UTC $stamp seconds" +"${FORMAT}") $line"
    #echo "$(date -d "@${stamp}" +"${FORMAT}") $line"
done

--//简单验证看看:

# zdate;tcpdump -i eth0 host 111.111.111.111; dmesg | tail -2;zdate ; tdmesg | tail -2
2020/03/16 09:30:43
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 96 bytes
^C
0 packets captured
0 packets received by filter
0 packets dropped by kernel
[7218540.683030] device eth0 entered promiscuous mode
[7218541.097668] device eth0 left promiscuous mode
2020/03/16 09:30:44
2020-03-16 09:30:43: [7218540.683030] device eth0 entered promiscuous mode
2020-03-16 09:30:43: [7218541.097668] device eth0 left promiscuous mode

--//最后说明一下,可以想像实际上这个时间戳越离开当前时间误差越大,正如man dmesg文档介绍:

-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.,

--//centos 7以后版本可以使用-T参数代替.-L

--//实际上上面执行很慢，我修改如下，加入tail 缺省显示50行。加入参数uptime，可以按uptime计算。
--//不想在细节上浪费时间。

# cat $(which tdmesg )
#! /bin/bash
FORMAT="%Y-%m-%d %T:"

now=$(date +%s)
cputime=$(grep -m1 "sched_clk" /proc/sched_debug | cut -f2 -d: )
uptime=$(grep -m1 "ktime" /proc/sched_debug | cut -f2 -d: )

# echo $now $cputime $uptime

if [ "$1" == "uptime" ] ; then
        cputime=$uptime
else
        cputime=$cputime
fi

dispnum=${2:-50}

#echo $dispnum

dmesg| tail -${dispnum} | while  read -r line; do
    offset=$( echo $line | cut -d"]" -f1 | tr -d "[")
    stamp=$( echo $now - $cputime / 1000 + $offset  | bc -l )
    #echo "$(date -d "1970-01-01 00:00:00 UTC $stamp seconds" +"${FORMAT}") $line"
    echo "$(date -d "@${stamp}" +"${FORMAT}") $line"
done

--//验证如下：
# zdate;tcpdump -i eth0 host 111.111.111.111; dmesg | tail -2;zdate ; tdmesg cputime 2
2020/03/16 09:45:00
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 96 bytes
^C
0 packets captured
0 packets received by filter
0 packets dropped by kernel
[7219395.849048] device eth0 entered promiscuous mode
[7219396.305863] device eth0 left promiscuous mode
2020/03/16 09:45:01
2020-03-16 09:45:00: [7219395.849048] device eth0 entered promiscuous mode
2020-03-16 09:45:00: [7219396.305863] device eth0 left promiscuous mode