Go Wiki: Goプログラムのパフォーマンス問題のデバッグ

– 元々 Dmitry Vyukov 氏によって書かれました

Goプログラムがあり、そのパフォーマンスを改善したいとします。このタスクに役立ついくつかのツールが利用可能です。これらのツールは、様々な種類のホットスポット（CPU、IO、メモリ）を特定するのに役立ちます。ホットスポットとは、パフォーマンスを大幅に改善するために集中すべき場所です。しかし、別の結果も考えられます。ツールは、プログラムの明らかなパフォーマンスの欠陥を特定するのに役立ちます。例えば、プログラム起動時に一度準備できるSQLステートメントを、クエリごとに準備している場合などです。別の例としては、明らかなO(N)アルゴリズムが存在し、それが期待される場所になぜかO(N^2)アルゴリズムが紛れ込んでしまった場合です。このようなケースを特定するには、プロファイルで表示される内容を健全性チェックする必要があります。例えば、最初のケースでは、SQLステートメントの準備にかなりの時間が費やされていることが危険信号となります。

パフォーマンスの様々な制限要因を理解することも重要です。例えば、プログラムが100Mbpsのネットワークリンクを介して通信し、すでに90Mbps以上を利用している場合、プログラムを改善してパフォーマンスを向上させるためにできることはほとんどありません。ディスクIO、メモリ消費、計算タスクにも同様の制限要因があります。これを念頭に置いて、利用可能なツールを見ていきましょう。

注：ツールは互いに干渉する可能性があります。例えば、精密なメモリプロファイリングはCPUプロファイルを歪め、ゴルーチンブロッキングプロファイリングはスケジューラトレースに影響を与えるなどです。より正確な情報を得るには、ツールを個別に使用してください。

CPUプロファイラ

