[インデックス 18265] ファイルの概要

このコミットは、Goランタイムにおいて、ゴルーチンがブロックされている時間をトレースバック出力に含めるように変更するものです。これにより、デバッグ時にゴルーチンがどのくらいの期間ブロックされているかを視覚的に把握できるようになり、パフォーマンスの問題やデッドロックの特定に役立ちます。

コミット

commit c0b9e6218c63a21e12305f8f7fbe7c92bdcbcbde
Author: Dmitriy Vyukov <dvyukov@google.com>
Date:   Thu Jan 16 12:54:46 2014 +0400

    runtime: output how long goroutines are blocked
    Example of output:
    
    goroutine 4 [sleep for 3 min]:
    time.Sleep(0x34630b8a000)
            src/pkg/runtime/time.goc:31 +0x31
    main.func·002()
            block.go:16 +0x2c
    created by main.main
            block.go:17 +0x33
    
    Full program and output are here:
    http://play.golang.org/p/NEZdADI3Td
    
    Fixes #6809.
    
    R=golang-codereviews, khr, kamil.kisiel, bradfitz, rsc
    CC=golang-codereviews
    https://golang.org/cl/50420043

GitHub上でのコミットページへのリンク

https://github.com/golang/go/commit/c0b9e6218c63a21e12305f8f7fbe7c92bdcbcbde

元コミット内容

Goランタイムにおいて、ゴルーチンがブロックされている時間を表示するように変更。

出力例:

goroutine 4 [sleep for 3 min]:
time.Sleep(0x34630b8a000)
        src/pkg/runtime/time.goc:31 +0x31
main.func·002()
        block.go:16 +0x2c
created by main.main
        block.go:17 +0x33

完全なプログラムと出力は以下のURLで確認できます: http://play.golang.org/p/NEZdADI3Td

Fixes #6809.

変更の背景

Go言語の並行処理モデルはゴルーチンとチャネルを基盤としており、非常に効率的で軽量な並行処理を可能にします。しかし、プログラムが複雑になるにつれて、特定のゴルーチンが予期せずブロックされたり、デッドロック状態に陥ったりすることがあります。このような状況では、どのゴルーチンが、なぜ、どのくらいの期間ブロックされているのかを特定することが、デバッグやパフォーマンスチューニングにおいて非常に重要になります。

このコミット以前は、Goランタイムのトレースバック出力には、ゴルーチンの状態（例: [running], [waiting]）は表示されていましたが、waitingやsyscall状態のゴルーチンがどれくらいの期間その状態にあるのかという情報は含まれていませんでした。この情報の欠如は、特に長時間ブロックされているゴルーチンを特定し、その原因を分析する上で大きな課題となっていました。

コミットメッセージにある Fixes #6809 は、この問題に対する改善要求、または関連する内部トラッキング番号を示唆しています。公開されているGoのIssue Trackerでは、この番号に直接関連する公開Issueは見つかりませんでしたが、これは内部的な追跡番号であるか、あるいはGo 1.3リリース前の古いIssueである可能性があります。いずれにせよ、この変更は、開発者がGoアプリケーションの並行処理の挙動をより深く理解し、デバッグを容易にするための重要な改善として導入されました。

前提知識の解説

このコミットの理解には、以下のGoランタイムの概念に関する知識が不可欠です。

• ゴルーチン (Goroutine): Goランタイムによって管理される軽量なスレッドです。数千、数万のゴルーチンを同時に実行することが可能で、Goの並行処理の基本単位となります。
• ゴルーチンの状態 (Goroutine Status): ゴルーチンはライフサイクルの中で様々な状態を取ります。このコミットで特に重要なのは以下の状態です。
  • Grunning: ゴルーチンが現在CPU上で実行されている状態。
  • Gwaiting: ゴルーチンが何らかのイベント（チャネル操作、タイマー、ミューテックスなど）を待っているためにブロックされている状態。
  • Gsyscall: ゴルーチンがシステムコールを実行中でブロックされている状態。
  • Gidle: ゴルーチンが実行可能であるが、実行するP（プロセッサ）がないためにアイドル状態にある。
