Keyboard shortcuts

Press ← or → to navigate between chapters

Press S or / to search in the book

Press ? to show this help

Press Esc to hide this help

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

このコミットは、Goランタイムのガベージコレクション（GC）における「Stop-the-World (STW)」時間の計測方法を改善するものです。具体的には、GOGCTRACEの出力において、STW時間をこれまでのマークフェーズに含めるのではなく、「その他 (other)」のセクションとして独立して計上するように変更しています。これにより、GCのSTWフェーズが長くなった際に、その原因をより容易に診断できるようになります。

コミット

commit fd32ac4bae462672b8b6b3737111f3c213f7230a
Author: Dmitriy Vyukov <dvyukov@google.com>
Date:   Tue Jan 22 13:44:49 2013 +0400

    runtime: account stop-the-world time in the "other" GOGCTRACE section
    Currently it's summed to mark phase.
    The change makes it easier to diagnose long stop-the-world phases.
    
    R=golang-dev, bradfitz, dave
    CC=golang-dev
    https://golang.org/cl/7182043

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

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

元コミット内容

runtime: account stop-the-world time in the "other" GOGCTRACE section
Currently it's summed to mark phase.
The change makes it easier to diagnose long stop-the-world phases.

変更の背景

Goのガベージコレクション（GC）は、アプリケーションの実行中に不要になったメモリを自動的に解放する重要なプロセスです。このGCプロセスには、アプリケーションの実行を一時的に停止させる「Stop-the-World (STW)」フェーズが存在します。STWフェーズ中は、すべてのゴルーチンが停止し、GCが安全にメモリを操作できるようになります。しかし、このSTWフェーズが長くなると、アプリケーションの応答性が低下し、ユーザー体験に悪影響を与える可能性があります。

以前のGoランタイムでは、GCのSTW時間がGOGCTRACEの出力において、マークフェーズ（オブジェクトが到達可能かどうかを識別するフェーズ）の時間に合算されていました。このため、GCのSTWフェーズが異常に長くなった場合でも、その時間がマークフェーズの一部として表示されるため、STW自体がボトルネックになっているのか、それともマークフェーズの処理自体が遅いのかを区別することが困難でした。

このコミットの目的は、GOGCTRACEの出力においてSTW時間を「その他 (other)」のセクションとして独立して計上することで、STWフェーズの長さをより明確に可視化し、開発者がGCのパフォーマンス問題を診断しやすくすることにあります。これにより、STWが長引く根本原因（例えば、GCのトリガー頻度、ヒープサイズ、特定のコードパスなど）を特定し、最適化の方向性を定めることが容易になります。

前提知識の解説

このコミットを理解するためには、以下のGoランタイムおよびガベージコレクションに関する前提知識が必要です。

Goのガベージコレクション (GC)

GoのGCは、並行マーク・スイープ方式を採用しています。これは、GCの大部分の処理がアプリケーションのゴルーチンと並行して実行されることを意味します。しかし、GCの特定のフェーズでは、アプリケーションの実行を一時的に停止させる必要があります。これが「Stop-the-World (STW)」フェーズです。

Stop-the-World (STW)

STWフェーズは、GCがメモリの状態を安全にスナップショットしたり、ポインタを更新したりするために必要です。GoのGCにおける主なSTWフェーズは以下の通りです。

  • GC開始時のSTW: GCが開始される際に、すべてのゴルーチンを停止し、GCの初期設定やヒープのスナップショットを行います。
  • GC終了時のSTW: GCが完了する際に、最終的なクリーンアップや状態の更新を行います。

STW時間は、アプリケーションのレイテンシに直接影響するため、GoランタイムはSTW時間を最小限に抑えるように設計されています。

GOGCTRACE 環境変数