Goランタイムには組み込みのCPUプロファイラが含まれており、どの関数がCPU時間の何パーセントを消費しているかを示します。これにアクセスするには3つの方法があります。

  1. 最も簡単なのは、「go test」コマンドの -cpuprofile フラグです (https://pkg.go.dev/cmd/go/#hdr-Description_of_testing_flags)。例えば、次のコマンドは

    $ go test -run=none -bench=ClientServerParallel4 -cpuprofile=cprof net/http

    与えられたベンチマークをプロファイルし、CPUプロファイルを「cprof」ファイルに書き込みます。次に

    $ go tool pprof --text http.test cprof

    最も頻繁に実行される関数のリストが出力されます。

    いくつかの出力タイプが利用可能で、最も便利なものは：--text、--web、--listです。完全なリストを取得するにはgo tool pprofを実行してください。このオプションの明らかな欠点は、テスト専用であることです。

  2. net/http/pprof: これはネットワークサーバーに理想的なソリューションです。単にnet/http/pprofをインポートし、以下のコマンドでプロファイルを収集するだけです。

    $ go tool pprof --text mybin  http://myserver:6060:/debug/pprof/profile

  3. 手動プロファイル収集。runtime/pprof をインポートし、以下のコードをmain関数に追加する必要があります。

    if *flagCpuprofile != "" {
    f, err := os.Create(*flagCpuprofile)
    if err != nil {
        log.Fatal(err)
    }
    pprof.StartCPUProfile(f)
    defer pprof.StopCPUProfile()
}

    プロファイルは指定されたファイルに書き込まれ、最初のオプションと同じ方法で視覚化されます。

以下は、--webオプションで可視化されたプロファイルの例です：[cpu_profile.png]

--list=funcnameオプションで単一の関数を調査できます。例えば、次のプロファイルはappend関数で時間が費やされたことを示しています。

 .      .   93: func (bp *buffer) WriteRune(r rune) error {
 .      .   94:     if r < utf8.RuneSelf {
 5      5   95:         *bp = append(*bp, byte(r))
 .      .   96:         return nil
 .      .   97:     }
 .      .   98:
 .      .   99:     b := *bp
 .      .  100:     n := len(b)
 .      .  101:     for n+utf8.UTFMax > cap(b) {
 .      .  102:         b = append(b, 0)
 .      .  103:     }
 .      .  104:     w := utf8.EncodeRune(b[n:n+utf8.UTFMax], r)
 .      .  105:     *bp = b[:n+w]
 .      .  106:     return nil
 .      .  107: }

プロファイラがスタックをアンワインドできない場合に使用する3つの特別なエントリ（GC、System、ExternalCode）もあります。GCはガベージコレクション中に費やされた時間を意味します。最適化の提案については、以下のメモリプロファイラとガベージコレクタトレースのセクションを参照してください。Systemはゴルーチンスケジューラ、スタック管理コード、その他の補助的なランタイムコードで費やされた時間を意味します。ExternalCodeはネイティブのダイナミックライブラリで費やされた時間を意味します。

プロファイルに表示される内容を解釈するためのヒントをいくつか紹介します。

runtime.mallocgc関数に多くの時間が費やされている場合、プログラムは過剰な量の小さなメモリ割り当てを行っている可能性があります。プロファイルは、割り当てがどこから来ているかを教えてくれます。このケースを最適化する方法については、メモリプロファイラのセクションを参照してください。

チャネル操作、sync.Mutex コード、その他の同期プリミティブ、または System コンポーネントに多くの時間が費やされている場合、プログラムはおそらく競合に悩まされています。頻繁にアクセスされる共有リソースを排除するために、プログラムの構造を見直すことを検討してください。これには、シャーディング/パーティショニング、ローカルバッファリング/バッチ処理、コピーオンライト技術などの一般的な手法が含まれます。

syscall.Read/Write に多くの時間が費やされている場合、プログラムは過剰な量の小さな読み書きを行っている可能性があります。この場合、os.File または net.Conn の周りの Bufio ラッパーが役立ちます。

GCコンポーネントに多くの時間が費やされている場合、プログラムは一時的なオブジェクトを大量に割り当てすぎているか、ヒープサイズが非常に小さいためガベージコレクションが頻繁に発生しすぎているかのどちらかです。最適化の提案については、ガベージコレクタートレーサーとメモリプロファイラーのセクションを参照してください。

注: Darwin CPU プロファイラは現在、El Capitan 以降でのみ動作します。

注：Windows では、svg/web プロファイルを生成するために Cygwin、Perl、Graphviz をインストールする必要があります。

メモリプロファイラ

メモリプロファイラは、どの関数がヒープメモリを割り当てているかを示します。CPUプロファイルと同様の方法で収集できます。go test --memprofile (https://pkg.go.dev/cmd/go/#hdr-Description_of_testing_flags)、net/http/pprof を介した http://myserver:6060:/debug/pprof/heap、または runtime/pprof.WriteHeapProfile を呼び出すことによって。

プロファイル収集時に生存している割り当てのみを視覚化することもできます (pprof の --inuse_space フラグ、デフォルト)。または、プログラム開始以降に行われたすべての割り当てを視覚化することもできます (pprof の --alloc_space フラグ)。前者はライブアプリケーションで net/http/pprof を使用して収集されたプロファイルに役立ち、後者はプログラム終了時に収集されたプロファイルに役立ちます (そうしないと、ほとんど空のプロファイルが表示されます)。

注：メモリプロファイラはサンプリング方式であり、メモリ割り当ての一部についてのみ情報を収集します。オブジェクトをサンプリングする確率はそのサイズに比例します。サンプリングレートは、go test --memprofilerateフラグまたはプログラム起動時にruntime.MemProfileRate変数を設定することで変更できます。レートを1にするとすべての割り当てに関する情報が収集されますが、実行速度が低下する可能性があります。デフォルトのサンプリングレートは、割り当てられたメモリ512KBあたり1サンプルです。

また、割り当てられたバイト数または割り当てられたオブジェクト数を視覚化することもできます (それぞれ --inuse/alloc_space および --inuse/alloc_objects フラグ)。プロファイラはプロファイリング中に大きなオブジェクトをサンプリングする傾向があります。しかし、大きなオブジェクトはメモリ消費とGC時間に影響を与え、多数の小さな割り当ては実行速度 (そしてある程度のGC時間も) に影響を与えることを理解することが重要です。そのため、両方を見るのが役立つ場合があります。

オブジェクトは永続的または一時的です。プログラムの開始時にいくつかの大きな永続的なオブジェクトが割り当てられた場合、それらはプロファイラによって最もサンプリングされる可能性が高いです（大きいため）。そのようなオブジェクトはメモリ消費とGC時間に影響を与えますが、通常の実行速度には影響しません（メモリ管理操作はそれらに対して行われません）。一方、寿命が非常に短い多数のオブジェクトがある場合、それらはプロファイルにほとんど表示されない可能性があります（デフォルトの--inuse_spaceモードを使用している場合）。しかし、それらは常に割り当てられて解放されるため、実行速度に大きく影響します。したがって、もう一度言いますが、両方の種類のオブジェクトを見るのが役立つ場合があります。一般的に、メモリ消費を減らしたい場合は、通常のプログラム操作中に収集された--inuse_spaceプロファイルを見る必要があります。実行速度を改善したい場合は、かなりの実行時間後またはプログラム終了時に収集された--alloc_objectsプロファイルを見てください。

レポートの粒度を制御するフラグがいくつかあります。--functionsはpprofに関数レベルでレポートさせます（デフォルト）。--linesはpprofにソースコード行レベルでレポートさせます。これは、ホットな関数が異なる行で割り当てを行う場合に役立ちます。また、正確な命令アドレスとファイルレベルのために、それぞれ--addressesと--filesもあります。

メモリプロファイルには便利なオプションがあります。ブラウザで直接確認できます（net/http/pprofをインポートしている場合）。http://myserver:6060/debug/pprof/heap?debug=1 を開くと、次のようなヒーププロファイルが表示されます。

heap profile: 4: 266528 [123: 11284472] @ heap/1048576
1: 262144 [4: 376832] @ 0x28d9f 0x2a201 0x2a28a 0x2624d 0x26188 0x94ca3 0x94a0b 0x17add6 0x17ae9f 0x1069d3 0xfe911 0xf0a3e 0xf0d22 0x21a70
#   0x2a201 cnew+0xc1   runtime/malloc.goc:718
#   0x2a28a runtime.cnewarray+0x3a          runtime/malloc.goc:731
#   0x2624d makeslice1+0x4d             runtime/slice.c:57
#   0x26188 runtime.makeslice+0x98          runtime/slice.c:38
#   0x94ca3 bytes.makeSlice+0x63            bytes/buffer.go:191
#   0x94a0b bytes.(*Buffer).ReadFrom+0xcb       bytes/buffer.go:163
#   0x17add6    io/ioutil.readAll+0x156         io/ioutil/ioutil.go:32
#   0x17ae9f    io/ioutil.ReadAll+0x3f          io/ioutil/ioutil.go:41
#   0x1069d3    godoc/vfs.ReadFile+0x133            godoc/vfs/vfs.go:44
#   0xfe911 godoc.func·023+0x471            godoc/meta.go:80
#   0xf0a3e godoc.(*Corpus).updateMetadata+0x9e     godoc/meta.go:101
#   0xf0d22 godoc.(*Corpus).refreshMetadataLoop+0x42    godoc/meta.go:141

2: 4096 [2: 4096] @ 0x28d9f 0x29059 0x1d252 0x1d450 0x106993 0xf1225 0xe1489 0xfbcad 0x21a70
#   0x1d252 newdefer+0x112              runtime/panic.c:49
#   0x1d450 runtime.deferproc+0x10          runtime/panic.c:132
#   0x106993    godoc/vfs.ReadFile+0xf3         godoc/vfs/vfs.go:43
#   0xf1225 godoc.(*Corpus).parseFile+0x75      godoc/parser.go:20
#   0xe1489 godoc.(*treeBuilder).newDirTree+0x8e9   godoc/dirtrees.go:108
#   0xfbcad godoc.func·002+0x15d            godoc/dirtrees.go:100

各エントリの冒頭の数字 (「1: 262144 [4: 376832]」) は、それぞれ、現在生存しているオブジェクト数、生存しているオブジェクトが占めるメモリ量、総割り当て数、およびすべての割り当てが占めるメモリ量を表します。

最適化は通常、アプリケーション固有ですが、いくつか一般的な提案があります。

  1. オブジェクトをより大きなオブジェクトに結合します。例えば、*bytes.Buffer構造体メンバーをbytes.Bufferに置き換えます（後でbytes.Buffer.Growを呼び出すことで書き込み用のバッファを事前に割り当てることができます）。これにより、メモリ割り当ての数が減り（高速化）、ガベージコレクタへの負担も軽減されます（ガベージコレクションが高速化されます）。

  2. 宣言スコープからエスケープするローカル変数は、ヒープ割り当てに昇格されます。コンパイラは通常、複数の変数が同じ寿命を持つことを証明できないため、そのような変数をそれぞれ個別に割り当てます。したがって、上記の助言はローカル変数にも適用できます。例えば、以下を置き換えます。

    for k, v := range m {
    k, v := k, v   // copy for capturing by the goroutine
    go func() {
        // use k and v
    }()
}

    を

    for k, v := range m {
    x := struct{ k, v string }{k, v}   // copy for capturing by the goroutine
    go func() {
        // use x.k and x.v
    }()
}

    これにより、2つのメモリ割り当てが単一の割り当てに置き換えられます。ただし、この最適化は通常、コードの可読性に悪影響を与えるため、適切に使用してください。

  3. 割り当て結合の特殊なケースとして、スライス配列の事前割り当てがあります。スライスの典型的なサイズがわかっている場合、次のようにバッキング配列を事前に割り当てることができます。

    type X struct {
    buf      []byte
    bufArray [16]byte // Buf usually does not grow beyond 16 bytes.
}

func MakeX() *X {
    x := &X{}
    // Preinitialize buf with the backing array.
    x.buf = x.bufArray[:0]
    return x
}

  4. 可能であれば、より小さなデータ型を使用してください。例えば、intの代わりにint8を使用します。

  5. ポインタを一切含まないオブジェクト（文字列、スライス、マップ、チャネルは暗黙のポインタを含みます）は、ガベージコレクタによってスキャンされません。例えば、1GBのバイトスライスはガベージコレクション時間にほとんど影響しません。したがって、活発に使用されるオブジェクトからポインタを削除すると、ガベージコレクション時間に良い影響を与える可能性があります。いくつかの可能性としては、ポインタをインデックスに置き換える、オブジェクトをポインタを含まない部分と含む部分の2つに分割するなどがあります。

  6. 一時的なオブジェクトを再利用し、割り当て数を減らすためにフリーリストを使用します。標準ライブラリには、ガベージコレクションの間で同じオブジェクトを複数回再利用できる sync.Pool 型が含まれています。ただし、手動のメモリ管理スキームと同様に、sync.Pool の誤った使用は use-after-free バグにつながる可能性があることに注意してください。

メモリ問題に関する洞察を得るために、ガベージコレクタートレース（下記参照）を使用することもできます。

TODO(dvyukov): 統計が遅延更新されることに言及: 「Memprof 統計は遅延更新されます。これは、割り当てが継続的に行われ、解放が後からバッチで行われる状況で一貫した全体像を提示するために必要です。いくつかの連続したGCが更新パイプラインを前進させます。これがあなたが見ているものです。したがって、ライブサーバーをプロファイルする場合、どのサンプルでも一貫したスナップショットが得られます。ただし、プログラムが何らかのアクティビティを完了し、そのアクティビティ後にスナップショットを収集したい場合は、収集前に2〜3回のGCを実行する必要があります。」

ブロッキングプロファイラ

ブロッキングプロファイラは、ゴルーチンが同期プリミティブ (タイマーチャネルを含む) でブロックして待機している場所を示します。CPUプロファイルと同様の方法で収集できます。go test --blockprofile (https://pkg.go.dev/cmd/go/#hdr-Description_of_testing_flags)、net/http/pprof を介した http://myserver:6060:/debug/pprof/block、または runtime/pprof.Lookup(“block”).WriteTo を呼び出すことによって。

しかし、重要な注意点があります。ブロッキングプロファイラはデフォルトでは有効になっていません。go test --blockprofile は自動的に有効にしてくれます。ただし、net/http/pprof または runtime/pprof を使用する場合は、手動で有効にする必要があります (そうしないとプロファイルは空になります)。ブロッキングプロファイラを有効にするには、runtime.SetBlockProfileRate を呼び出します。SetBlockProfileRate は、ブロッキングプロファイルで報告されるゴルーチンブロッキングイベントの割合を制御します。プロファイラは、ブロックされた指定されたナノ秒あたり平均1つのブロッキングイベントをサンプリングすることを目指しています。プロファイルにすべてのブロッキングイベントを含めるには、レートを1に設定します。

関数に複数のブロッキング操作が含まれており、どれがブロッキングにつながるのかが明らかでない場合は、pprof の --lines フラグを使用してください。

すべてのブロッキングが悪いわけではないことに注意してください。ゴルーチンがブロックすると、基盤となるワーカースレッドは単純に別のゴルーチンに切り替わります。したがって、協調的なGo環境でのブロッキングは、非協調的なシステム（例えば、一般的なC++やJavaのスレッドライブラリで、ブロッキングがスレッドのアイドル状態と高価なスレッドコンテキスト切り替えにつながる場合）でのミューテックスでのブロッキングとは大きく異なります。いくつか例を挙げて、その感覚をつかんでみましょう。

time.Ticker でのブロックは通常問題ありません。ゴルーチンが Ticker で10秒間ブロックした場合、プロファイルには10秒間のブロックが表示されますが、これは全く問題ありません。sync.WaitGroup でのブロックは頻繁に問題ありません。例えば、タスクに10秒かかる場合、完了を待つ WaitGroup でのゴルーチンはプロファイルで10秒間のブロックを計上します。sync.Cond でのブロックは、状況によって問題ない場合とそうでない場合があります。チャネルでブロックしているコンシューマは、プロデューサが遅いか、作業がないことを示唆します。チャネルでブロックしているプロデューサは、コンシューマが遅いことを示唆しますが、これは頻繁に問題ありません。チャネルベースのセマフォでブロックしていると、セマフォでゲートされているゴルーチンの数がわかります。sync.Mutex または sync.RWMutex でのブロックは通常は良くありません。pprof の --ignore フラグを使用して、視覚化中に既知の興味のないブロックをプロファイルから除外できます。

ゴルーチンのブロッキングは、2つの負の結果につながる可能性があります。

  1. 作業不足によりプログラムがプロセッサでスケールしない。スケジューラトレースがこのケースを特定するのに役立ちます。

  2. 過剰なゴルーチンのブロッキング/アンブロッキングがCPU時間を消費する。CPUプロファイラがこのケースを特定するのに役立ちます（Systemコンポーネメントを参照）。

ゴルーチンのブロッキングを減らすのに役立つ一般的な提案をいくつか紹介します。

  1. プロデューサーとコンシューマーのシナリオでは、十分にバッファリングされたチャネルを使用します。バッファリングされていないチャネルは、プログラムの利用可能な並列処理を大幅に制限します。

  2. 読み取り中心のワークロードでは、sync.Mutex の代わりに sync.RWMutex を使用します。sync.RWMutex では、実装レベルでもリーダーは他のリーダーをブロックしません。

  3. 場合によっては、コピーオンライト技術を使用することで、ミューテックスを完全に削除することが可能です。保護されたデータ構造が頻繁に変更されず、そのコピーを作成することが実現可能であれば、次のように更新できます。

    type Config struct {
    Routes   map[string]net.Addr
    Backends []net.Addr
}

var config atomic.Value  // actual type is *Config

// Worker goroutines use this function to obtain the current config.
  // UpdateConfig must be called at least once before this func.
func CurrentConfig() *Config {
    return config.Load().(*Config)
}

// Background goroutine periodically creates a new Config object
// as sets it as current using this function.
func UpdateConfig(cfg *Config) {
  config.Store(cfg)
}

    このパターンは、更新中に書き込み側が読み取り側をブロックするのを防ぎます。

  4. パーティショニングは、共有された可変データ構造における競合/ブロッキングを減らすためのもう一つの一般的な手法です。以下は、ハッシュマップをパーティション分割する方法の例です。

    type Partition struct {
    sync.RWMutex
    m map[string]string
}

const partCount = 64
var m [partCount]Partition

func Find(k string) string {
    idx := hash(k) % partCount
    part := &m[idx]
    part.RLock()
    v := part.m[k]
    part.RUnlock()
    return v
}

  5. ローカルキャッシュと更新のバッチ処理は、パーティション分割できないデータ構造での競合を減らすのに役立ちます。以下に、チャネルへの送信をバッチ処理する方法の例を示します。

    const CacheSize = 16

type Cache struct {
    buf [CacheSize]int
    pos int
}

func Send(c chan [CacheSize]int, cache *Cache, value int) {
    cache.buf[cache.pos] = value
    cache.pos++
    if cache.pos == CacheSize {
        c <- cache.buf
        cache.pos = 0
    }
}

    この技術はチャネルに限定されません。マップへの更新のバッチ処理、割り当てのバッチ処理などにも使用できます。

  6. チャネルベースまたはミューテックスで保護されたフリーリストの代わりに、フリーリストに sync.Pool を使用してください。sync.Pool は内部的にスマートな技術を使用してブロッキングを削減します。

ゴルーチンプロファイラ

ゴルーチンプロファイラは、プロセス内のすべてのライブゴルーチンの現在のスタックを単純に提供します。負荷分散の問題（以下のスケジューラトレースセクションを参照）のデバッグや、デッドロックのデバッグに役立ちます。このプロファイルは実行中のアプリケーションに対してのみ意味があるため、go testでは公開されません。プロファイルは、net/http/pprof を介した http://myserver:6060:/debug/pprof/goroutine で収集し、svg/pdfに視覚化するか、runtime/pprof.Lookup("goroutine").WriteTo を呼び出すことで収集できます。しかし、最も便利な方法は、ブラウザで http://myserver:6060:/debug/pprof/goroutine?debug=2 と入力することです。これにより、プログラムがクラッシュしたときに表示されるのと同様のシンボル化されたスタックが得られます。「syscall」状態のゴルーチンはOSスレッドを消費しますが、他のゴルーチンは消費しません（runtime.LockOSThreadを呼び出したゴルーチンを除く。残念ながらこれはプロファイルには表示されません）。「IO wait」状態のゴルーチンもスレッドを消費せず、ノンブロッキングネットワークポーラー（epoll/kqueue/GetQueuedCompletionStatusを使用して後でゴルーチンをアンパークします）に駐車されていることに注意してください。

ガベージコレクタートレース

プロファイリングツールとは別に、もう一つ種類のツールがあります。それはトレーサーです。これらはガベージコレクション、メモリアロケータ、ゴルーチンスケジューラの状態をトレースすることができます。ガベージコレクタ（GC）トレースを有効にするには、GODEBUG=gctrace=1環境変数を使用してプログラムを実行します。

$ GODEBUG=gctrace=1 ./myserver

すると、プログラムは実行中に以下のような出力を表示します。

gc9(2): 12+1+744+8 us, 2 -> 10 MB, 108615 (593983-485368) objects, 4825/3620/0 sweeps, 0(0) handoff, 6(91) steal, 16/1/0 yields
gc10(2): 12+6769+767+3 us, 1 -> 1 MB, 4222 (593983-589761) objects, 4825/0/1898 sweeps, 0(0) handoff, 6(93) steal, 16/10/2 yields
gc11(2): 799+3+2050+3 us, 1 -> 69 MB, 831819 (1484009-652190) objects, 4825/691/0 sweeps, 0(0) handoff, 5(105) steal, 16/1/0 yields

これらの数字の意味を考えてみましょう。GCごとに1行が出力されます。最初の数字 ("gc9") はGCの回数 (プログラム開始から9回目のGCです)。括弧内の数字 ("(2)") はGCに参加したワーカースレッドの数です。次の4つの数字 ("12+1+744+8 us") は、それぞれストップザワールド、スウィープ、マーキング、ワーカースレッドが終了するのを待つ時間をマイクロ秒で表しています。次の2つの数字 ("2 -> 10 MB") は、前のGC後のライブヒープサイズと現在のGC前のフルヒープサイズ (ガベージを含む) を意味します。次の3つの数字 ("108615 (593983-485368) objects") は、ヒープ内のオブジェクトの総数 (ガベージを含む) とメモリ割り当ておよび解放操作の総数です。次の3つの数字 ("4825/3620/0 sweeps") は (前のGCの) スウィープフェーズを特徴付けています。合計4825のメモリスパンがあり、3620はオンデマンドまたはバックグラウンドでスウィープされ、0はストップザワールドフェーズ中にスウィープされました (残りは未使用のスパンでした)。次の4つの数字 ("0(0) handoff, 6(91) steal") は並列マークフェーズ中の負荷分散を特徴付けています。オブジェクトのハンドオフ操作は0回 (0オブジェクトがハンドオフされました)、スティール操作は6回 (91オブジェクトがスティールされました)。最後の3つの数字 ("16/1/0 yields") は並列マークフェーズの有効性を特徴付けています。他のスレッドを待つ間に合計17回のyield操作がありました。

GCはマーク＆スイープ型です。総GC時間は次のように表現できます。

Tgc = Tseq + Tmark + Tsweep

ここで、Tseqはユーザゴルーチンを停止し、いくつかの準備活動にかかる時間（通常は小さい）です。Tmarkはヒープマーキング時間で、マーキングはすべてのユーザゴルーチンが停止している間に発生するため、処理のレイテンシに大きく影響する可能性があります。Tsweepはヒープスイープ時間で、スイープは通常、通常のプログラム実行と並行して行われるため、レイテンシにとってそれほど重要ではありません。

マーキング時間は近似的に次のように表現できます。

Tmark = C1*Nlive + C2*MEMlive_ptr + C3*Nlive_ptr

ここで、Nlive は GC 中のヒープ内のライブオブジェクトの数、MEMlive_ptr はポインタを持つライブオブジェクトが占めるメモリ量、Nlive_ptr はライブオブジェクト内のポインタの数です。

スイープ時間は近似的に次のように表現できます。

Tsweep = C4*MEMtotal + C5*MEMgarbage

ここで、MEMtotalはヒープメモリの総量、MEMgarbageはヒープ内のガベージの量です。

次のGCは、プログラムがすでに使用中のメモリ量に比例した追加のメモリ量を割り当てた後に発生します。この比率はGOGC環境変数（デフォルトは100）によって制御されます。GOGC=100で、プログラムが4Mのヒープメモリを使用している場合、プログラムが8Mに達するとランタイムは再びGCをトリガーします。これにより、GCコストは割り当てコストに比例して線形に保たれます。GOGCを調整すると、線形定数と使用される追加メモリ量が変更されます。

スイープのみがヒープの合計サイズに依存し、スイープは通常のプログラム実行と並行して行われます。そのため、追加のメモリ消費を許容できるのであれば、GOGCをより高い値（200、300、500など）に設定するのは理にかなっています。例えば、GOGC=300はガベージコレクションのオーバーヘッドを最大2倍削減し、レイテンシを同じに保つことができます（ヒープサイズが2倍になるというコストを伴いますが）。

GCは並行処理されており、一般にハードウェアの並列処理と良好にスケールします。したがって、シーケンシャルなプログラムであっても、ガベージコレクションを高速化するためだけにGOMAXPROCSをより高い値に設定することは理にかなっています。ただし、ガベージコレクタスレッドの数は現在8に制限されていることに注意してください。

メモリアロケータトレース

メモリアロケータートレースは、すべてのメモリ割り当ておよび解放操作をコンソールに単純にダンプします。これは GODEBUG=allocfreetrace=1 環境変数で有効になります。出力は次のような形式です。

tracealloc(0xc208062500, 0x100, array of parse.Node)
goroutine 16 [running]:
runtime.mallocgc(0x100, 0x3eb7c1, 0x0)
    runtime/malloc.goc:190 +0x145 fp=0xc2080b39f8
runtime.growslice(0x31f840, 0xc208060700, 0x8, 0x8, 0x1, 0x0, 0x0, 0x0)
    runtime/slice.goc:76 +0xbb fp=0xc2080b3a90
text/template/parse.(*Tree).parse(0xc2080820e0, 0xc208023620, 0x0, 0x0)
    text/template/parse/parse.go:289 +0x549 fp=0xc2080b3c50
...

tracefree(0xc208002d80, 0x120)
goroutine 16 [running]:
runtime.MSpan_Sweep(0x73b080)
        runtime/mgc0.c:1880 +0x514 fp=0xc20804b8f0
runtime.MCentral_CacheSpan(0x69c858)
        runtime/mcentral.c:48 +0x2b5 fp=0xc20804b920
runtime.MCache_Refill(0x737000, 0xc200000012)
        runtime/mcache.c:78 +0x119 fp=0xc20804b950
...

トレースには、メモリブロックのアドレス、サイズ、タイプ、ゴルーチンID、スタックトレースが含まれます。デバッグに役立つことが多いですが、割り当て最適化のための非常に詳細な情報も提供できます。

スケジューラトレース

スケジューラトレースは、ゴルーチンスケジューラの動的な動作に関する洞察を提供し、負荷分散とスケーラビリティの問題をデバッグすることを可能にします。スケジューラトレースを有効にするには、GODEBUG=schedtrace=1000 環境変数（値は出力の周期をミリ秒単位で示し、この場合は1秒に1回）を使用してプログラムを実行します。

$ GODEBUG=schedtrace=1000 ./myserver

すると、プログラムは実行中に以下のような出力を表示します。

SCHED 1004ms: gomaxprocs=4 idleprocs=0 threads=11 idlethreads=4 runqueue=8 [0 1 0 3]
SCHED 2005ms: gomaxprocs=4 idleprocs=0 threads=11 idlethreads=5 runqueue=6 [1 5 4 0]
SCHED 3008ms: gomaxprocs=4 idleprocs=0 threads=11 idlethreads=4 runqueue=10 [2 2 2 1]

最初の数字（「1004ms」）はプログラム開始からの時間です。GomaxprocsはGOMAXPROCSの現在の値です。Idleprocsはアイドル状態のプロセッサ数です（残りはGoコードを実行しています）。Threadsはスケジューラによって作成されたワーカースレッドの総数です（スレッドは3つの状態になります：Goコードの実行（gomaxprocs-idleprocs）、システムコール/Cgoコールの実行、またはアイドル）。Idlethreadsはアイドル状態のワーカースレッドの数です。Runqueueは実行可能なゴルーチンを持つグローバルキューの長さです。角括弧内の数字（「[0 1 0 3]」）は、実行可能なゴルーチンを持つプロセッサごとのキューの長さです。グローバルキューとローカルキューの長さの合計は、実行可能なゴルーチンの総数を表します。

注：GODEBUG=gctrace=1,allocfreetrace=1,schedtrace=1000のように、任意のトレーサーを組み合わせることができます。

注：GODEBUG=schedtrace=1000,scheddetail=1 で有効にできる詳細なスケジューラトレースもあります。これはすべてのゴルーチン、ワーカースレッド、プロセッサに関する詳細な情報を出力します。主にスケジューラ開発者向けに有用であるため、ここではそのフォーマットについては説明しませんが、src/pkg/runtime/proc.c で詳細を確認できます。

スケジューラートレースは、プログラムがGOMAXPROCSに比例してスケールしない場合や、CPU時間の100%を消費しない場合に役立ちます。理想的な状況は、すべてのプロセッサがGoコードの実行で忙しく、スレッド数が適切で、すべてのキューに十分な作業があり、作業が合理的に均等に分散されている場合です。

gomaxprocs=8 idleprocs=0 threads=40 idlethreads=5 runqueue=10 [20 20 20 20 20 20 20 20]

上記のいずれかが成り立たない場合、それは悪い状況です。例えば、以下のサンプルは、すべてのプロセッサを忙しくさせるのに十分な作業がないことを示しています。

gomaxprocs=8 idleprocs=6 threads=40 idlethreads=30 runqueue=0 [0 2 0 0 0 1 0 0]

注: 実際のCPU使用率は、最終的な特性としてOSが提供する手段で測定してください。Unix系のオペレーティングシステムでは top コマンド、Windowsではタスクマネージャーです。

作業不足の場合にゴルーチンがどこでブロックしているかを理解するには、ゴルーチンプロファイラを使用できます。すべてのプロセッサが忙しい限り、負荷の不均衡は最終的に悪いことではなく、適度な負荷分散のオーバーヘッドを引き起こすだけであることに注意してください。

メモリ統計

Goランタイムは、runtime.ReadMemStats 関数を介して、粗粒度なメモリ統計を公開しています。この統計は、net/http/pprofを介して http://myserver:6060/debug/pprof/heap?debug=1 の下部にも公開されています。統計はこちらで説明されています。興味深いフィールドの一部を以下に示します。

  1. HeapAlloc - 現在のヒープサイズ。
  2. HeapSys - ヒープの総サイズ。
  3. HeapObjects - ヒープ内のオブジェクトの総数。
  4. HeapReleased - OSに解放されたメモリ量。ランタイムは5分間未使用のメモリをOSに解放します。runtime/debug.FreeOSMemory でこのプロセスを強制できます。
  5. Sys - OSから割り当てられたメモリの総量。
  6. Sys-HeapReleased - プログラムの実効メモリ消費量。
  7. StackSys - ゴルーチンのスタックに消費されたメモリ（一部のスタックはヒープから割り当てられ、ここでは計上されていないことに注意してください。残念ながらスタックの合計サイズを取得する方法はありません（https://code.google.com/p/go/issues/detail?id=7468))）。
  8. MSpanSys/MCacheSys/BuckHashSys/GCSys/OtherSys - ランタイムが様々な補助目的で割り当てたメモリ量。通常は高すぎない限り興味深いものではありません。
  9. PauseNs - 最後のガベージコレクションの期間。

ヒープダンパー

利用可能な最後のツールはヒープダンパーで、ヒープ全体の状態をファイルに書き出し、後で調査することができます。これはメモリリークの特定やプログラムのメモリ消費に関する洞察を得るのに役立ちます。

まず、runtime/debug.WriteHeapDump 関数を使ってダンプを書き込む必要があります。

    f, err := os.Create("heapdump")
    if err != nil { ... }
    debug.WriteHeapDump(f.Fd())

次に、ヒープのグラフィカル表示を含むdotファイルとしてレンダリングするか、hprof形式に変換することができます。dotファイルとしてレンダリングするには

$ go get github.com/randall77/hprof/dumptodot
$ dumptodot heapdump mybinary > heap.dot

Graphvizでheap.dotを開きます。

hprof形式に変換するには

$ go get github.com/randall77/hprof/dumptohprof
$ dumptohprof heapdump heap.hprof
$ jhat heap.hprof

ブラウザで http://myserver:7000 にアクセスしてください。

結びの言葉

最適化は未解決の問題であり、パフォーマンスを向上させるために使用できる簡単なレシピがあります。時には、最適化にはプログラムの完全な再構築が必要になることもあります。しかし、これらのツールがあなたのツールボックスに貴重な追加となり、少なくとも何が起こっているかを分析し理解するために使用できることを願っています。 Profiling Go Programs は、簡単なプログラムを最適化するためのCPUおよびメモリプロファイラの使い方に関する優れたチュートリアルです。

このコンテンツはGo Wikiの一部です。

go.dev は、サービスの品質を提供および向上させ、トラフィックを分析するために、Google の Cookie を使用しています。詳細はこちらをご覧ください。