• トレースバック (Traceback): Goプログラムがパニックを起こしたり、runtime.Stack()関数が呼び出されたりすると、現在実行中のすべてのゴルーチンのスタックトレースが出力されます。これは、プログラムの実行フローや、どのゴルーチンがどこでブロックされているかを理解するための重要なデバッグ情報です。
• runtimeパッケージ: Goランタイムの低レベルな機能を提供するパッケージです。ガベージコレクション、スケジューリング、ゴルーチン管理など、Goプログラムの実行環境を制御するC言語で書かれた部分（src/pkg/runtime以下）と、Go言語で書かれた部分から構成されます。
• nanotime(): Goランタイム内部で使用される、ナノ秒単位のモノトニック時間を返す関数です。システム時刻の変更に影響されないため、経過時間の計測に適しています。
• proc.c: Goランタイムのスケジューラとプロセッサ管理に関するC言語のソースファイルです。ゴルーチンの状態遷移や、トレースバック出力のロジックが含まれています。
• mgc0.c: Goランタイムのガベージコレクタの初期化とルートスキャンに関するC言語のソースファイルです。このコミットでは、ガベージコレクションの開始時刻を記録するために変更されています。
• runtime.h: Goランタイムの内部データ構造や定数を定義するヘッダーファイルです。ゴルーチン構造体 (struct G) の定義も含まれます。

技術的詳細

このコミットの主要な目的は、ゴルーチンがブロックされている期間をトレースバック出力に含めることです。これを実現するために、以下の技術的な変更が導入されています。

1. G構造体へのwaitsinceフィールドの追加:

   • src/pkg/runtime/runtime.hにおいて、ゴルーチンを表すstruct Gにint64 waitsince;という新しいフィールドが追加されました。
   • このwaitsinceフィールドは、ゴルーチンがGwaitingまたはGsyscall状態になったおおよその時刻（ナノ秒単位のモノトニック時間）を記録するために使用されます。

2. ブロック開始時刻の記録:

   • src/pkg/runtime/mgc0.cのaddroots関数内で、ゴルーチンがGwaitingまたはGsyscall状態になり、かつwaitsinceがまだ記録されていない（つまり、初めてブロック状態が観測された）場合に、現在の時刻（work.tstart、ガベージコレクションの開始時刻）をgp->waitsinceに設定するロジックが追加されました。
   • work.tstartは、gc関数内でガベージコレクションの開始時刻（args->start_time）で初期化されます。これは、ガベージコレクションのルートスキャン中にゴルーチンの状態をチェックするタイミングを利用して、ブロック開始時刻を記録していることを意味します。厳密なブロック開始時刻ではなく、ガベージコレクションがゴルーチンをスキャンした時点でのブロック開始時刻の「おおよそ」の値となります。

3. ブロック終了時刻のリセット:

   • src/pkg/runtime/proc.cのexecute関数（ゴルーチンが実行状態になる直前）とruntime·exitsyscall関数（システムコールから戻る際）において、gp->waitsinceが0にリセットされるようになりました。これは、ゴルーチンがブロック状態から解放され、再び実行可能になったことを示すためです。

4. トレースバック出力の変更:

   • src/pkg/runtime/proc.cのruntime·goroutineheader関数は、ゴルーチンのヘッダー情報を出力する役割を担っています。
   • この関数内で、ゴルーチンがGwaitingまたはGsyscall状態であり、かつwaitsinceが0でない場合に、現在の時刻（runtime·nanotime()）とwaitsinceの差分を計算し、ブロックされている期間を分単位で算出するロジックが追加されました。
   • 算出されたwaitfor（ブロック時間）が1分以上の場合、ゴルーチンの状態表示に「, D minutes」という形式でブロック時間が追加されるようになりました。これにより、goroutine 4 [sleep for 3 min]: のような出力が可能になります。