GOGCTRACEは、Goプログラムの実行中にガベージコレクションのトレース情報を標準エラー出力（stderr）に出力するための環境変数です。GOGCTRACE=1を設定してプログラムを実行すると、GCの各サイクルに関する詳細な情報が表示されます。この情報には、GCの実行回数、各フェーズにかかった時間、ヒープの使用量、オブジェクトの数などが含まれます。

GOGCTRACEの出力形式は以下のようになります（変更前の一般的な形式）：

gc<N>(<P>): <mark_time>+<sweep_time>+<other_time> ms, <heap_before> -> <heap_after> MB <objects_before> -> <objects_after> (<total_alloc>-<free_objects>) objects, ...
  • <N>: GCの実行回数
  • <P>: GCに参加したプロセッサ（P）の数
  • <mark_time>: マークフェーズにかかった時間
  • <sweep_time>: スイープフェーズにかかった時間
  • <other_time>: その他のGC処理にかかった時間（このコミットでSTW時間がここに含まれるようになる）
  • <heap_before>: GC前のヒープ使用量
  • <heap_after>: GC後のヒープ使用量

runtime.nanotime()

runtime.nanotime()は、Goランタイム内部で使用される高精度な時間計測関数です。これは、システム起動からの経過時間をナノ秒単位で返します。GCの各フェーズの時間を計測するために使用されます。

mstats 構造体

mstatsは、Goランタイムのメモリ統計情報を保持する構造体です。GCの実行回数 (numgc)、最後のGCのタイムスタンプ (last_gc)、STWポーズ時間 (pause_ns, pause_total_ns) など、GCに関する様々な統計情報が含まれています。

parfordo

parfordoは、Goランタイム内部で並行処理を行うためのユーティリティ関数です。GCのマークフェーズやスイープフェーズなど、並行して実行できる処理に使用されます。

scanblock

scanblockは、GCのマークフェーズにおいて、メモリブロックをスキャンして到達可能なオブジェクトをマークする関数です。

sweepfor

sweepforは、GCのスイープフェーズにおいて、不要になったメモリを解放する処理を並行して実行するための構造体です。

stealcache

stealcacheは、GCの並行処理において、他のプロセッサから作業を「盗む」ことで、作業負荷のバランスを取るメカニズムに関連する関数です。

cachestats

cachestatsは、GCのキャッシュに関する統計情報を収集する関数です。

技術的詳細

このコミットの技術的な核心は、runtime/mgc0.cファイル内のGC統計情報の計測ロジックの変更にあります。

変更前は、GCの開始時刻 (t0) からマークフェーズの終了時刻 (t1) までの時間がマークフェーズとして計上され、スイープフェーズの開始時刻 (t1) からスイープフェーズの終了時刻 (t2) までの時間がスイープフェーズとして計上されていました。そして、GC全体の終了時刻 (t3) からスイープフェーズの終了時刻 (t2) までの時間が「その他」のセクションとして計上されていました。

問題は、GC開始時のSTWフェーズがt0からt1の間に含まれており、マークフェーズの時間に合算されていた点です。同様に、GC終了時のSTWフェーズもt2からt3の間に含まれていました。

このコミットでは、新しいタイムスタンプ変数 t4 を導入し、時間の計測ポイントを調整しています。

  1. GC開始時のSTW時間の分離:

    • GC開始時刻をt0とします。
    • 並行ヘルパーがGC作業を完了した直後（runtime·helpgc(work.nproc); の後）にt1 = runtime·nanotime(); を呼び出します。このt1は、GC開始時のSTWフェーズが終了し、並行マークフェーズが実質的に開始される直前の時間を示します。
    • これにより、t1 - t0 がGC開始時のSTW時間として明確に分離されます。

  2. マークフェーズとスイープフェーズの計測点の調整:

    • マークフェーズの終了時刻をt2 = runtime·nanotime(); とします。これは、scanblockやparfordo(work.markfor)などのマーク処理が完了した直後です。
    • スイープフェーズの終了時刻をt3 = runtime·nanotime(); とします。これは、parfordo(work.sweepfor)などのスイープ処理が完了した直後です。
    • これにより、t2 - t1 が純粋なマークフェーズの時間、t3 - t2 が純粋なスイープフェーズの時間として計測されます。

  3. GC終了時のSTW時間の分離と「その他」への合算:

    • GC全体の終了時刻をt4 = runtime·nanotime(); とします。
    • GOGCTRACEの出力において、「その他」のセクションの時間を (t1-t0 + t4-t3) と計算するように変更します。これは、GC開始時のSTW時間 (t1-t0) とGC終了時のSTW時間 (t4-t3) を合計したものです。

