[20200317]dmesg与时间戳3.txt

[20200317]dmesg与时间戳3.txt

--//dmesg的输出显示的时间戳不是很精确的,网上许多链接计算使用/proc/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

--//晚上想如果我能定时插入1个时间戳,获得比较准确的时间对于分析问题有一定的帮助.至少可以参考一下。
--//如何插入呢?我使用strace跟踪很容易发现dmesg实际上是读取/dev/kmsg.但是我测试rhel 5.9 与centos 7.0不同.
--//如果直接使用cat /dev/kmsg看centos 7.0可以直接看到里面的内容.
--//而rhel 5.9不行报 invalid argument.似乎两个版本对这个缓存处理方式不同.
# cat /dev/kmsg
cat: /dev/kmsg: invalid argument

--//我直接执行 zdate >> /dev/kmsg,再使用dmesg观察,可以正常显示写入的时间戳的.
--//以下是我执行zdate >> /dev/kmsg后今天看到的情况：
--//zdate 我定义的别名。

# alias zdate
alias zdate='date +'\''%y/%m/%d %t'\'''

$ tdmesg '' 8
2020-03-16 09:47:57: [7219393.671149] device eth0 left promiscuous mode
2020-03-16 09:47:59: [7219395.849048] device eth0 entered promiscuous mode
2020-03-16 09:48:00: [7219396.305863] device eth0 left promiscuous mode
2020-03-16 10:58:25: [7223621.108505] 2020/03/16 10:55:34
2020-03-16 10:58:36: [7223632.716785] 2020/03/16 10:55:46
2020-03-16 11:11:45: [7224421.260769] 2020/03/16 11:08:56
2020-03-16 11:11:49: [7224425.731058] 2020/03/16 11:09:00
2020-03-16 11:11:50: [7224426.450256] 2020/03/16 11:09:01

--//你可以发现实际出现很大偏差。
# zdate >> /dev/kmsg
$ tdmesg '' 9
2020-03-16 09:47:58: [7219393.671149] device eth0 left promiscuous mode
2020-03-16 09:48:00: [7219395.849048] device eth0 entered promiscuous mode
2020-03-16 09:48:01: [7219396.305863] device eth0 left promiscuous mode
2020-03-16 10:58:25: [7223621.108505] 2020/03/16 10:55:34
2020-03-16 10:58:37: [7223632.716785] 2020/03/16 10:55:46
2020-03-16 11:11:46: [7224421.260769] 2020/03/16 11:08:56
2020-03-16 11:11:50: [7224425.731058] 2020/03/16 11:09:00
2020-03-16 11:11:51: [7224426.450256] 2020/03/16 11:09:01
2020-03-17 10:16:51: [7307526.307652] 2020/03/17 10:16:51
--//马上插入对照看时间基本一致。明天再看就出现误差了。这样只能定时插入时间戳，对照分析就能相对获得比较正确的时间点。
--//实际上centos 7的dmesg看也是误差很大的。

# cat /etc/redhat-release
centos linux release 7.7.1908 (core)

# dmesg -t -l | tail -3
[tue mar 17 10:29:37 2020] 2020/03/17 10:19:12
[tue mar 17 10:30:34 2020] 2020/03/17 10:20:08
[tue mar 17 10:30:37 2020] 2020/03/17 10:20:12
--//对比时间相差 10分钟+25秒。 大约625秒

--//使用我写的脚本测试：
# tdmesg '' 3
2020-03-17 10:19:11: [1295232.409194] 2020/03/17 10:19:12
2020-03-17 10:20:08: [1295289.078426] 2020/03/17 10:20:08
2020-03-17 10:20:11: [1295292.485899] 2020/03/17 10:20:12
--//基本接近。

# egrep  "sched_clk|ktime|cpu_clk" /proc/sched_debug
ktime                                   : 1294875872.314080
sched_clk                               : 1295502651.262182
cpu_clk                                 : 1295502651.262218

--//(1295502651.262182-1294875872.314080)/1000 = 626.778948102
--//基本接近。也就是dmesg -t也是使用 类似 /proc/uptime作为基准的，这样开机运行时间越长误差越大。

--//这样就很简单了,利用crond定时执行，每小时执行1次。注意百分号前面的\不然不能正确执行。
--//在crontab中%字符被认为是换行，所以你的命令中有%时，在crontab中要加\转义
$ man 5 crontab
the "sixth" field (the rest of the line) specifies the command to be run.  the entire command portion of the line, up to
a newline or % character, will be executed by /bin/sh or by the shell specified in the shell variable of the  cronfile.
percent-signs (%) in the command, unless escaped with backslash (\), will be changed into newline characters, and all
data after the first % will be sent to the command as standard input.

# cat /etc/cron.d/dmesg
0 * * * * root /bin/date +"\%y/\%m/\%d \%t"  >> /dev/kmsg

--//这样写入这个时间戳是准确的,这样再结合前面的脚本,分析误差就不会太大.当然误差还是存在的.
--//不知道这样武断的写法有什么问题不妥,有待在测试环境观察.