フューチャー技術ブログ

Go 1.24リリース連載 testing/synctest(experimental)

はじめに

こんにちは。CSIGの棚井です。

Go 1.24 Release Notes の内容を紹介する「フューチャー技術ブログ Go 1.24 リリース連載」の記事です。

testing/synctest」パッケージを取り上げます。

TL;DR

  • 1.24 に experimental として追加された testing/synctest の嬉しいポイントは2つ
    • いずれも「テストコードを綺麗にする」用途に使える
  • 1つ目
    • これまでのテストでは「実際の時間経過」を待つ必要があった
      • 高スペックのPCではテストに通過しても、低スペックのCI環境では処理速度の影響で失敗するなど「Flaky Test(不安定なテスト)」に悩まされることがある
      • 一定時間が経過したら、time.AfterFunctime.Timer を用いて「一定時間が経過した後に呼び出したい処理」を追加するという対処策もある
    • testing/synctest を使えば、テスト処理内での時間操作ができる
      • synctest.Run 内で fake clock を使う
  • 2つ目
    • 複数の goroutine すべての完了を待つには、WaitGroup の Add(), Done(), Wait() を利用していた
    • testing/synctestを使えば、テスト処理内での goroutine の処理待ちができる
      • synctest.Run の中では、synctest.Wait により「すべての goroutine が idle 状態になったこと」を判定できる

Discussion #67434

testing/synctest が追加されるまでの経緯は、proposal: testing/synctest: new package for testing concurrent code #67434 で会話されています。Discussion 全体のサマリーは #AI-generated issue overview として Original Post Summary に整理されています。

Discussion では、テスト時に「実際の時間経過」が求められるようなテストケースに対して、

  • テスト専用のロジックを追加せず
  • より短いテスト時間で
  • Flaky Test(不安定なテスト)にならない

というニーズを、いかに実現するかに焦点が当てられています。

「実際の時間経過」が求められるテストケースの解像度を上げるために、Discussion の冒頭(及び、コメント内容)で例示されている「有効期限付きキャッシュのテスト」を見ていきます。

type Cache[K comparable, V any] struct{}

// NewCache creates a new cache with the given expiry.
// f is called to create new items as necessary.
func NewCache[K comparable, V any](expiry time.Duration, f func(K) V) *Cache {}

// Get returns the cache entry for K, creating it if necessary.
func (c *Cache[K,V]) Get(key K) V {}
func TestCacheEntryExpires(t *testing.T) {
count := 0
c := NewCache(2 * time.Second, func(key string) string {
count++
return fmt.Sprintf("%v:%v", key, count)
})

// Get an entry from the cache.
if got, want := c.Get("k"), "k:1"; got != want {
t.Errorf("c.Get(k) = %q, want %q", got, want)
}

// Verify that we get the same entry when accessing it before the expiry.
time.Sleep(1 * time.Second)
if got, want := c.Get("k"), "k:1"; got != want {
t.Errorf("c.Get(k) = %q, want %q", got, want)
}

// Wait for the entry to expire and verify that we now get a new one.
time.Sleep(3 * time.Second)
if got, want := c.Get("k"), "k:2"; got != want {
t.Errorf("c.Get(k) = %q, want %q", got, want)
}
}

このような「期限付きのキャッシュを作成する関数」に対して、「指定の時間を超過したら、キャッシュが Expire されること」をテストするためには、テスト関数の TestCacheEntryExpires に複数の time.Sleep が記載されているように「実際の時間経過を待つ」処理が必要になります。

上記テスト関数内では、計4秒(1秒 + 3秒)のスリープ時間が発生します。ほんの数秒であれば気に留めるまでもありませんが、現実のキャッシュ運用として数分単位や数時間単位での「時間経過後の処理」をテストしたい場合には、テストコード内での様々な工夫(もしくは単体テストは諦めてE2E テストに任せる)を入れることになります。また、これらの「工夫」は、テストコードに「テスト専用のロジック」を追加することにも繋がりがちです。

これらの問題に対して、「テスト専用のロジックを追加せず」かつ「より短いテスト時間で」かつ「Flaky Test(不安定なテスト)にならない」を同時に達成するために testing/synctest が提案されました。こちらも Discussion 冒頭のコードを引用して以下に添付します。

func TestCacheEntryExpires(t *testing.T) {
synctest.Run(func() {
count := 0
c := NewCache(2 * time.Second, func(key string) string {
count++
return fmt.Sprintf("%v:%v", key, count)
})

// Get an entry from the cache.
if got, want := c.Get("k"), "k:1"; got != want {
t.Errorf("c.Get(k) = %q, want %q", got, want)
}

// Verify that we get the same entry when accessing it before the expiry.
time.Sleep(1 * time.Second)
synctest.Wait()
if got, want := c.Get("k"), "k:1"; got != want {
t.Errorf("c.Get(k) = %q, want %q", got, want)
}

// Wait for the entry to expire and verify that we now get a new one.
time.Sleep(3 * time.Second)
synctest.Wait()
if got, want := c.Get("k"), "k:2"; got != want {
t.Errorf("c.Get(k) = %q, want %q", got, want)
}
})
}