この変更により、GOGCTRACEの出力は以下のようになります。

gc<N>(<P>): <mark_time>+<sweep_time>+<stw_time> ms, ...

ここで、<stw_time>はGC開始時と終了時のSTW時間の合計を表し、以前はマークフェーズに隠れていたSTW時間が独立して表示されるようになります。これにより、開発者はGCのパフォーマンスプロファイリングにおいて、STWがボトルネックになっているかどうかを直接的に判断できるようになります。

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

src/pkg/runtime/mgc0.c ファイルの変更点です。

diff --git a/src/pkg/runtime/mgc0.c b/src/pkg/runtime/mgc0.c
index 994bb3f64c..a658895489 100644
--- a/src/pkg/runtime/mgc0.c
+++ b/src/pkg/runtime/mgc0.c
@@ -1474,7 +1474,7 @@ runtime·gc(int32 force)
 static void
 gc(struct gc_args *args)
 {
-	int64 t0, t1, t2, t3;
+	int64 t0, t1, t2, t3, t4;
 	uint64 heap0, heap1, obj0, obj1;
 	GCStats stats;
 	M *mp;
@@ -1528,6 +1528,8 @@ gc(struct gc_args *args)
 		runtime·helpgc(work.nproc);
 	}
 
+	t1 = runtime·nanotime();
+
 	runtime·parfordo(work.markfor);
 	scanblock(nil, nil, 0, true);
 
@@ -1536,10 +1538,10 @@ gc(struct gc_args *args)
 			debug_scanblock(work.roots[i].p, work.roots[i].n);
 		runtime·atomicstore(&work.debugmarkdone, 1);
 	}
-	t1 = runtime·nanotime();
+	t2 = runtime·nanotime();
 
 	runtime·parfordo(work.sweepfor);
-	t2 = runtime·nanotime();
+	t3 = runtime·nanotime();
 
 	stealcache();
 	cachestats(&stats);
@@ -1569,18 +1571,18 @@ gc(struct gc_args *args)
 	heap1 = mstats.heap_alloc;
 	obj1 = mstats.nmalloc - mstats.nfree;
 
-	t3 = runtime·nanotime();
-	mstats.last_gc = t3;
-	mstats.pause_ns[mstats.numgc%nelem(mstats.pause_ns)] = t3 - t0;
-	mstats.pause_total_ns += t3 - t0;
+	t4 = runtime·nanotime();
+	mstats.last_gc = t4;
+	mstats.pause_ns[mstats.numgc%nelem(mstats.pause_ns)] = t4 - t0;
+	mstats.pause_total_ns += t4 - t0;
 	mstats.numgc++;
 	if(mstats.debuggc)