この変更により、Goランタイムは、ゴルーチンがブロック状態に入ったおおよその時刻を記録し、トレースバック出力時にその情報を用いてブロック期間を計算し表示するようになりました。これにより、開発者はデバッグ時にゴルーチンのブロック状況をより詳細に把握できるようになります。

コアとなるコードの変更箇所

このコミットにおける主要なコード変更は以下の4つのファイルにわたります。

1. doc/go1.3.txt:

   • Go 1.3のリリースノートに、この機能が追加されたことを示すエントリが追加されました。
   • +runtime: output how long goroutines are blocked (CL 50420043)

2. src/pkg/runtime/mgc0.c:

   • ガベージコレクションのルートスキャン中に、ゴルーチンがブロック状態になった時刻を記録するロジックが追加されました。
   • static struct { ... int64 tstart; ... } work; : work構造体にtstartフィールドが追加され、ガベージコレクションの開始時刻を保持します。
   • if((gp->status == Gwaiting || gp->status == Gsyscall) && gp->waitsince == 0)ブロック: ゴルーチンがGwaitingまたはGsyscall状態であり、かつwaitsinceが未設定の場合に、gp->waitsince = work.tstart;としてブロック開始時刻を記録します。
   • gc関数内でwork.tstart = args->start_time;として、ガベージコレクションの開始時刻をwork.tstartに設定します。

3. src/pkg/runtime/proc.c:

   • ゴルーチンのヘッダー出力ロジックが変更され、ブロック時間が表示されるようになりました。
   • runtime·goroutineheader(G *gp)関数内で、int64 waitfor;が追加されました。
   • if((gp->status == Gwaiting || gp->status == Gsyscall) && gp->waitsince != 0)ブロック: ブロック時間を計算し、waitforに格納します。
   • if(waitfor < 1)とelseブロック: waitforの値に応じて、ブロック時間を表示するかどうかを決定し、出力フォーマットを切り替えます。
   • execute(G *gp)関数内で、gp->waitsince = 0;が追加され、ゴルーチンが実行状態になる際にwaitsinceをリセットします。
   • runtime·exitsyscall(void)関数内で、g->waitsince = 0;が追加され、システムコールから戻る際にwaitsinceをリセットします。

4. src/pkg/runtime/runtime.h:

   • struct G（ゴルーチン構造体）にwaitsinceフィールドが追加されました。
   • int64 waitsince; // approx time when the G become blocked

コアとなるコードの解説

src/pkg/runtime/runtime.h の変更

struct	G
{
	// ... 既存のフィールド ...
	int16	status;
	int64	goid;
	int64	waitsince;	// approx time when the G become blocked
	int8*	waitreason;	// if status==Gwaiting
	// ... 既存のフィールド ...
};

struct Gにwaitsinceフィールドが追加されました。これは、ゴルーチンがブロック状態（GwaitingまたはGsyscall）になったおおよその時刻をナノ秒単位で記録するためのものです。

src/pkg/runtime/mgc0.c の変更

static struct {
	// ... 既存のフィールド ...
	uint32	nproc;
	int64	tstart; // 追加
	volatile uint32	nwait;
	// ... 既存のフィールド ...
} work; // work構造体はガベージコレクションの作業状態を保持

// addroots関数内
	for(i=0; i<allglen; i++) {
		gp = allg[i];
		if(gp->status == Gdead)
			continue;
		// ... 既存のロジック ...
		if((gp->status == Gwaiting || gp->status == Gsyscall) && gp->waitsince == 0)
			gp->waitsince = work.tstart; // ブロック開始時刻を記録
	}

// gc関数内
void gc(struct gc_args *args) {
	// ... 既存のロジック ...
	t0 = args->start_time;
	work.tstart = args->start_time; // ガベージコレクション開始時刻をwork.tstartに設定
	// ... 既存のロジック ...
}