こちらのテスト関数内では、synctest.Runsynctest.Wait の2つの関数が呼ばれていること、さらに重要な点として「元のテストコードの構造は変わっていないこと」が分かります。ただし、このテストコードだけでは「具体的に何が嬉しいのか?」が分かりにくいため、ここからは release-branch.go1.24 のテストコードを動かしながら、testing/synctest の活用に向けて解像度を上げていきます。

注意点として、testing/synctestexperimental のため、Release Noteに

The package API is subject to change in future releases.

と記載されている通り、将来のバージョンでは取り下げられる可能性があります。

testing/synctest

  • 環境構築
  • 動作仕様の確認

環境構築

Goリリースノートから技術ブログを書く流れ基礎 環境を構築する の内容を踏襲して、今回の go1.24(go1.24rc2)を動かす環境を用意します。go1.24rc2 は「こちら」にインストールコマンドがありますので、早速実行していきます。

$ go install golang.org/dl/go1.24rc2@latest
go: downloading golang.org/dl v0.0.0-20250116195134-55ca457114df

$ go1.24rc2 download
Downloaded 0.0% ( 3120 / 75458927 bytes) ...
Downloaded 1.5% ( 1097728 / 75458927 bytes) ...
(略)
Downloaded 99.0% (74693520 / 75458927 bytes) ...
Downloaded 100.0% (75458927 / 75458927 bytes)
Unpacking /Users/me/sdk/go1.24rc2/go1.24rc2.darwin-arm64.tar.gz ...
Success. You may now run 'go1.24rc2'

$ go1.24rc2 version
go version go1.24rc2 darwin/arm64

また、Release Note の New experimental testing/synctest package には以下記述がありますので、環境変数への追加も忘れずに行います。

The synctest package is experimental and must be enabled by setting GOEXPERIMENT=synctest at build time.

$ echo $GOEXPERIMENT

$ export GOEXPERIMENT=synctest
$ echo $GOEXPERIMENT
synctest

go versionGOEXPERIMENT=synctest の設定まで確認できれば、testing/synctest の準備完了です。以下から、具体的なテストコードを見ていきます。

動作仕様の確認

例1: Example_contextWithTimeout

まずは testing/synctest を使わないコードを見ていきます。以下の Example_contextWithTimeoutNotSynctest を実行した場合、実行完了までにどのくらいの時間がかかるのかを、一旦手を止めてイメージしてみてください。

func Example_contextWithTimeoutNotSynctest() {
const timeout = 5 * time.Second
ctx, cancel := context.WithTimeout(context.Background(), timeout)
defer cancel()

time.Sleep(timeout - time.Nanosecond)
fmt.Printf("before timeout: ctx.Err() = %v\n", ctx.Err())

time.Sleep(time.Nanosecond)
fmt.Printf("after timeout: ctx.Err() = %v\n", ctx.Err())

// Output:
// before timeout: ctx.Err() = <nil>
// after timeout: ctx.Err() = context deadline exceeded
}

イメージできましたか?

time.Sleep の総時間を計算すれば、5秒 +α 程度になることはコード上から明確です。実際に実行してみると 5.189s でした。

$ go1.24rc2 test -v -run Example_contextWithTimeoutNotSynctest
=== RUN Example_contextWithTimeoutNotSynctest
--- PASS: Example_contextWithTimeoutNotSynctest (5.00s)
PASS
ok example 5.189s

それでは、testing/synctest を用いたバージョンを見ていきます。

先ほどの関数 Example_contextWithTimeoutNotSynctest に対して、以下の Example_contextWithTimeout では

  • synctest.Run
  • synctest.Wait

の2つを追加しています。

この関数の場合でも、実行したらどの程度の時間がかかるのかをイメージしてみてください。

func Example_contextWithTimeout() {
synctest.Run(func() {
const timeout = 5 * time.Second
ctx, cancel := context.WithTimeout(context.Background(), timeout)
defer cancel()

time.Sleep(timeout - time.Nanosecond)
synctest.Wait()
fmt.Printf("before timeout: ctx.Err() = %v\n", ctx.Err())

time.Sleep(time.Nanosecond)
synctest.Wait()
fmt.Printf("after timeout: ctx.Err() = %v\n", ctx.Err())

// Output:
// before timeout: ctx.Err() = <nil>
// after timeout: ctx.Err() = context deadline exceeded
})
}