-		runtime·printf("pause %D\n", t3-t0);
+		runtime·printf("pause %D\n", t4-t0);
 
 	if(gctrace) {
 		runtime·printf("gc%d(%d): %D+%D+%D ms, %D -> %D MB %D -> %D (%D-%D) objects,\"\n",
-			mstats.numgc, work.nproc, (t1-t0)/1000000, (t2-t1)/1000000, (t3-t2)/1000000,
+			mstats.numgc, work.nproc, (t2-t1)/1000000, (t3-t2)/1000000, (t1-t0+t4-t3)/1000000,
 			heap0>>20, heap1>>20, obj0, obj1,
 			mstats.nmalloc, mstats.nfree,
 			stats.nhandoff, stats.nhandoffcnt,

コアとなるコードの解説

  1. int64 t0, t1, t2, t3, t4; の追加:

    • t4という新しいint64型の変数が追加されました。これはGC全体の終了時刻を記録するために使用されます。

  2. t1 = runtime·nanotime(); の移動と追加:

    • 変更前は、t1はマークフェーズの終了時刻を記録していました。
    • 変更後、runtime·helpgc(work.nproc); の直後に t1 = runtime·nanotime(); が追加されました。これにより、t1はGC開始時のSTWフェーズが終了した直後の時刻を記録するようになります。

  3. t2 = runtime·nanotime(); の変更:

    • 変更前は、t2はスイープフェーズの終了時刻を記録していました。
    • 変更後、マーク処理（scanblockなど）が完了した直後に t2 = runtime·nanotime(); が配置されました。これにより、t2はマークフェーズの終了時刻を記録するようになります。

  4. t3 = runtime·nanotime(); の変更:

    • 変更前は、t3はGC全体の終了時刻を記録していました。
    • 変更後、スイープ処理（runtime·parfordo(work.sweepfor);）が完了した直後に t3 = runtime·nanotime(); が配置されました。これにより、t3はスイープフェーズの終了時刻を記録するようになります。

  5. t4 = runtime·nanotime(); の追加:

    • GCの最終的な統計情報が計算される直前に t4 = runtime·nanotime(); が追加されました。これはGC全体の終了時刻を正確に記録します。

  6. mstats の更新ロジックの変更:

    • mstats.last_gc, mstats.pause_ns, mstats.pause_total_ns の更新において、以前はt3を使用していた箇所がt4を使用するように変更されました。これにより、GC全体のポーズ時間が正確に記録されます。

  7. gctrace 出力フォーマットの変更:

    • 最も重要な変更は、runtime·printfによるgctraceの出力フォーマットです。
    • 変更前: (t1-t0)/1000000, (t2-t1)/1000000, (t3-t2)/1000000
      • これはそれぞれ、GC開始からマーク終了、マーク終了からスイープ終了、スイープ終了からGC終了までの時間をミリ秒で表示していました。
    • 変更後: (t2-t1)/1000000, (t3-t2)/1000000, (t1-t0+t4-t3)/1000000
      • t2-t1: GC開始時のSTW後からマーク終了までの時間（純粋なマークフェーズ時間）
      • t3-t2: マーク終了からスイープ終了までの時間（純粋なスイープフェーズ時間）
      • (t1-t0+t4-t3): GC開始時のSTW時間 (t1-t0) とGC終了時のSTW時間 (t4-t3) の合計。これがGOGCTRACEの「その他」のセクションとして表示されるようになります。

これらの変更により、GOGCTRACEの出力は、マーク、スイープ、そしてSTWを含む「その他」の時間を明確に分離して表示するようになり、GCのパフォーマンス分析がより容易になりました。

関連リンク

  • Goのガベージコレクションに関する公式ドキュメントやブログ記事
  • GOGCTRACE環境変数の詳細な解説
  • Goランタイムのソースコード（src/runtime/mgc.go や src/runtime/mgc0.c など）

参考にした情報源リンク

  • Goの公式ドキュメント: https://golang.org/doc/
  • Goのガベージコレクションに関するブログ記事や解説（例: "Go's Garbage Collector: From 1.3 to 1.5 and beyond" など）
  • Goのソースコード: https://github.com/golang/go
  • GoのIssueトラッカーやChange List (CL) のアーカイブ
  • GOGCTRACEに関する情報源 (例: https://pkg.go.dev/runtime/debug#SetGCPercent の関連情報や、Goのパフォーマンスチューニングに関する記事)
  • GoのGCに関する技術的な議論や論文