Open1

draft sync test deeeeeep dive

kakkkykakkky

Deep Dive Into testing/synctest の下書き

https://speakerdeck.com/daikieng/synctest

名前は聞いていたが何か詳しくはよく知らなかったパッケージでした。

便利なのが理解できた上に、その中身がとても気になったので、自分でもさらにDeep Diveしてみています。

Goランタイムをなんとなく知っているとより面白いですが、ここではその説明は割愛します。

（筆者も「なんとなく」なのでうまく説明できるほどではないです）

非同期テストのつらみ

非同期テスト処理のテストが難しいぞという話がありました。

  • 関数が処理中にgoroutineを呼び出しており、結果を確認すべきタイミングが不安定

    • goroutineの実行タイミングはスケジューラのお気分です(？)

  • 「経過時間」に依存する処理をtime.Sleepで待ってもflakyになる

    • sleep処理になると、実行しているgoroutineはスケジューラによりブロッキングとみなされ、マシンスレッドから外されます。timeがすぎてブロッキングが解除されたとしても、実行可能なキューに入るだけで、それをgoroutineがいつ戻してくれるかはこれまたスケジューラの気分です。
    • この辺の話は一度記事にしたことがある（ちょっと違うけど）ので興味あればぜひこちらから。

gorutineの完了を確実に待つためにsleep時間を長く置いてみたりするとシンプルに実行時間が長くなっていくだけですし、そもそもそれで確実にflakyではなくなるかというと、述べたようなランタイムの仕組みを考えればNOです。

そこで、synctestという解決策の1つがあるようです。

このパッケージが提供するAPIは二つのみで、

  • synctest.Test()：
    • 「バブル」内でテストを実行し、実行時間の短縮を実現する
  • synctest.Wait()：
    • hoge

です。

1. synctest.Testを見てみる

func Test(t *testing.T, f func(*testing.T)) {...}

TL;DR

  • synctest.Test()は、テスト実行を「バブル」という仮想的な隔離環境に閉じ込める
  • バブル内では仮想クロック等が動作し、time.Sleepやtime.Timerなどの時間待ちが瞬時に完了する
  • 条件は「バブル内の全goroutineがdurably block状態」になること
  • durably blockは「同バブル内の他goroutineによってのみ解除可能なブロック」を指す
  • File I/Oやmutex待ちなど、バブル外の要因によるブロックは対象外

バブル(goroutine)内でテストを実行する

まず押さえておくべきそうな独自概念が、

Test executes f in a new bubble.

ということです。

この「バブル」は、「テスト実行時の仮想的な隔離環境」と捉えておくと良さそうです。

つまり第二引数にとるfは隔離環境で実行されるわけですね。

そしてバブル内でテストの実行（f）がgoroutine内で行われるようになっているようです。また、そのf内で起動されるgoroutineもまた同バブルに属します。

Test関数により以下のコードが呼ばれます。

テスト関数を実行するgoroutine（root goroutineと呼称します）の中にバブルが紐付けられ、そのバブルの中でgoroutineが起動してfが実行されるという流れが見て取れます。

synctest.Test()の内部コード（抜粋）
src/runtime/synctest.go
func synctestRun(f func()) {
    // 現在のgoroutineを取得
    gp := getg()
    if gp.bubble != nil {
        panic("synctest.Run called from within a synctest bubble")
    }
    // 新しいバブル空間を作成し、現在のgoroutine(gp)をそのrootにする
    bubble := &synctestBubble{
        id:      bubbleGen.Add(1),
        total:   1,
        running: 1,
        root:    gp,
    }
    // 現在のgoroutineとバブルを紐付ける
    gp.bubble = bubble
    defer func() { gp.bubble = nil }()

    // テスト関数fを新しいgoroutine(bubble.main = 以降、main goroutine)で実行している部分
    systemstack(func() {
        fv := *(**funcval)(unsafe.Pointer(&f))
        // newproc1は実行可能ステータスのgoroutineを作成し、その中でfvは実行される。また、そのgoroutineも同バブルに属する
        bubble.main = newproc1(fv, gp, sys.GetCallerPC(), false, waitReasonZero)
        pp := getg().m.p.ptr()
        runqput(pp, bubble.main, true)
        wakep()
    })

    // ...（仮想時間管理やタイマー処理は省略）...
}

bubble内で新たなgoroutineを起動しています。これをここでは main goroutineと呼ぶことにします。

