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

このコミットは、Goランタイムに新しいデバッグ機能を追加するものです。具体的には、GODEBUG環境変数にschedtraceとscheddetailというオプションを導入し、Goスケジューラの状態を定期的にダンプする機能を提供します。これにより、Goプログラムの実行中にスケジューラの挙動を詳細に監視し、パフォーマンスの問題やデッドロックなどのデバッグに役立てることができます。

コミット

commit 4f2e382c9fb646e6f34bb0d7c4fa1a0a963a3b54
Author: Dmitriy Vyukov <dvyukov@google.com>
Date:   Wed Aug 14 00:30:55 2013 +0400

    runtime: dump scheduler state if GODEBUG=schedtrace is set
    The schedtrace value sets dump period in milliseconds.
    In default mode the trace looks as follows:
    SCHED 0ms: gomaxprocs=4 idleprocs=0 threads=3 idlethreads=0 runqueue=0 [1 0 0 0]
    SCHED 1001ms: gomaxprocs=4 idleprocs=3 threads=6 idlethreads=3 runqueue=0 [0 0 0 0]
    SCHED 2008ms: gomaxprocs=4 idleprocs=1 threads=6 idlethreads=1 runqueue=0 [0 1 0 0]
    If GODEBUG=scheddetail=1 is set as well, then the detailed trace is printed:
    SCHED 0ms: gomaxprocs=4 idleprocs=0 threads=3 idlethreads=0 runqueue=0 singleproc=0 gcwaiting=1 mlocked=0 nmspinning=0 stopwait=0 sysmonwait=0
      P0: status=3 tick=1 m=0 runqsize=1/128 gfreecnt=0
      P1: status=3 tick=0 m=-1 runqsize=0/128 gfreecnt=0
      P2: status=3 tick=0 m=-1 runqsize=0/128 gfreecnt=0
      P3: status=3 tick=0 m=-1 runqsize=0/128 gfreecnt=0
      M2: p=-1 curg=-1 mallocing=0 throwing=0 gcing=0 locks=1 dying=0 helpgc=0 spinning=0 lockedg=-1
      M1: p=-1 curg=-1 mallocing=0 throwing=0 gcing=0 locks=1 dying=0 helpgc=0 spinning=0 lockedg=-1
      M0: p=0 curg=1 mallocing=0 throwing=0 gcing=0 locks=1 dying=0 helpgc=0 spinning=0 lockedg=1
      G1: status=2() m=0 lockedm=0
      G2: status=1() m=-1 lockedm=-1
    
    R=golang-dev, raggi, rsc
    CC=golang-dev
    https://golang.org/cl/11435044

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

https://github.com/golang/go/commit/4f2e382c9fb646e6f34bb0d7c4fa1a0a963a3b54

元コミット内容

このコミットは、Goランタイムにスケジューラのデバッグトレース機能を追加します。GODEBUG=schedtraceを設定すると、指定されたミリ秒間隔でスケジューラの状態がダンプされます。さらにGODEBUG=scheddetail=1を設定すると、より詳細なスケジューラ、プロセッサ（P）、スレッド（M）、ゴルーチン（G）の状態情報が出力されます。

変更の背景

Goのランタイムスケジューラは、ゴルーチンを効率的にOSスレッドにマッピングし、並行処理を実現する上で非常に重要な役割を担っています。しかし、複雑な並行プログラムでは、スケジューラの挙動が予期せぬパフォーマンスボトルネックやデッドロックの原因となることがあります。

このコミットが導入される以前は、Goスケジューラの内部状態を詳細に把握するための組み込みツールが限られていました。開発者は、スケジューラがどのようにゴルーチンをP（プロセッサ）に割り当て、M（OSスレッド）上で実行しているのか、あるいはアイドル状態のPやMがどれくらいあるのかといった情報を、直接的に取得することが困難でした。

このような状況では、Goプログラムのパフォーマンスチューニングやデバッグにおいて、スケジューラの挙動を推測するしかなく、問題の特定と解決に時間がかかることがありました。このコミットは、このようなデバッグの困難さを解消し、スケジューラのリアルタイムな状態を可視化することで、開発者がより効率的に問題を診断できるようにすることを目的としています。

