問題
time.TimeのSubメソッドを利用すると、２つのtime.Time間のDurationを取得することが出来ます。
例えば↓なカンジで処理時間を計測したりします。
start := time.Now()
(何か処理)
elapsed := time.Now().Sub(start)
fmt.Println(elapsed)
このコード自体間違いではないですが、今回実行していて明らかに実際の経過時間を返していない事象に遭遇し、軽くハマりました。
9:02にスタートし9:10に終了しているのに、elapsedに 3m などと出力されたり。
startとnowも出力↓
start:2020-07-08 09:02:00.243095 +0900 JST m=+0.003321332
now:2020-07-08 09:10:25.388989 +0900 JST m=+222.388991487
elapsed:3m42.385670155s
startとnowも確かに正しい日時が入っています。何が起きているのでしょうか・・・ 🤔
（鋭い人はこのログでピンと来てそうですね）
タネあかし
ログを見ると m=+222.388991487 みたいな出力が見られます。
これの単位を秒とみなすと、nowとstartの差分がちょうどelapsedと一致します。
これは実はmonotonic clockと呼ばれるものです。time.Timeは時刻を表す情報（wall clock）とは別に時間計測に使う為の情報（monotonic clock）を持つことが出来ます。time.Now() で作成したtime.Timeは内部にmonotonic clockを持ちます。
Subメソッドの様な時間経過を得る為の関数1はwall clockよりmonotonic clockを優先的に使用して計算を行います。それにより、例えば処理中にOS時刻を変更されたりしても、正しく経過時間を取得することが出来ます。
さてここまで見る限り処理時間の計測方法としては正しいと思われる（実際正しい）のですが、なぜズレが生じてしまったのでしょうか。
公式ドキュメントにそのものズバり書かれていました(-ω-;
https://golang.org/pkg/time/#hdr-Monotonic_Clocks
On some systems the monotonic clock will stop if the computer goes to sleep. On such a system, t.Sub(u) may not accurately reflect the actual time that passed between t and u.
「いくつかのシステムではコンピューターがスリープした場合monotonic clockが停止して、t.Sub(u)が実際の経過時間を返さないことがある」とのことでした。
そうです。今回私は実行中に何度かスリープ→回復していたのです。2
明示的にwall clockで計算したい場合は、t.Sub(u)のt、uどちらかのmonotonic clock情報を削除すればOKです。
monotonic clock情報は t = t.Round(0) の様にすれば削除出来ます。
最後に
monotonic clockについては、今まで「時間計測に使用される」、「monotinic timeが違うと同時刻のt.Timeを==演算子で比較してもfalseになる」くらいの曖昧な知識しかありませんでした。
time.Timeのドキュメント見ると真っ先にmonotonic clockの説明が書かれているのに、全然読んでませんでした（猛省）。
公式ドキュメントはちゃんと読まなきゃですね。。