[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