testing/synctest の導入検討経緯として「より短いテスト時間で」というのがありますので、このテストコードがもし「5秒未満」で終了するならば、本パッケージの狙いは達成されたことになります。

それでは、実際にどのくらい早くなったのかを確認してみた結果が以下です。

$ go1.24rc2 test -v -run Example_contextWithTimeout
=== RUN Example_contextWithTimeout
--- PASS: Example_contextWithTimeout (0.00s)
PASS
ok example 0.189s

なんと、5.189s から 0.189s にまでテスト時間を短縮できました。

5.189s / 0.189s ≒ 27.5

このテストケースでは、testing/synctest を用いることで、27.5倍のスピードでテストが終了しました。圧倒的な速度改善です。

例2: TestNow

続いて、fake clock の仕様と synctest.Run の中(Bubble と呼ばれる)での時間進捗を見ていきます。説明の都合上、オリジナルのテストコードに対して // Point①, ②, ③ のコメントを追加しています。

func TestNow(t *testing.T) {
start := time.Date(2000, 1, 1, 0, 0, 0, 0, time.UTC).In(time.Local)
synctest.Run(func() {
// Time starts at 2000-1-1 00:00:00. // Point①
if got, want := time.Now(), start; !got.Equal(want) {
t.Errorf("at start: time.Now = %v, want %v", got, want)
}
go func() { // Point②
// New goroutines see the same fake clock.
if got, want := time.Now(), start; !got.Equal(want) {
t.Errorf("time.Now = %v, want %v", got, want)
}
}()
// Time advances after a sleep.
time.Sleep(1 * time.Second) // Point③
if got, want := time.Now(), start.Add(1*time.Second); !got.Equal(want) {
t.Errorf("after sleep: time.Now = %v, want %v", got, want)
}
})
}

もちろんテスト処理は、1秒未満で終了します。

% go1.24rc2 test -v -run TestNow                   
=== RUN TestNow
--- PASS: TestNow (0.00s)
PASS
ok example 0.228

TestNow 関数の中では、testing/synctest での重要な仕様が2つ利用されています。

まず1つ目は、Point① に記載された 2000-1-1 00:00:00 という時刻についてです。synctest.Run 内での fake clock は、このテストが通過することから分かるように「UTC の 2000-1-1 00:00:00」で初期化されます。synctest 内でのテスト開始時刻は「2000年1月1日の0時」という点は、パッケージ導入初期においてはテスト内コメントなどで周知する必要がありそうです。

2つ目は Point②, ③実行順序 です。事前に testing/synctest の仕様を知らない状況で、TestNow を読んだ場合には、Point② の時点で goroutine 内での処理が始まることにより、goroutine 内のテストと Point③ のどちらが先に実行されるかで、Flaky Test(不安定なテスト) になることが想像できます。

それでは、本テストを連続で100回実行してみます。

$ seq 100 | xargs -I {} go1.24rc2 test -run TestNow | grep PASS | wc -l
100

Flaky Test の可能性があれば、100実行すれば数回は失敗する想定ですが、すべて成功(PASS)したことを確認できました。ここが重要なポイントで、fake clock 内での時間進捗は、Bubble(synctest.Run内のこと)内の goroutine がすべて idle 状態になったとき に起こる点です。先ほどのコードでは Point③ に到達した時点にて、 Point② で開始された goroutine が idle 状態になるまで処理待ちとなり、その後に time.Sleep(1 * time.Second) が実行される、つまり、② -> ③ の実行順序維持されるため、Flaky Test を回避できます。

「idle 状態」については、Testing Concurrent Code Using the Experimental ‘testing/synctest’ Package に端的な要約がありますのでご参照ください。

例3: TestWait

「例2: TestNow」では、「fake clock の時間進捗操作は、Bubble 内での goroutine がすべて idle 状態になるまで待機する」ことを利用したテストコードでした。続いて、以下のコードでは、同様の状態を明示的に待機する関数として、synctest.Wait() を利用しています。

func TestWait(t *testing.T) {
synctest.Run(func() {
done := false
ch := make(chan int)
var f func()
f = func() {
count := <-ch
if count == 0 {
done = true
} else {
go f()
ch <- count - 1
}
}
go f()
ch <- 100
synctest.Wait()
if !done {
t.Fatalf("done = false, want true")
}
})
}

再帰的に goroutine を呼び出し続けて、最後に呼び出された goroutine により done = true へと更新された場合のみに通過するテストコードです。

synctest.Wait() をコメントアウトした場合、if !done{ ... } が先に判定されるためテストコードは失敗します。

-		synctest.Wait()
+ // synctest.Wait()
$ go1.24rc2 test -v -run TestWait
=== RUN TestWait
example_sync_test.go:312: done = false, want true
--- FAIL: TestWait (0.00s)
FAIL
exit status 1
FAIL example 0.225s

