0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

Go 1.27のUUIDv7を10秒間生成し続けたら、8秒先の時刻が入っていた

0
Posted at

Go 1.27でuuidが標準ライブラリに入ります。
uuid.NewV7()が返す値は先頭48bitがunixミリ秒なので、IDだけ見れば作成時刻が読めます。
その時刻を画面表示や時間範囲の抽出に使うつもりなら、実装を1箇所変えておいたほうがいいです。
索引の局所性のためだけにv7を選んでいるなら実害はないので、読み飛ばして構いません。

高い頻度で並行生成すると、埋め込まれた時刻が実時刻より先へ進みます。
手元では4ゴルーチンで10秒間生成し続けたところ8.0秒先まで進み、生成を止めてから実時刻が追いつくまでにさらに8.0秒かかりました。
仕様違反ではありません。
RFC 9562が明示的に許している挙動で、報告されたissueもその理由でcloseされています。
それでも、この値を作成時刻として読むのは止めたほうがいい。

検証環境は次のとおりです。

$ go version
go version go1.27rc2 linux/amd64
$ grep -m1 "model name" /proc/cpuinfo
model name	: Intel(R) Core(TM) i7-14700F     # 20 論理コア
$ go list -m github.com/google/uuid
github.com/google/uuid v1.6.0                 # 比較対象

OSはUbuntu 24.04.4 LTS(WSL2、カーネル6.6.87.2-microsoft-standard-WSL2)です。
Go 1.27はまだ正式リリース前ですが、go.modgo 1.27rc2と書けばGOTOOLCHAINが勝手に取ってくるのでgotipは要りません。

4096という数字はどこから来るのか

RFC 9562のv7は、先頭48bitにunixミリ秒を置き、残りを乱数にします。
ミリ秒より細かい順序は規定されていないので、素のv7は同一ミリ秒内に複数生成した時点で順序が壊れます。

RFCはこれを補う方法を3つ挙げていて、そのうちの1つが「乱数領域の先頭をサブミリ秒精度の時刻で置き換える」ものです。
Goはこれを採り、rand_aの12bitを1/4096ミリ秒の目盛りとして使います。

12bitで1ミリ秒を割るので、1目盛りは1000000/4096ナノ秒、つまり244.140625ナノ秒です。
以降に出てくる数字はほぼ全部この値の倍数で、ここさえ押さえれば残りは算術になります。

実際に生成した1個を桁ごとに割ると、こうなります。

uuid-v7-layout.png

3番目のかたまりの7がバージョンで、続く979が1ミリ秒を4096分割した位置です。
16進の979は10進で2425なので、この1個はミリ秒の頭から0.592ミリ秒の地点を指しています。

273行の中の、待たない分岐

src/uuid/uuid.goは273行しかありません。
NewV7の中心はこれだけです(コメントは私が付けたものです)。

now := time.Now()                      // 実時刻を取る
secs := uint64(now.Unix())             // 秒
nanos := uint64(now.Nanosecond())      // 秒内のナノ秒
msecs := nanos / 1000000               // ミリ秒成分
frac := nanos - (1000000 * msecs)      // ミリ秒内の余り
timestamp := (1000*secs + msecs) << 12 // 48bit のミリ秒を 12bit ぶん左へ寄せる
timestamp += (frac * 4096) / 1000000   // 余りを 1/4096 ミリ秒の目盛りに換算して足す

if v7lastSecs > secs {
	// 時計が巻き戻った場合。直前までの値を無視する
} else if timestamp <= v7lastTimestamp {
	timestamp = v7lastTimestamp + 1 // 直前と同じか古いなら 1 目盛り進める
}

最初、私はこの12bitをカウンタだと思い込んで読んでいました。
そのつもりで生成した値を並べたら3847, 3967, 3972, 3974と増え方が不均一で、+1ずつ進まないなら乱数で初期化でもしているのかと疑って一度手が止まりました。
答えは単純で、ここはカウンタではなく実時刻のサブミリ秒成分そのものです。
1目盛り244ナノ秒の実時刻を読んでいるだけなので、不均一で当たり前でした。

挙動を決めているのは後半のelse ifです。
直前と同じか古い値になったとき、次の目盛りが来るのを待たずにv7lastTimestamp + 1で先へ進みます。
上限のチェックはなく、実時刻へ引き戻す処理もありません。

v7lastTimestampはパッケージ変数で、v7muというグローバルなミューテックスで守られています。
単調性がプロセス内に限られるのはこのためで、別プロセスや別ホストとの間では何も保証されません。

1本で回している限りは何も起きない

まず生成コストを測りました。
-count 3の中央値です。

ns/op B/op allocs/op
標準NewV4 214.6 0 0
標準NewV7 252.7 0 0
google/uuid NewRandom 240.3 16 1
google/uuid NewV7 297.0 16 1

標準ライブラリのほうが速く、確保もゼロです。
google/uuid側の1回16バイトがどこから来ているかはエスケープ解析を見ただけでは分からず、この記事の本筋から外れるのでそれ以上は追っていません。