そのmain goroutineの中でfを実行しているのは以下の関数です。

src/runtime/proc.go
// Create a new g in state _Grunnable (or _Gwaiting if parked is true), starting at fn.
//
func newproc1(fn *funcval, callergp *g, callerpc uintptr, parked bool, waitreason waitReason) *g {
    // 省略

    // 実行可能ステータスの新goroutine(newg)を取得/作成
    newg := gfget(pp)
    if newg == nil {
        newg = malg(stackMin)
        casgstatus(newg, _Gidle, _Gdead)
        allgadd(newg)
    }
    // ...（スタック設定など省略）...

    // 親goroutineのバブルを継承
    // callergpはbubbleのrootであるgoroutine
    newg.bubble = callergp.bubble

    // 実行する関数(fn)をセット
    gostartcallfn(&newg.sched, fn)

    // 実行可能状態にする
    casgstatus(newg, _Gdead, _Grunnable)

    // 返されたgoroutineはスケジューラによりfn（関数本体）が実行される
    return newg
}

ちなみに、goroutineの構造体にあるbubbleフィールドは、synctestのものです。テストに使われるパッケージがgoroutine自体に埋め込まれている感じなんですね。

type g struct {
    // 省略
    bubble  *synctestBubble
}

そして、このバブル内にテスト実行を隔離させて何が嬉しくなったかというと、

Within a bubble, the time package uses a fake clock. Each bubble has its own clock. The initial time is midnight UTC 2000-01-01.

Time in a bubble only advances when every goroutine in the bubble is durably blocked.

なんかいい感じに一瞬で時間を進めてくれるみたいです。そのいい感じに時間が進む条件というのが、バブル内の全てのgoroutineがdurably block(持続的なブロック)された時です。

例えば、time.Sleepはgoroutineをdurably blockするため、バブル内でsleep処理があった場合はsleep時間を待つことなく、一瞬で時刻を進めてくれる感じなんだそう。

ただ使う分にはこの辺で読み終わっていいです。

しかし、synctest.Test()に実行関数を入れ込むだけで、なんでこんなうまいことやってくれるんだろうとかなり不思議に思えますね。

さらに深ぼってみます。

なぜtime.Sleepの時間が一瞬で過ぎるのか

time.Sleepの中を見てみます。

go/src/runtime/time.go
go/src/runtime/time.go
func timeSleep(ns int64) {
    if ns <= 0 {
        return // 0以下なら即復帰
    }

    gp := getg() // 現在のgoroutineを取得

    // goroutineにタイマーがなければ新規作成
    t := gp.timer
    if t == nil {
        t = new(timer)
        t.init(goroutineReady, gp)
        // synctestバブル内なら仮想タイマーとして扱う
        if gp.bubble != nil {
            t.isFake = true
        }
        gp.timer = t
    }

    // 現在時刻を取得（バブル内なら仮想時刻、外なら実時刻）
    var now int64
    if bubble := gp.bubble; bubble != nil {
        now = bubble.now
    } else {
        now = nanotime()
    }

    // 目覚めるべき時刻を計算
    when := now + ns

    gp.sleepWhen = when

    if t.isFake {
        // sleepWhen後にタイマーが発火するように設定(つまりsleepWhenの間sleepする)
        resetForSleep(gp, nil)
        // 現在のgoroutineをコンテキストスイッチ（waitingにparkする）
        gopark(nil, nil, waitReasonSleep, traceBlockSleep, 1)
    } else {
        // 通常のタイマー処理
        gopark(resetForSleep, nil, waitReasonSleep, traceBlockSleep, 1)
    }
}

time.Sleepが呼ばれているgoroutineを見て、それがbubbleかどうかを見てるみたいです（gp.bubble != nilの分岐が目につく）。

一旦ここまでをまとめると、

  • synctest.Test()によって実行をbubble(goroutine)に隔離する
  • time.Sleepが、自分が呼ばれたgoroutineがbubbleに属していた場合、仮想クロックでタイマーの発火（動き出し）を設定してからgoparkする

ここでさらに、もう一度syntestRun()の中を見てみましょう。
先にbubble内でgoroutineを起動して、f関数を実行するところまで見ていましたが、その続きです。

