Go Wiki: Go 1.23 タイマーチャネルの変更

Go 1.23 では、time.NewTimer、time.After、time.NewTicker、GODEBUG 設定 asynctimerchan=1 は古いセマンティクスを強制し、asynctimerchan=0 は新しいセマンティクスを強制します。

Cap と Len

Go 1.23 以前では、タイマーチャネルの cap は 1 であり、タイマーチャネルの len は値が受信待ちであるかどうかを示していました（待ち状態の場合は 1、そうでない場合は 0）。Go 1.23 の実装では、cap と len が常に 0 のタイマーチャネルが作成されます。

一般に、任意のチャネルを len でポーリングすることは、別のゴルーチンがチャネルから同時に受信し、いつでも len の結果を無効にする可能性があるため、通常は役立ちません。len を使用してタイマーチャネルをポーリングするコードは、代わりに非ブロッキング select を使用する必要があります。

つまり、次のようなコードは

if len(t.C) == 1 {
    <-t.C
    more code
}

代わりに次のようにする必要があります。

select {
default:
case <-t.C:
    more code
}

Select の競合

Go 1.23 以前では、0ns や 1ns のような非常に短い間隔で作成されたタイマーは、スケジューリング遅延のために、その間隔よりもかなり長い時間をかけてチャネルを受信可能にしていました。この遅延は、select の前に準備ができているチャネルと、非常に短いタイムアウトを持つ新しく作成されたタイマーの間で select を行うコードで観測できます。

c := make(chan bool)
close(c)

select {
case <-c:
    println("done")
case <-time.After(1*time.Nanosecond):
    println("timeout")
}

select の引数が評価され、select が関連するチャネルを調べたときには、タイマーは期限切れになっているはずであり、両方のケースが進行可能になっていることを意味します。select は、複数の準備ができたケースからランダムに1つを選択するため、このプログラムは各ケースを約半分の確率で選択するはずです。

Go 1.23 以前のタイマー実装におけるスケジューリング遅延のため、このようなプログラムは「done」ケースを常に100%誤って実行していました。

Go 1.23 のタイマー実装は同じスケジューリング遅延の影響を受けないため、Go 1.23 では、そのプログラムは各ケースを約半分の確率で実行します。

Google のコードベースで Go 1.23 のテスト中に、select を使用して、進行準備ができたチャネル（しばしばコンテキストの Done チャネル）と、非常に低いタイムアウトのタイマーを競合させるテストがいくつか見つかりました。通常、本番コードでは実際のタイムアウトを使用するため、競合は面白くありませんが、テストではタイムアウトが非常に小さい値に設定されていました。そして、テストはタイムアウトに達した場合に失敗するように、タイムアウト以外のケースが実行されることを要求していました。簡略化された例は次のようになります。

select {
case <-ctx.Done():
    return nil
case <-time.After(timeout):
    return errors.New("timeout")
}

そして、テストは timeout を 1ns に設定してこのコードを呼び出し、コードがエラーを返した場合に失敗しました。

このようなテストを修正するには、呼び出し元がタイムアウトの可能性を理解するように変更するか、次のようにタイムアウトの場合でも done チャネルを優先するようにコードを変更することができます。

select {
case <-ctx.Done():
    return nil
case <-time.After(timeout):
    // Double-check that Done is not ready,
    // in case of short timeout during test.
    select {
    default:
    case <-ctx.Done():
        return nil
    }
    return errors.New("timeout")
}

デバッグ

Go 1.23 を使用してプログラムまたはテストが失敗するが、Go 1.22 を使用して機能した場合、asynctimerchan GODEBUG 設定 を使用して、新しいタイマー実装が失敗の原因となっているかどうかを確認できます。

GODEBUG=asynctimerchan=0 mytest  # force Go 1.23 timers
GODEBUG=asynctimerchan=1 mytest  # force Go 1.22 timers

プログラムまたはテストが Go 1.22 では常に合格するが、Go 1.23 では常に失敗する場合、それは問題がタイマーに関連しているという強い兆候です。

これまで観測されたすべてのテスト失敗において、問題はタイマー実装ではなくテスト自体にあったため、次のステップは mytest 内のどのコードが古い実装に依存しているかを正確に特定することです。そのためには、bisect ツール を使用できます。