移行で効いてくるのは速度よりAPIの差です。
標準ライブラリの生成関数はerrorを返さないので、NewRandomから置き換えるとエラー処理がまるごと消えます。

この252.7ナノ秒を、先ほどの目盛り244.140625ナノ秒と並べてみます。
差は8.6ナノ秒しかありません。
1ゴルーチンで回している限りは実時刻のほうがわずかに速く進むのでelse ifはほとんど成立しませんが、偶然にしては際どい数字です。

境界はゴルーチンの本数ではなかった

ワーカ数を変えて、埋め込まれた時刻と実時刻の差を測ります。
go.modgo 1.27rc2と書いてgo run .で動きます。

package main

import (
	"encoding/binary"
	"fmt"
	"sync"
	"time"
	"uuid"
)

const nsPerTick = 1000000.0 / 4096 // 12bit で 1ms を割った 1 目盛り。244.140625ns

// v7 の先頭 8 バイトから 60bit のタイムスタンプを取り出す
func stamp(u uuid.UUID) uint64 {
	hi := binary.BigEndian.Uint64(u[0:8])
	return (hi>>16)<<12 | (hi & 0x0fff) // ver の 4bit を飛ばして ms とサブミリ秒を連結する
}

// 現在時刻を同じ目盛りに変換する
func nowStamp() uint64 {
	t := time.Now()
	frac := uint64(t.Nanosecond()%1000000) * 4096 / 1000000 // ミリ秒内のナノ秒を目盛りに換算する
	return uint64(t.UnixMilli())<<12 | frac
}

// 目盛りの差をミリ秒に直す
func driftMs(a, b uint64) float64 { return (float64(a) - float64(b)) * nsPerTick / 1e6 }

func main() {
	const perWorker = 250000 // ワーカあたりの生成数。合計はワーカ数に比例する
	fmt.Printf("1 目盛り = %.6f ns\n\n", nsPerTick)

	for _, workers := range []int{1, 2, 3, 4} {
		peaks := make([]uint64, workers) // ワーカごとに最後に見た値を置く
		var wg sync.WaitGroup
		start := time.Now()
		for w := 0; w < workers; w++ {
			wg.Add(1)
			go func(w int) {
				defer wg.Done()
				var local uint64 // 共有スライスへの毎回の書き込みを避ける
				for i := 0; i < perWorker; i++ {
					local = stamp(uuid.NewV7()) // 単調なので最後の値が最大になる
				}
				peaks[w] = local
			}(w)
		}
		wg.Wait()
		elapsed := time.Since(start)

		var peak uint64
		for _, p := range peaks { // 全ワーカ中の最大値を取る
			if p > peak {
				peak = p
			}
		}
		n := workers * perWorker
		fmt.Printf("ワーカ %d 本: %7d 個 %6v %6.1f ns/op ずれ %+8.1f ms\n",
			workers, n, elapsed.Round(time.Millisecond),
			float64(elapsed.Nanoseconds())/float64(n), driftMs(peak, nowStamp()))

		// v7lastTimestamp はパッケージ変数なので、実時刻が追いつくまで待たないと次の計測に持ち越される
		for driftMs(peak, nowStamp()) > 0 {
			time.Sleep(10 * time.Millisecond)
		}
	}
}

3回実行したうちの2回目です。

1 目盛り = 244.140625 ns

ワーカ 1 本:  250000 個   63ms  252.2 ns/op ずれ     -0.0 ms
ワーカ 2 本:  500000 個  122ms  243.7 ns/op ずれ     +0.3 ms
ワーカ 3 本:  750000 個  127ms  168.8 ns/op ずれ    +56.5 ms
ワーカ 4 本: 1000000 個  173ms  173.4 ns/op ずれ    +70.8 ms

2本のときだけ、3回の実行で結果が毎回入れ替わりました。

実行 ns/op ずれ
1回目 186.9 +28.7 ms
2回目 243.7 +0.3 ms
3回目 253.5 -0.0 ms

本数は同じなのに、なぜ揃わないのか。
1個あたりのコストが244.140625ナノ秒の線をまたいでいて、下回った回だけずれています。
つまり「ゴルーチン何本で壊れる」という数え方に意味はなく、条件は1個あたりが244ナノ秒を切るかどうかだけです。
本数はそこへ到達するための手段でしかありませんでした。

3本以上は毎回160〜175ナノ秒に収まるので、ずれは安定して出ます。

10秒の負荷で8秒ずれ、戻るのに8秒かかる

4ワーカで10秒間生成し続け、1秒ごとにずれを記録しました。

  t=1   s generated=7389184     drift= +804.379 ms
  t=2   s generated=14880768    drift=+1633.626 ms
  t=3   s generated=22343680    drift=+2455.871 ms
  t=5   s generated=37122048    drift=+4064.639 ms
  t=10  s generated=73900032    drift=+8043.227 ms
  停止時のドリフト: +8045.007 ms
  実時刻が追いつくまで: 8.049s
  復帰後の1個のドリフト: -0.002 ms