synctestRunのbubble生成後の流れ
src/runtime/synctest.go
func synctestRun(f func()) {
    // 省略 - バブル作成、初期化処理
    // bubble内でmain goroutineを起動して、f関数を実行するところまで完了

    lock(&bubble.mu)
    bubble.active++  // rootgoroutineをactiveカウントに含める
    
    // メインループ: 仮想時間管理
    for {
        unlock(&bubble.mu)
        
        // 1. 現在の仮想時刻でタイマーをチェックし、発火できる場合はbubble内goroutineをrunnableにする（→その後スケジューラがrunningにして実行再開）
        systemstack(func() {
            gp.bubble.timers.check(bubble.now, bubble)
        })
        
        // 2. バブル内の全goroutineがdurably blockされるまで待機
        // synctestidle_c関数で、
        //   - bubble内goroutineが全てdurably blockしている場合 ➡️ root goroutine（= `TestXxxx()`といったテスト関数を実行しているgoroutine）が復帰する
        //   - bubble内にrunningなgoroutineがある場合 ➡️ root goroutineがブロッキング（待機）
        gopark(synctestidle_c, nil, waitReasonSynctestRun, traceBlockSynctest, 0)

        // root goroutineが復帰したら以降の処理へ進む
        // この時、bubble内goroutineは全てdurably blockしている

        lock(&bubble.mu)
        
        // 3. 次にタイマーが発火すべき時刻を取得
        next := bubble.timers.wakeTime()

        // 4. 仮想時刻を次のタイマー発火時刻まで一気に進める
        bubble.now = next
    }

    // 省略(終了処理)
}

バブル内の全goroutineがdurably blockしているかを判定し、これが返す値が真であれば gopark()内でroot goroutineは再開する / 偽であればgopark内でブロッキング判定となる。

src/runtime/synctest.go
func synctestidle_c(gp *g, _ unsafe.Pointer) bool {
	canIdle := true
        // ative == 1はroot goroutine自体のカウント分
	if gp.bubble.running == 0 && gp.bubble.active == 1 {
		// bubble内の全goroutineがブロックまたは終了している
		canIdle = false
	} else {
		gp.bubble.active--
	}
	
	return canIdle
}

ちなみに、root goroutineがブロッキングとなった時（つまり上で偽となった場合）には、

  • bubble.changegstatus()
  • bubble.maybeWakeLocked()

の順に見てみると、その復帰の様子が見えるかと思います。

bubble内がdurably blockと判断されれば復帰し、止まっていたfor loopの続きから始まると思われます。

https://github.com/golang/go/blob/master/src/runtime/synctest.go#L43

コードで見たように、以下で仮想時刻を進めました。nextの値は、timeSleep()でresetForSleep()によってセットしていたタイマー発火の時間（sleepWhen）です。

// 4. 仮想時刻を次のタイマー発火時刻まで一気に進める
bubble.now = next

バブル内の仮想時間が一気に進んだところで、また for loopの冒頭に戻り、 gp.bubble.timers.check(bubble.now, bubble)に差し掛かります。

そこで、タイマーが発火readyになっているはずなので、t.check()内でタイマーがt.unlockAndRun()により発火し、goroutineReady()が呼ばれてgoroutineがrunnableになります（気になる人はここも追ってみてください）。

流れを概念的に図解してみました。

ここで、durably blockとは何かを理解しましょう。

そもそもdurably blockとは何かを理解する

A goroutine in a bubble is "durably blocked" when it is blocked and can only be unblocked by another goroutine in the same bubble. A goroutine which can be unblocked by an event from outside its bubble is not durably blocked.

つまり、バブル内の現在のgoroutineがブロックされていて、それが「同バブル内の他のgoroutineによってのみブロック解除される」場合に、durably blockの状態となるそう。

また、durably blockという判定になるのはどんな時かというのも以下のように挙げられています。

The following operations durably block a goroutine:

  • a blocking send or receive on a channel created within the bubble
  • a blocking select statement where every case is a channel created within
  • the bubble
  • sync.Cond.Wait
  • sync.WaitGroup.Wait, when sync.WaitGroup.Add was called within the bubble
  • time.Sleep

durably blockという概念はおそらくこのsynctest独自のものと思います。単なるブロッキングではないという定義を持たせたいのだと思っています。

そして、以下のようなブロッキングは、durably blockではないと明示されています。

Operations not in the above list are not durably blocking. In particular, the following operations may block a goroutine, but are not durably blocking because the goroutine can be unblocked by an event occurring outside its bubble:

  • locking a sync.Mutex or sync.RWMutex
  • blocking on I/O, such as reading from a network socket
  • system calls