go install golang.org/x/tools/cmd/bisect@latest
bisect -godebug asynctimerchan=1 mytest

このように呼び出すと、bisect は mytest を繰り返し実行し、タイマー呼び出しにつながるスタックトレースに応じて新しいタイマー実装をオン/オフに切り替えます。二分探索を使用して、特定のスタックトレース中に新しいタイマーを有効にすることによって誘発された失敗を絞り込み、それを報告します。bisect の実行中は、試行に関するステータスメッセージが出力されます。これは主に、テストが遅い場合にまだ実行中であることを知らせるためです。

bisect の実行例は次のようになります。

$ bisect -godebug asynctimerchan=1 ./view.test
bisect: checking target with all changes disabled
bisect: run: GODEBUG=asynctimerchan=1#n ./view.test... FAIL (7 matches)
bisect: run: GODEBUG=asynctimerchan=1#n ./view.test... FAIL (7 matches)
bisect: checking target with all changes enabled
bisect: run: GODEBUG=asynctimerchan=1#y ./view.test... ok (7 matches)
bisect: run: GODEBUG=asynctimerchan=1#y ./view.test... ok (7 matches)
bisect: target fails with no changes, succeeds with all changes
bisect: searching for minimal set of disabled changes causing failure
bisect: run: GODEBUG=asynctimerchan=1#!+0 ./view.test... FAIL (3 matches)
bisect: run: GODEBUG=asynctimerchan=1#!+0 ./view.test... FAIL (3 matches)
bisect: run: GODEBUG=asynctimerchan=1#!+00 ./view.test... ok (1 matches)
bisect: run: GODEBUG=asynctimerchan=1#!+00 ./view.test... ok (1 matches)
bisect: run: GODEBUG=asynctimerchan=1#!+10 ./view.test... FAIL (2 matches)
bisect: run: GODEBUG=asynctimerchan=1#!+10 ./view.test... FAIL (2 matches)
bisect: run: GODEBUG=asynctimerchan=1#!+0010 ./view.test... ok (1 matches)
bisect: run: GODEBUG=asynctimerchan=1#!+0010 ./view.test... ok (1 matches)
bisect: run: GODEBUG=asynctimerchan=1#!+1010 ./view.test... FAIL (1 matches)
bisect: run: GODEBUG=asynctimerchan=1#!+1010 ./view.test... FAIL (1 matches)
bisect: confirming failing change set
bisect: run: GODEBUG=asynctimerchan=1#v!+x65a ./view.test... FAIL (1 matches)
bisect: run: GODEBUG=asynctimerchan=1#v!+x65a ./view.test... FAIL (1 matches)
bisect: FOUND failing change set
--- change set #1 (disabling changes causes failure)
internal/godebug.(*Setting).Value()
    go/src/internal/godebug/godebug.go:165
time.syncTimer()
    go/src/time/sleep.go:25
time.NewTimer()
    go/src/time/sleep.go:144
time.After()
    go/src/time/sleep.go:202
region_dash/regionlist.(*Cache).Top()
    region_dash/regionlist/regionlist.go:89
region_dash/view.(*Page).ServeHTTP()
    region_dash/view/view.go:45
region_dash/view.TestServeHTTPStatus.(*Router).Handler.func2()
    httprouter/httprouter/params_go17.go:27
httprouter/httprouter.(*Router).ServeHTTP()
    httprouter/httprouter/router.go:339
region_dash/view.TestServeHTTPStatus.func1()
    region_dash/view/view.test.go:105
testing.tRunner()
    go/src/testing/testing.go:1689
runtime.goexit()
    go/src/runtime/asm_amd64.s:1695

---
bisect: checking for more failures
bisect: run: GODEBUG=asynctimerchan=1#!-x65a ./view.test... ok (6 matches)
bisect: run: GODEBUG=asynctimerchan=1#!-x65a ./view.test... ok (6 matches)
bisect: target succeeds with all remaining changes disabled

この場合、スタックトレースは、新しいタイマーを使用した場合に失敗を引き起こす time.After の呼び出しを正確に示しています。

このコンテンツはGo Wikiの一部です。

go.dev は、サービスの品質を提供および向上させ、トラフィックを分析するために、Google の Cookie を使用しています。詳細はこちらをご覧ください。