終了時刻から開始時刻を引いただけなのに、なぜ処理時間がマイナスになるのか?
処理時間を測るとき、start = Time.now と書いて最後に Time.now - start を引く。誰もが一度は書いたコードだ。ところがある日、ログに duration=-0.8s が出たり、5 秒のはずのタイムアウトが一瞬で発火したりする。時計は前にしか進まないはずなのに、なぜ引き算が負になるのだろうか。
- OS には「今が何時か」を表す壁時計(
CLOCK_REALTIME)と、「どれだけ経ったか」だけを表すモノトニッククロック(CLOCK_MONOTONIC)の 2 種類がある。 - 壁時計は NTP や手動設定で後ろへ飛びうるため、2 つの時刻の差は負にも巨大にもなる。モノトニッククロックは飛ばないが、値そのものに日時としての意味はない。
- 経過時間・タイムアウト・レート計算はモノトニック、ログやDBに残す「いつ」は壁時計、と使い分ける。Go は
time.Now()が両方を持つが、UTC()や JSON 化で片方が消える点に注意する。
コンピュータの「時計」は 1 つではない
Linux の clock_gettime(2) は、引数で読む時計を選ばせる。代表が 2 つある。CLOCK_REALTIME は「壁時計」、つまり 1970-01-01 からの経過として表した現在時刻で、man ページは「設定可能な」時計であり、時刻の不連続なジャンプの影響を受けると明記している。CLOCK_MONOTONIC は「過去のある不定の時点からの経過時間」で、設定不可能であり、そうしたジャンプの影響を受けない。
モノトニッククロック(monotonic clock)とは、値が決して減らないことを保証する時計だ。代わりに、値の起点は「過去のどこか」でしかなく、Linux ではおおむね起動時刻に近いが仕様上は決まっていない。そのため CLOCK_MONOTONIC の値を見ても「何時何分か」は分からないし、別のマシンの値と比べても意味がない。
多くの言語の「現在時刻を返す関数」は壁時計を読んでいる。Ruby の Time.now、JavaScript の Date.now()、Python の time.time() がそうだ。つまり冒頭の Time.now - start は「2 回読んだ壁時計の差」であり、その間に壁時計が動かされればそのぶん結果がずれる。
壁時計はなぜ後ろへ飛ぶのか
マシンの水晶発振器は少しずつ進んだり遅れたりするため、OS は NTP(Network Time Protocol: ネットワーク越しに正確な時刻源と照合して時計を合わせるプロトコル)で補正し続けている。補正のやり方は 2 つある。ずれの分だけ時計を一気に書き換えるステップと、時計の進む速さをわずかに変えて徐々に追いつかせるスルー(slew)だ。ステップで時計が遅れ側に直されると、壁時計は過去へ戻る。
chrony(Linux で広く使われる NTP 実装)の設定では、この振る舞いを makestep で決める。ドキュメントの例 makestep 0.1 3 は「ずれが 0.1 秒を超えていれば、起動後最初の 3 回の更新に限ってステップする」という意味で、それ以降はスルーだけで補正する。起動直後に大きくずれた時計を素早く直しつつ、稼働中のアプリの足元で時計が飛ぶのを避けるための折衷だ。
# /etc/chrony.conf # 起動直後の 3 回だけ、0.1 秒超のずれを一気に修正 makestep 0.1 3 # 3 回目以降の大きなずれはスルーで少しずつ直す
ただし、この設定で守られるのは chrony 自身の補正だけだ。管理者の date -s、VM のスナップショット復元やライブマイグレーション後の時刻同期、手で入れた設定ミスなど、壁時計を動かす経路はほかにもある。アプリ側で「壁時計は飛ばない」と仮定できる場面は思ったより少ない。
start ─(実際の経過は 0.2 秒)─▶ end
REALTIME(壁時計)
10:00:00.0 ──┐
│ 途中で NTP が 1 秒戻す
└──▶ 09:59:59.2
end - start = -0.8 秒 ✗
MONOTONIC
5000.0 ──────────▶ 5000.2
end - start = +0.2 秒 ✓
壁時計は駅のホームの時計、モノトニッククロックはキッチンタイマーだ。ホームの時計は正確な時刻を示すために係員がときどき針を合わせ直すので、針を戻した瞬間をまたいで「何分待ったか」を引き算すると狂う。キッチンタイマーは今が何時かは教えてくれないが、押してからの経過だけは誰にも触られずに数え続ける。電車の発車時刻を記録するならホームの時計、ラーメンの 3 分を測るならタイマーを使う。
実際に起きた事故: うるう秒と負の RTT
これは机上の話ではない。Cloudflare は 2017 年 1 月 1 日 0 時(UTC)のうるう秒で DNS 障害を起こし、その原因を公開している。自社 DNS サーバー RRDNS が上流リゾルバまでの往復時間を rtt := time.Now().Sub(start) で測っていたところ、うるう秒の処理で時計が戻った瞬間に rtt が負になった。その値が乱数関数 rand.Int63n() に渡り、負の引数で panic したことで、ピーク時に DNS クエリのおよそ 0.2% が影響を受けた。
当時の Go の time.Now() は壁時計しか持っていなかった(Cloudflare の報告もこの欠如を議論する Go の issue 12914 に触れている)。その後 Go 1.9 で time パッケージは各 Time 値の中でモノトニック時刻を透過的に追跡するようになった。リリースノートは、これで壁時計の調整があっても 2 つの Time 間の差の計算が安全になったと説明している。
なお、うるう秒で時計を戻さない対策として「スミア(smear)」がある。Google の公開 NTP は、うるう秒の 1 秒を正午から翌日正午までの 24 時間に線形に溶かし込み、時計の進む速さを約 11.6 ppm だけ変えてやり過ごす。ステップの代わりに長いスルーを使う発想だ。
Go は自動で守ってくれる、ただし条件付きで
Go 1.9 以降の time.Now() は壁時計とモノトニック時刻の両方を読み、1 つの Time に詰めて返す。両方の値がモノトニック時刻を持っていれば、Sub・Before・After・Equal はモノトニック側だけで計算する。だから time.Since(start) と書けば、途中で壁時計が戻っても経過時間は負にならない。
これで一件落着に思える。しかし実際は、モノトニック時刻は思いのほか簡単に剥がれ落ちる。パッケージドキュメントによれば、t.UTC()・t.In()・t.Local()・t.Round()・t.Truncate() は結果からモノトニック時刻を取り除き、MarshalJSON などのシリアライズでも省かれる。time.Parse や time.Unix で作った値にはもともと無い。片方でもモノトニック時刻を持たない値との Sub は、黙って壁時計同士の引き算に戻る。
start := time.Now().UTC() // ✗ ここでモノトニック時刻が消える doWork() d := time.Since(start) // 壁時計の差。負になりうる start := time.Now() // ✓ そのまま持つ doWork() d := time.Since(start) // モノトニックの差
典型的な落とし穴は「ジョブの開始時刻を UTC に揃えて構造体に入れ、後で time.Since する」パターンや、開始時刻を Redis や DB に保存して別プロセスで差を取るパターンだ。後者はそもそもモノトニック時刻がプロセス(起動)をまたいで意味を持たないので、壁時計で測るしかない。その場合は負の値や異常に大きい値が来る前提で、ゼロに丸める・捨てるといった防御を入れておく。
Ruby・JavaScript・Python では明示的に選ぶ
Go 以外の主要言語は、壁時計とモノトニッククロックを別の API として提供している。経過時間を測るときはモノトニック側を自分で呼ぶ必要がある。
# Ruby(単位の既定は :float_second) t0 = Process.clock_gettime(Process::CLOCK_MONOTONIC) work elapsed = Process.clock_gettime(Process::CLOCK_MONOTONIC) - t0 // JavaScript const t0 = performance.now(); work(); const elapsedMs = performance.now() - t0; # Python t0 = time.monotonic() work() elapsed = time.monotonic() - t0
Ruby の Process.clock_gettime は第 2 引数で単位を選べ、整数ナノ秒が欲しいときは :nanosecond を渡す。JavaScript の performance.now() は MDN によれば timeOrigin 起点のモノトニックな値で、システム時計の調整を受けない。一方で、タイミング攻撃対策のため分解能は意図的に粗くされている(クロスオリジン分離されていない文書では 100 マイクロ秒)。
もう 1 つの注意点は、モノトニッククロックも「正確」とは限らないことだ。man ページによれば CLOCK_MONOTONIC は飛ばない代わりに NTP の周波数調整(スルー)の影響は受け、またシステムのサスペンド中は進まない。サスペンド時間も含めたい場合は CLOCK_BOOTTIME、周波数調整すら受けない生のハードウェア時刻が欲しい場合は CLOCK_MONOTONIC_RAW がある。サーバーの処理時間計測なら、通常は CLOCK_MONOTONIC で十分だ。
最初に疑うべきは、自前で書いた計測・タイムアウトのコードだ。Rails のサービスオブジェクトで Time.now を引き算してメトリクスに送っていると、時刻補正のたびにヒストグラムへ負の値や外れ値が混ざる。リトライの待ち時間やレートリミッタのトークン補充を壁時計で計算していると、時計が進んだ瞬間に大量のトークンが補充され、戻った瞬間には補充が止まる。どれも「普段は正しく、まれに説明のつかない値が出る」形で現れるので、ログに負の duration を見つけたら時計の種類を確認するとよい。逆に、ログのタイムスタンプ・created_at・JWT の exp のように「いつ」を他のマシンや人と共有する値には壁時計を使う。こちらはモノトニッククロックでは代わりが利かない。
Go の Time がモノトニック時刻を持っていること、そして UTC() と JSON 往復でそれが消えることを、文字列表現の m=+... で確かめる。
mkdir -p /tmp/monoclock && cd /tmp/monoclock
cat > main.go <<'EOF'
package main
import (
"encoding/json"
"fmt"
"time"
)
func main() {
t := time.Now()
fmt.Println("Now :", t)
fmt.Println("UTC() :", t.UTC())
b, _ := json.Marshal(t)
var u time.Time
json.Unmarshal(b, &u)
fmt.Println("JSON :", u)
}
EOF
go run main.go
python3 -c "import time;print(time.get_clock_info('time'));print(time.get_clock_info('monotonic'))"
Now の行だけ末尾に m=+0.000... が付き、UTC() と JSON 往復後の行には付かないはずだ。付いていない値を使って Sub すると壁時計の差になる。Python の出力では、time 側が adjustable=True(外部から調整されうる)、monotonic 側が adjustable=False と表示され、2 つが別の時計だと分かる。
- NTP で同期していれば時刻は戻らない — NTP 自体が時計を合わせる仕組みであり、設定次第でステップ補正をする。手動設定や VM の復元など NTP 以外の経路でも壁時計は動く。
- モノトニッククロックなら別サーバー間でも比較できる — 起点は各マシン(各起動)で異なる「過去のどこか」なので、プロセスやホストをまたいだ差には使えない。サービス間で共有する時刻には壁時計を使い、ずれを許容する設計にする。
- Go の
time.Sinceはどんな値を渡しても安全 — 安全なのは両方の値がモノトニック時刻を持つときだけだ。UTC()やRound、シリアライズを経た値では壁時計の差に戻る。
- 壁時計(CLOCK_REALTIME)
- 1970 年起点の現在時刻を表す OS の時計。設定や NTP によって前後に飛びうる。
- モノトニッククロック(CLOCK_MONOTONIC)
- 値が決して減らない経過時間専用の時計。起点は不定で、日時としての意味はない。
- NTP
- ネットワーク越しの時刻源と照合してマシンの時計を合わせるプロトコル。
- ステップ / スルー
- 時計の補正方法。ステップは一気に書き換え、スルーは進む速さを変えて徐々に合わせる。
- うるう秒スミア
- うるう秒の 1 秒を長時間に薄めて溶かし込み、時計を飛ばさずにやり過ごす手法。
- clock_gettime(2) — Linux manual page — REALTIME / MONOTONIC / BOOTTIME / MONOTONIC_RAW の違いが一次情報で並んでいる。
- Go time パッケージ: Monotonic Clocks — どの操作がモノトニック時刻を使い、どの操作で剥がれるかの正確な一覧。
- How and why the leap second affected Cloudflare DNS — 壁時計の引き算が本番障害になった経緯を、コード片付きで追える事後報告。
- Google Public NTP: Leap Smear — うるう秒を 24 時間に溶かす具体的な方式と、その副作用の説明。