0.5秒ごとに記録した別の実行を、停止後まで通して並べたのが次の図です。

uuid-v7-drift-profile.png

10秒で7390万個生成し、埋め込まれた時刻は8.04秒先まで進みました。
1秒あたり約805ミリ秒の割合で伸び続け、頭打ちになる気配はありません。
3回実行して停止時のずれは8.05秒・7.72秒・7.96秒で、傾きは変わりませんでした。

頭打ちにならないのは、else ifの作りが単純だからです。
成立している間は1個生成するごとにタイムスタンプが1目盛り、つまり244.140625ナノ秒ぶん進みます。
生成の間隔がこれより短ければタイムスタンプ空間を実時間より速く消費することになり、差は生成した個数に比例して開き続けます。
止める仕組みはコードのどこにもありません。

4ゴルーチンの実測値173.4ナノ秒で並べると、6個目でもう354ナノ秒先に出ます。

uuid-v7-tick-mechanism.png

図の下段が実際に生成した時刻、上段がそのUUIDに入る時刻です。
矢印が右に倒れていく分がそのままずれになります。

式にすると、ずれ=生成数×244.140625ナノ秒−経過時間になります。
構成ごとにプロセスを分けて16本まで測った回に当てはめると、2本は500000×244.140625ナノ秒−106ミリ秒=16.07ミリ秒に対して実測16.76ミリ秒。
3本は183.1−104=79.1ミリ秒のはずが79.6、16本は976.6−582=394.6のはずが395.6。
6構成すべてが1ミリ秒以内に収まったので、生成された60bitの値は時刻ではなく244ナノ秒刻みの採番だと考えたほうが実態に合います。
実際、400万個生成しても重複は1件も出ず、値の範囲は生成数とほぼ同じでした。

極端なのは戻り方でした。
生成を止めるとv7lastTimestampはそこで動きを止め、あとは実時刻が追いつくのを待つしかないので、復帰にかかる時間はずれの量とほぼ同じになります。
8045ミリ秒ずれた状態から復帰まで8049ミリ秒で、ほぼ1対1です。
10秒の負荷に対して、時刻が信用できない区間は18秒続きます。

ここで一度計測をやり直しました。
最初はワーカ数を1つのプロセスで順に変えて測っていて、4本の結果だけが式と合いませんでした。
143ミリ秒かかったので式では101ミリ秒のはずが、148ミリ秒出ています。
この47ミリ秒はどこから来たのか。
測り始める前のずれを表示させたら、その時点で既に46.8ミリ秒進んでいました。
v7lastTimestampがパッケージ変数なので、前の構成のずれをそのまま引き継いでいたわけです。

1本から3本までが無事だったのは、構成の切り替えに挟まっていた集計処理が数十ミリ秒かかっていて、その間に実時刻が追いついていたからでした。
3本のずれは78ミリ秒あって、こちらは吸収しきれていません。
プロセスを分けるか、追いつくまで待つかのどちらかが要ります。
掲載したコードの末尾でdriftMsが0以下になるまで待っているのは、この後始末です。

この現象自体はissue #80222で報告されていて、2026-07-06にcloseされています。
報告者の環境では単一スレッドで1ミリ秒に9033個に達し、1000万回呼んだ直後のずれは+1327ミリ秒でした。
手元の1本では線を超えなかったので、どこで壊れるかがハードウェアの生成コスト次第だということがここでも裏付けられます。
closeの理由は、RFC 9562がタイムスタンプを実時刻より進めることを許しており、単一プロセスで毎秒400万個を持続生成する必要が現実にあるのかという点でした。
仕様の読みとしては正しいと思います。

js/wasmではもっと素直に壊れます。
Date.getTime()がミリ秒精度しかないため、サブミリ秒成分が常に0になり、rand_aが固定値になります(issue #80084)。

一番損な使い方

一番損なのは、v7のIDを主キーにしたうえで、作成時刻を別に持たずにIDから復元して時間範囲で抽出する実装です。
並行生成が244ナノ秒の線を切っている間、抽出条件の右端より先の時刻がIDに入るので、直近のレコードが範囲から漏れます。
漏れる量はその時点のずれと同じで、負荷を止めたあとも同じ長さだけ続きます。

索引の局所性が目的なら、何も変わりません。
ずれても単調性は保たれ、重複も出ず、値は右端に詰まったまま入るので、索引目的でv7を選んだ判断をこの件で見直す必要はありません。

私なら作成時刻は別カラムにtime.Now()で持ちます。
8バイト増えるだけで、IDの生成速度とは無関係になります。

所感

273行を読むだけで挙動が全部説明できるのは気持ちがよかったです。
待たずに1目盛り進めるという4行のためにここまでの性質が決まっているのに、ドキュメントには「システム時計が巻き戻る場合を除き、常に昇順で並ぶ値を返す」としか書いてありません。
この一文に嘘はありません。
昇順であることは保証されていて、それが実時刻であることは保証されていない、というだけの話です。

0
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?