[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

--//這樣寫入這個時間戳是準確的,這樣再結合前面的指令碼,分析誤差就不會太大.當然誤差還是存在的.
--//不知道這樣武斷的寫法有什麼問題不妥,有待在測試環境觀察.