これらの場合、「ゴルーチンはバブルの外で発生するイベントによってブロック解除できる」ため、durably blockには分類されないみたいです。

ここまでの話を踏まえると、

バブル内に閉じたブロッキング（durably block）はsynctestを活用できるが、バブル外の要因で起きるブロッキングに対しては有効活用が難しい

というふうにいえそうです。

sycrtest.Test()で高速化できる/できない場合のイメージは以下です。（あくまで筆者の）

コードベースから拾ってみる

手っ取り早くdurably blockっていつなの？をコードから確認してみましょう。

スタックトレースでgoroutineの状態を表示する箇所を見つけました。

見てみると、goroutineがbubble内であり、gp.waitreason.isIdleInSynctest()が真であった場合に(durable)と表示するようですね。

src/runtime/traceback.go 
func goroutineheader(gp *g){
    //省略
    if bubble := gp.bubble; bubble != nil &&
        gp.waitreason.isIdleInSynctest() &&
    !stringslite.HasSuffix(status, "(durable)") {
        // If this isn't a status where the name includes a (durable)
        // suffix to distinguish it from the non-durable form, add it here.
        print(" (durable)")
	}
}

( durable)の表すところですが、上の関数の分岐は、go 1.24には見られない & bubbleを見ている時点でsynctestの指すdurably blockを表していることは間違い無いでしょう。

https://github.com/golang/go/blob/release-branch.go1.24/src/runtime/traceback.go#L1196

そして、重要なのはisIdleSynctest()です。waitReasonが以下のmapに含まれていれば真になりますね。

func (w waitReason) isIdleInSynctest() bool {
	return isIdleInSynctest[w]
}

// isIdleInSynctest indicates that a goroutine is considered idle by synctest.Wait.
var isIdleInSynctest = [len(waitReasonStrings)]bool{
	waitReasonChanReceiveNilChan:    true,
	waitReasonChanSendNilChan:       true,
	waitReasonSelectNoCases:         true,
	waitReasonSleep:                 true,
	waitReasonSyncCondWait:          true,
	waitReasonSynctestWaitGroupWait: true,
	waitReasonCoroutine:             true,
	waitReasonSynctestRun:           true,
	waitReasonSynctestWait:          true,
	waitReasonSynctestChanReceive:   true,
	waitReasonSynctestChanSend:      true,
	waitReasonSynctestSelect:        true,
}

mapのキーを見てみると、先に見たdocumentの引用にあったdurably lockedになるケースと大方マッチしてそうですね。

documentの内容とコードが一致しているのが分かれば十分納得できるかと思います。

いくつか動かしてみる

2. synctest.Wait()

durably blockのセクションが一個挟まりましたが、2つ目のAPIである Waitについてみていきましょう。

func Wait()

Wait blocks until every goroutine within the current bubble, other than the current goroutine, is durably blocked.

bubble内でsynctest.Waitを呼び出しているgoroutine以外の全てのgoroutineがdurably blockになるまで待機するとありました。

一旦簡単なテストコードを動かしてみる

個人的に捉えづらかったので、まず実例としてどんなテストコードになるのかみてみましょう。

documentにあった例をさらに簡素化しました。
先に見たsynctest.Test()関数内で、5秒後にキャンセルされるコンテキストが5秒後にキャンセルされていることを確かめるというテストです。

func TestContextWithTimeout(t *testing.T) {
	synctest.Test(t, func(t *testing.T) {
		// 5秒後にキャンセルされるContextを作成
		const timeout = 5 * time.Second
		ctx, cancel := context.WithTimeout(t.Context(), timeout)
		defer cancel()

		// 5s待つ
		time.Sleep(timeout)

		// ここではタイムアウトしているはず....???
		if err := ctx.Err(); err != context.DeadlineExceeded {
			t.Fatalf("after timeout: ctx.Err() = %v, want DeadlineExceeded\n", err)
		}
	})
}

ありゃ。こちら落ちました。

--- FAIL: TestContextWithTimeout (0.00s)
    synctest_wait_example_test.go:25: after timeout: ctx.Err() = <nil>, want DeadlineExceeded
FAIL
FAIL    playground      0.193s
FAIL

なんで落ちたんでしょう。

context.WithTimeoutの内部では、cancel処理が行われるgoroutineが別に起動します。