特に、scheddetailオプションは、各P、M、Gの個別の状態まで掘り下げて表示するため、特定のゴルーチンがなぜ実行されないのか、あるいは特定のOSスレッドがなぜアイドル状態になっているのかといった、より粒度の細かい分析を可能にします。

前提知識の解説

このコミットの理解には、Goランタイムのスケジューラモデルに関する基本的な知識が不可欠です。

• Goroutine (G): Goにおける軽量な実行単位です。OSスレッドよりもはるかに軽量で、数百万個のゴルーチンを同時に実行できます。Goランタイムが管理し、OSスレッドにマッピングされます。
• Logical Processor (P): 論理プロセッサは、Goスケジューラがゴルーチンを実行するために必要なコンテキストを提供します。Pの数は通常、GOMAXPROCS環境変数によって設定され、CPUコアの数に一致させることが推奨されます。各Pはローカルな実行キューを持ち、そこにゴルーチンが配置されます。
• Machine (M): OSスレッドを表します。MはPにアタッチされ、Pのローカルキューからゴルーチンを取り出して実行します。Mはシステムコールを実行したり、ブロッキング操作を行ったりする際に、Pからデタッチされることがあります。
• GOMAXPROCS: Goプログラムが同時に実行できるOSスレッド（M）の最大数を制御する環境変数です。これは、Goスケジューラが利用できるPの数に直接影響します。
• GODEBUG: Goランタイムのデバッグオプションを設定するための環境変数です。name=valの形式で複数のオプションをカンマ区切りで指定できます。例えば、GODEBUG=gctrace=1はGCのトレースを有効にします。
• スケジューラの役割: Goスケジューラは、多数のゴルーチンを限られた数のOSスレッド（M）と論理プロセッサ（P）に効率的に割り当てる役割を担います。これにより、並行処理のオーバーヘッドを最小限に抑えつつ、高いスループットと応答性を実現します。スケジューラは、ゴルーチンの生成、実行、ブロック、再開、そしてPとMの管理を行います。

技術的詳細

このコミットによって導入されたGODEBUG=schedtraceおよびGODEBUG=scheddetailは、Goランタイムの内部状態を可視化するための強力なデバッグツールです。

• GODEBUG=schedtrace=X:

  • Xはミリ秒単位のダンプ間隔を指定します。例えば、schedtrace=1000と設定すると、1秒ごとにスケジューラの概要情報が標準エラー出力にダンプされます。
  • 出力される情報は、gomaxprocs（利用可能なPの数）、idleprocs（アイドル状態のPの数）、threads（OSスレッドの総数）、idlethreads（アイドル状態のOSスレッドの数）、runqueue（グローバル実行キューのゴルーチン数）、そして各Pのローカル実行キューのゴルーチン数（例: [1 0 0 0]）を含みます。
  • この概要情報は、システム全体のスケジューラの負荷状況や、P間のゴルーチン分散の偏りなどを大まかに把握するのに役立ちます。

• GODEBUG=scheddetail=1:

  • schedtraceと同時に設定することで、より詳細なスケジューラ、P、M、Gの状態情報がダンプされます。
  • スケジューラ全体の状態: singleproc, gcwaiting, mlocked, nmspinning, stopwait, sysmonwaitなどのフラグが表示され、スケジューラの特定の内部状態（例: GCが待機中か、Mがスピン中かなど）を示します。
  • P（論理プロセッサ）の状態: 各Pについて、status（Pの状態、例: アイドル、実行中）、schedtick（スケジューラ呼び出し回数）、syscalltick（システムコール呼び出し回数）、m（アタッチされているMのID）、runqsize（ローカル実行キューのゴルーチン数）、gfreecnt（解放されたゴルーチンの数）などが表示されます。これにより、各Pの稼働状況や負荷を詳細に分析できます。
  • M（OSスレッド）の状態: 各Mについて、p（アタッチされているPのID）、curg（現在実行中のゴルーチンのID）、mallocing（メモリ割り当て中か）、throwing（パニック中か）、gcing（GC中か）、locks（ロック数）、dying（終了中か）、helpgc（GCヘルパーか）、spinning（スピン中か）、lockedg（ロックされているゴルーチンのID）などが表示されます。これにより、各OSスレッドの役割や状態を把握できます。
  • G（ゴルーチン）の状態: 各Gについて、goid（ゴルーチンID）、status（ゴルーチンの状態、例: 実行可能、実行中、ブロック中）、waitreason（ブロックされている理由）、m（実行中のMのID）、lockedm（ロックされているMのID）などが表示されます。これにより、個々のゴルーチンのライフサイクルや、なぜ特定のゴルーチンがブロックされているのかを追跡できます。