synctest.Run の中で開始した goroutine に対して、synctest.Wait() により goroutine のすべてが idle 状態になるまで待つ」という選択肢が得られると、「平行処理が関わるテストコード」のリファクタリングが進みそうだなと思いました。

TestWaitsync.WaitGroup で書き換えると、以下のようになります。

func TestWaitWithWaitGroup(t *testing.T) {
var wg sync.WaitGroup
done := false
ch := make(chan int)

var f func()
f = func() {
defer wg.Done()

count := <-ch
if count == 0 {
done = true
} else {
wg.Add(1)
go f()
ch <- count - 1
}
}

wg.Add(1)
go f()
ch <- 100

wg.Wait()

if !done {
t.Fatalf("done = false, want true")
}
}

例4: TestTimerReset

最後に、testing/synctest での時間操作は「認知負荷が高いことがある」ケースを見ていきます。

テストコードから引用した以下の TestTimerReset について、

  • 各処理のタイミングで fake clock は何時を示すのか
  • 最後の時間処理で「1+2+4」を行なっているのは、どの time.Sleep に対応した操作なのか

を一読で理解するのは、中々難しいのではないでしょうか。

func TestTimerReset(t *testing.T) {
synctest.Run(func() {
start := time.Now()
tm := time.NewTimer(1 * time.Second)
if got, want := <-tm.C, start.Add(1*time.Second); got != want {
t.Errorf("first sleep: <-tm.C = %v, want %v", got, want)
}

tm.Reset(2 * time.Second)
if got, want := <-tm.C, start.Add((1+2)*time.Second); got != want {
t.Errorf("second sleep: <-tm.C = %v, want %v", got, want)
}

tm.Reset(3 * time.Second)
time.Sleep(1 * time.Second)
tm.Reset(3 * time.Second)
if got, want := <-tm.C, start.Add((1+2+4)*time.Second); got != want {
t.Errorf("third sleep: <-tm.C = %v, want %v", got, want)
}
})
}

<-tm.Ctm.Reset のそれぞれの実行時点で、fake clock は何時になっているのか(スタート時刻からどれだけ進んでいるのか)を、脳内で補完しながら読み進めるのが辛くなったため、デバッグモードにより値を見ながらで理解できました。プリントデバッグ文を追加すると以下のようになります。

func TestTimerReset(t *testing.T) {
synctest.Run(func() {
start := time.Now()
tm := time.NewTimer(1 * time.Second)

+ fmt.Printf("(1) time.Now(): %v\n", time.Now())

if got, want := <-tm.C, start.Add(1*time.Second); got != want {
t.Errorf("first sleep: <-tm.C = %v, want %v", got, want)
}

+ fmt.Printf("(2) time.Now(): %v\n", time.Now())

tm.Reset(2 * time.Second)
if got, want := <-tm.C, start.Add((1+2)*time.Second); got != want {
t.Errorf("second sleep: <-tm.C = %v, want %v", got, want)
}

+ fmt.Printf("(3) time.Now(): %v\n", time.Now())

tm.Reset(3 * time.Second)
time.Sleep(1 * time.Second)

+ fmt.Printf("(4) time.Now(): %v\n", time.Now())

tm.Reset(3 * time.Second)
if got, want := <-tm.C, start.Add((1+2+4)*time.Second); got != want {
t.Errorf("third sleep: <-tm.C = %v, want %v", got, want)
}

+ fmt.Printf("(5) time.Now(): %v\n", time.Now())
})
}
$ go1.24rc2 test -v -run TestTimerReset
=== RUN TestTimerReset
(1) time.Now(): 2000-01-01 09:00:00 +0900 JST m=+946499195.401301751
(2) time.Now(): 2000-01-01 09:00:01 +0900 JST m=+946499196.401301751
(3) time.Now(): 2000-01-01 09:00:03 +0900 JST m=+946499198.401301751
(4) time.Now(): 2000-01-01 09:00:04 +0900 JST m=+946499199.401301751
(5) time.Now(): 2000-01-01 09:00:07 +0900 JST m=+946499202.401301751
--- PASS: TestTimerReset (0.00s)
PASS
ok example 0.276s

testing/synctest により「テスト時間を操作する」のは非常に便利な機能ですが、その一方で、時間を任意に進めるという操作自体によりコード理解の負荷が高まる可能性も感じました。

おわりに

本記事では「testing/synctest」パッケージを取り上げました。

Disscusion の中では、標準パッケージの net/http に含まれる以下のテスト関数について、testing/synctest の利用により「This test now executes instantaneously(現在は瞬時に実行されます)」と記載されています。

  • TestServerShutdownStateNew
  • TestTransportExpect100Continue

いずれは experimental が外れて、テスト時間の短縮になるのが楽しみな機能だなと思いました。