work構造体にtstartが追加され、ガベージコレクションの開始時刻がここに格納されます。addroots関数は、ガベージコレクションのルートスキャン中にすべてのゴルーチンを走査します。ここで、ゴルーチンがGwaitingまたはGsyscall状態であり、かつwaitsinceがまだ設定されていない場合（つまり、このGCサイクルで初めてブロック状態が観測された場合）、work.tstart（GC開始時刻）をgp->waitsinceに設定します。これは、ブロック開始時刻の「おおよそ」の値として利用されます。

src/pkg/runtime/proc.c の変更

void runtime·goroutineheader(G *gp) {
	int8 *status;
	int64 waitfor; // 追加

	// ... gp->statusに応じたstatus文字列の設定 ...

	// approx time the G is blocked, in minutes
	waitfor = 0;
	if((gp->status == Gwaiting || gp->status == Gsyscall) && gp->waitsince != 0)
		waitfor = (runtime·nanotime() - gp->waitsince) / (60LL*1000*1000*1000); // ナノ秒を分に変換

	if(waitfor < 1)
		runtime·printf("goroutine %D [%s]:\\n", gp->goid, status);
	else
		runtime·printf("goroutine %D [%s, %D minutes]:\\n", gp->goid, status, waitfor);
}

void execute(G *gp) {
	// ... 既存のロジック ...
	gp->status = Grunning;
	gp->waitsince = 0; // 実行状態になる際にwaitsinceをリセット
	// ... 既存のロジック ...
}

void runtime·exitsyscall(void) {
	// ... 既存のロジック ...
	g->waitsince = 0; // システムコールから戻る際にwaitsinceをリセット
	// ... 既存のロジック ...
}

runtime·goroutineheader関数は、ゴルーチンのトレースバックヘッダーを生成します。ここで、ゴルーチンがGwaitingまたはGsyscall状態であり、waitsinceが設定されている場合、現在の時刻(runtime·nanotime())とwaitsinceの差分を計算し、ブロック時間を分単位で算出します。その時間が1分以上であれば、出力に「, D minutes」を追加します。

execute関数とruntime·exitsyscall関数では、ゴルーチンがブロック状態から解放され、実行可能になった際にgp->waitsinceを0にリセットします。これにより、次にブロックされたときに新しいブロック開始時刻が正確に記録されるようになります。

これらの変更により、Goランタイムはゴルーチンのブロック時間を追跡し、デバッグ出力にその情報を含めることができるようになりました。

関連リンク

• Go言語の公式ドキュメント: https://golang.org/doc/
• Goランタイムのソースコード: https://github.com/golang/go/tree/master/src/runtime
• Go Playground (コミットメッセージに記載の例): http://play.golang.org/p/NEZdADI3Td

参考にした情報源リンク

• Go言語のIssue Tracker (一般的なGoのIssue検索): https://github.com/golang/go/issues
• Goのコミット履歴 (golang/goリポジトリ): https://github.com/golang/go/commits/master
• Go 1.3 Release Notes (doc/go1.3.txtの変更が示すリリース): https://golang.org/doc/go1.3 (このコミットがGo 1.3の一部としてリリースされたことを示唆)
• Goの内部構造に関するブログ記事やドキュメント (一般的なGoランタイムの理解のため):
  • "Go's work-stealing scheduler": https://rakyll.org/scheduler/
  • "Go scheduler: MS, P, G": https://medium.com/@ankur_anand/go-scheduler-m-p-g-60e909463ee
  • "Go's Goroutine Scheduler": https://www.ardanlabs.com/blog/2018/08/go-scheduler.html

（注: Fixes #6809 に関連する公開されたGoのIssueは特定できませんでした。これは内部的なトラッキング番号であるか、非常に古いIssueである可能性があります。）