これらの情報は、Goプログラムのデバッグにおいて以下のようなシナリオで非常に有用です。

• パフォーマンスボトルネックの特定: idleprocsやidlethreadsが多い場合、CPUリソースが十分に活用されていない可能性があります。runqueueや各Pのrunqsizeが大きい場合、ゴルーチンが実行待ちになっている可能性があり、GOMAXPROCSの調整やコードの最適化が必要かもしれません。
• デッドロックの診断: scheddetailで各ゴルーチンのstatusやwaitreasonを確認することで、どのゴルーチンがどのリソースを待っているのか、あるいはどのゴルーチンがブロックされているのかを特定し、デッドロックの原因を突き止める手がかりを得られます。
• スケジューラの挙動理解: 複雑な並行処理パターンを持つアプリケーションにおいて、スケジューラがどのようにゴルーチンをPとMに割り当て、コンテキストスイッチを行っているのかをリアルタイムで観察できます。

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

このコミットでは、主に以下のファイルが変更されています。

• src/pkg/runtime/extern.go: GODEBUG環境変数の説明にschedtraceとscheddetailが追加されました。
• src/pkg/runtime/panic.c: パニック発生時にschedtraceを呼び出す処理が追加されました。
• src/pkg/runtime/proc.c:
  • procresize関数内でP構造体にidを割り当てる処理が追加されました。
  • sysmon関数にスケジューラトレースの定期的なダンプロジックが追加されました。
  • runtime·schedtrace関数が新規に追加されました。この関数がスケジューラ状態のダンプ処理の本体です。
• src/pkg/runtime/runtime.c: GODEBUGの解析対象変数としてschedtraceとscheddetailが追加されました。
• src/pkg/runtime/runtime.h:
  • P構造体にidフィールドが追加されました。
  • DebugVars構造体にschedtraceとscheddetailフィールドが追加されました。
  • runtime·schedtrace関数のプロトタイプ宣言が追加されました。

コアとなるコードの解説

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

struct P
{
    // ...
    int32   id; // 新しく追加されたPのID
    // ...
};

struct DebugVars
{
    int32   gctrace;
    int32   schedtrace; // 新しく追加されたschedtraceのGODEBUG値
    int32   scheddetail; // 新しく追加されたscheddetailのGODEBUG値
};

// ...
void    runtime·schedtrace(bool); // schedtrace関数のプロトタイプ宣言

P構造体にidフィールドが追加され、各論理プロセッサを一意に識別できるようになりました。DebugVars構造体には、GODEBUG環境変数から読み取られるschedtraceとscheddetailの値が格納されるフィールドが追加されています。runtime·schedtraceは、スケジューラ情報をダンプする新しい関数のプロトタイプ宣言です。

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

static struct {
    int32*  value;
} dbgvar[] = {
    {"gctrace", &runtime·debug.gctrace},
    {"schedtrace", &runtime·debug.schedtrace}, // GODEBUGの解析対象に追加
    {"scheddetail", &runtime·debug.scheddetail}, // GODEBUGの解析対象に追加
};

GODEBUG環境変数を解析する際に、schedtraceとscheddetailの値をruntime·debug構造体の対応するフィールドにマッピングするように設定が追加されました。これにより、Goプログラムの起動時にこれらのデバッグオプションを環境変数経由で設定できるようになります。

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

procresize 関数

