プログラマ探偵の事件簿:精度の低い時計がログを消す
助手の猫の予感があたった事件である。
事件のはじまり
GitHUBに届いた1件のTWSNMP FCに関する問い合わせから始まった。
不思議なこともあるものだと思ったが、私は使っている人の勘違いだろうと思っていた。しかし助手の猫は「プログラマー探偵の出番では?」と言っていた。
証拠を集める
話だけでは調べようがないので証拠のなるログを送ってもらった。
なんと、使っている人の勘違いではなさそうである。
たしかに、
が発生している。
通知のリストに載っていないものはログにも記録されてないメール通知をする仕組みの問題ではなさそうである。障害が発生したことをログに記録できないことが原因のようである。この時点で少し真相に近づいていた。
助手の猫もやる気がでてきたようだ。
私を混乱させた情報
問い合わせをした人から、
と
という情報があった。
またまた、私は使っている人の勘違いではと思い始めた。TWSNMP FCが動作する監視サーバーを再起動しているのかと思ったからだ。再起動している間のログが記録されていない。そのことを問い合わせをしてきた人に聞いて調べるのは待とうと思った。しかし、助手の猫は「プログラマー探偵の出番では?」と言い続けている。
週末の休みになった。
イベントログが消える原因
週が開けてから
という回答があった。私の勘違いであった。助手の猫が「そらみろ、プログラマー探偵の出番だろ。ちゃんと、もう一度、ソースコードを調べろ!」と言った。
一つの仮説
助手の猫に言われるまま、ソースコードを見直した。最初は多数のログを保存した時に溢れて一部抜けるのかと思ったが、その可能性低い。
深くまでソースコードを見ていると「ログを保存するキーのところが怪しい」と助手の猫が言った。なるほど、一つの仮説が浮かんだ。
ログをデータベースに保存する時に、ログを識別するキーを時刻から作っている。もし、同時刻のキーが連続するとログは失われる。簡単に言うと
00:03:00.00000000001のログは1件だだけしか保存できない仕組みなのである。プログラム上は10億分の1秒単位の時刻でキーを作成している、これが重なることなどありえないように思える。
時計の精度を現場検証
10億分の1秒単位の時刻が重なる可能性をテストプログラムを作って現場検証してみた。
package main
import (
"log"
"time"
)
func main() {
i := 0
st := time.Now()
for st.UnixNano() == time.Now().UnixNano() {
i++
}
log.Printf("%d %v", i, time.Since(st))
}
プログラムが動作するコンピュータの時計を読んで10億分の1秒単位の時刻が同じであった回数をカウントしている。カウントが10だったら、10回見る間、針は動かなかったということである。
コンピュータの時計の精度(解像度)が低いか、コンピュータのCPUが後続ならカウントが大きくなる。カウントが大きくなるコンピュータ上で今回の問題のログのためのキーを作成すると同じ値になる(重複する)可能性が高いということである。
安いPCで動かしているLinuxでは常に0である。
開発用にMacでは、大きくて7ぐらいである。0の時もある。
Windows環境では、なんと10000以上になる。WIndowsの時計の精度は他より良くないのであろう。
解決
高速なCPUのWindows環境だとログのキーが同じになる確率が高く、これが原因でログが消えていたのである。キーが同じ値にならないように値をずらして保存するように対策して解決した。
プログラム上で10億分の1秒単位と書いても実際には違っていたのである。
助手の猫から一言
「プログラム上に見えているものは、真実ではない!」
まったく、その通りである。自分の勘違いも反省しなければ。
開発のための諸経費(機材、Appleの開発者、サーバー運用)に利用します。 ソフトウェアのマニュアルをnoteの記事で提供しています。 サポートによりnoteの運営にも貢献できるのでよろしくお願います。