procresize(int32 new)
{
    // ...
    if(p == nil) {
        p = (P*)runtime·mallocgc(sizeof(*p), 0, FlagNoInvokeGC);
        p->id = i; // PのIDを初期化
        p->status = Pgcstop;
        runtime·atomicstorep(&runtime·allp[i], p);
    }
    // ...
}

procresize関数は、GOMAXPROCSの変更などによってPの数が調整される際に呼び出されます。ここで新しく作成されるPに対して、そのインデックスiをp->idとして割り当てる処理が追加されました。これにより、トレース出力時に各Pを一意に識別できるようになります。

sysmon 関数

static void
sysmon(void)
{
    // ...
    int64 now, lastpoll, lasttrace; // lasttraceが追加
    // ...
    lasttrace = 0; // lasttraceの初期化
    // ...
    for(;;) {
        // ...
        // schedtraceが設定されている場合、定期的にschedtraceを呼び出す
        if(runtime·debug.schedtrace > 0 && lasttrace + runtime·debug.schedtrace*1000000ll <= now) {
            lasttrace = now;
            runtime·schedtrace(runtime·debug.scheddetail);
        }
    }
}

sysmon（システムモニター）は、Goランタイムのバックグラウンドで動作し、GCのトリガー、ネットワークポーリング、アイドル状態のPの解放など、様々なハウスキーピングタスクを実行するM（OSスレッド）です。この関数内に、GODEBUG=schedtraceが設定されている場合に、指定された間隔（runtime·debug.schedtraceミリ秒）でruntime·schedtrace関数を呼び出すロジックが追加されました。これにより、スケジューラの状態が定期的にダンプされるようになります。

runtime·schedtrace 関数 (新規追加)

void
runtime·schedtrace(bool detailed)
{
    static int64 starttime; // トレース開始時刻
    int64 now;
    int32 i, q, t, h, s;
    int8 *fmt;
    M *mp, *lockedm;
    G *gp, *lockedg;
    P *p;

    now = runtime·nanotime();
    if(starttime == 0)
        starttime = now; // 初回呼び出し時に開始時刻を記録

    runtime·lock(&runtime·sched); // スケジューラロックを取得

    // 概要情報の出力
    runtime·printf("SCHED %Dms: gomaxprocs=%d idleprocs=%d threads=%d idlethreads=%d runqueue=%d",
        (now-starttime)/1000000, runtime·gomaxprocs, runtime·sched.npidle, runtime·sched.mcount,
        runtime·sched.nmidle, runtime·sched.runqsize);

    if(detailed) { // 詳細モードの場合、追加情報を出力
        runtime·printf(" gcwaiting=%d nmidlelocked=%d nmspinning=%d stopwait=%d sysmonwait=%d\\n",
            runtime·gcwaiting, runtime·sched.nmidlelocked, runtime·sched.nmspinning,
            runtime·sched.stopwait, runtime·sched.sysmonwait);
    }

    // 各Pの状態を出力
    for(i = 0; i < runtime·gomaxprocs; i++) {
        p = runtime·allp[i];
        if(p == nil)
            continue;
        // Pのローカルキューのゴルーチン数を計算
        t = p->runqtail;
        h = p->runqhead;
        s = p->runqsize;
        q = t - h;
        if(q < 0)
            q += s;

        if(detailed) { // 詳細モードの場合、Pの詳細情報を出力
            runtime·printf("  P%d: status=%d schedtick=%d syscalltick=%d m=%d runqsize=%d/%d gfreecnt=%d\\n",
                i, p->status, p->schedtick, p->syscalltick, mp ? mp->id : -1, q, s, p->gfreecnt);
        } else { // 概要モードの場合、Pのローカルキューサイズのみ出力
            // ... フォーマット調整 ...
            runtime·printf(fmt, q);
        }
    }

    if(!detailed) { // 概要モードの場合、ここでロックを解放して終了
        runtime·unlock(&runtime·sched);
        return;
    }

    // 詳細モードの場合、MとGの状態を出力
    // 各Mの状態を出力
    for(mp = runtime·allm; mp; mp = mp->alllink) {
        // ... Mの詳細情報を出力 ...
    }

    // 各Gの状態を出力
    for(gp = runtime·allg; gp; gp = gp->alllink) {
        // ... Gの詳細情報を出力 ...
    }

    runtime·unlock(&runtime·sched); // スケジューラロックを解放
}

runtime·schedtrace関数は、スケジューラ状態のダンプ処理の核心です。

1. 時刻の記録: 初回呼び出し時にstarttimeを記録し、以降の出力ではstarttimeからの経過時間をミリ秒単位で表示します。
2. スケジューラロック: スケジューラの内部状態を読み取る前にruntime·lock(&runtime·sched)でスケジューラロックを取得し、一貫性のあるデータを読み取ることを保証します。
3. 概要情報の出力: gomaxprocs, idleprocs, threads, idlethreads, runqueue（グローバル実行キュー）の情報を出力します。
4. 詳細情報の追加: detailedがtrueの場合（scheddetail=1が設定されている場合）、gcwaiting, nmidlelocked, nmspinningなどの追加のスケジューラ状態フラグを出力します。
5. Pの状態出力: runtime·allp配列をイテレートし、各Pのstatus, schedtick, syscalltick, アタッチされているMのID、ローカル実行キューのサイズなどを出力します。詳細モードでない場合は、各Pのローカルキューサイズのみを[len1 len2 ...]形式で出力します。
6. Mの状態出力: detailedがtrueの場合、runtime·allmリンクリストをイテレートし、各MのPのID、現在実行中のGのID、mallocing, throwing, gcingなどの状態フラグ、ロック数などを出力します。
7. Gの状態出力: detailedがtrueの場合、runtime·allgリンクリストをイテレートし、各GのID、status, waitreason, 実行中のMのID、ロックされているMのIDなどを出力します。
8. スケジューラロック解放: 処理の最後にruntime·unlock(&runtime·sched)でスケジューラロックを解放します。

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

runtime·startpanic(void)
{
    // ...
    if(runtime·debug.schedtrace > 0 || runtime·debug.scheddetail > 0)
        runtime·schedtrace(true); // パニック時に詳細なスケジューラトレースを出力
    runtime·freezetheworld();
}

runtime·startpanic関数は、Goプログラムがパニックを起こした際に呼び出されます。この変更により、schedtraceまたはscheddetailが有効になっている場合、パニック発生直前にruntime·schedtrace(true)が呼び出され、詳細なスケジューラ状態がダンプされるようになりました。これは、パニックの原因がスケジューラのデッドロックや異常な状態にある場合に、その瞬間のスケジューラ状態を把握するための重要なデバッグ情報を提供します。

これらの変更により、Go開発者はGODEBUG環境変数を設定するだけで、Goスケジューラの内部挙動を詳細に観察し、パフォーマンス問題や並行処理のバグを効率的に診断できるようになりました。

関連リンク

• Go言語公式ドキュメント: https://golang.org/
• Goランタイムスケジューラに関する記事 (一般的な情報): https://go.dev/doc/articles/go_scheduler.html (これは一般的な情報源であり、このコミットに直接関連するものではありませんが、背景知識として役立ちます)
• GODEBUG環境変数に関するGoのドキュメント: https://pkg.go.dev/runtime/debug#SetGCPercent (このコミットで追加されたschedtraceとscheddetailもここに記載されています)

参考にした情報源リンク

• Goのソースコード (特にsrc/runtimeディレクトリ): https://github.com/golang/go/tree/master/src/runtime
• Goのコミット履歴: https://github.com/golang/go/commits/master
• Goのコードレビューシステム (Gerrit): https://go-review.googlesource.com/ (コミットメッセージに記載されているhttps://golang.org/cl/11435044は、このGerritの変更リストへのリンクです)
• GoのIssueトラッカー: https://github.com/golang/go/issues
• Goのメーリングリスト (golang-dev): https://groups.google.com/g/golang-dev
• Goのスケジューラに関する一般的な解説記事やブログポスト (Web検索を通じて得られた情報)