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

– Dmitry Vyukov によって書かれた

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

パフォーマンスのさまざまな境界要因を理解することも重要です。たとえば、プログラムが 100 Mbps のネットワークリンクを介して通信し、既に 90 Mbps を超えている場合、プログラムのパフォーマンスを向上させるためにできることはあまりありません。ディスク 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

    は、最もホットな関数のリストを出力します。

    利用可能な出力タイプは複数ありますが、最も useful なのは `--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 をインストールする必要があります。

メモリプロファイラ

メモリプロファイラは、どの関数がヒープメモリを割り当てているかを示します。 `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 を呼び出すことで、CPU プロファイルと同様の方法で収集できます。

プロファイル収集時に有効な割り当てのみ (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 時間もある程度) に影響を与えることを理解することが重要です。したがって、両方を見るのが useful な場合があります。

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

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

メモリプロファイルには useful なオプションがあります。ブラウザで直接見ることができます ( `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` struct メンバーを `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 つのメモリ割り当てが 1 つの割り当てに置き換えられます。ただし、この最適化は通常、コードの可読性に悪影響を与えるため、合理的に使用してください。

  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 を誤って使用すると、解放後使用のバグが発生する可能性があることに注意してください。

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

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 でのブロッキングは通常は問題です。`--ignore` フラグを pprof に使用して、視覚化中に既知の不要なブロッキングをプロファイルから除外できます。

ゴルーチンのブロッキングは、2 つの負の影響をもたらす可能性があります。

  1. 作業が不足しているため、プログラムはプロセッサに合わせてスケーリングしません。スケジューラトレースはこのケースの特定に役立ちます。

  2. 過剰なゴルーチンのブロッキング/ブロック解除は CPU 時間を消費します。CPU プロファイラはこのケースの特定に役立ちます（システムコンポーネントを参照）。

ゴルーチンのブロッキングを減らすのに役立つ一般的な提案を以下に示します。

  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. パーティショニングは、共有の可変データ構造に対する競合/ブロッキングを減らすためのもう 1 つの一般的な手法です。以下は、ハッシュマップをパーティション化する方法の例です。

    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」）は、それぞれ stop-the-world、スイープ、マーキング、およびワーカースレッドの完了を待機する時間をマイクロ秒単位で表します。次の 2 つの数値（「2 -> 10 MB」）は、前回の GC 後のライブヒープのサイズと、現在の GC 前のフルヒープサイズ（ガベージを含む）を意味します。次の 3 つの数値（「108615 (593983-485368) objects」）は、ヒープ内のオブジェクトの総数（ガベージを含む）と、メモリ割り当ておよび解放操作の総数です。次の 3 つの数値（「4825/3620/0 sweeps」）は、スイープフェーズ（前回の GC の）を特徴付けています。合計 4825 のメモリ範囲があり、3620 はオンデマンドまたはバックグラウンドでスイープされ、0 は stop-the-world フェーズ中にスイープされました（残りは未使用の範囲でした）。次の 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）、syscall/cgocall を実行する、またはアイドル状態）。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 コードの実行でビジー状態であり、スレッドの数が妥当であり、すべてのキューに十分な作業があり、作業が reasonably 均等に分散されている場合です。

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 関数を通じて、粗粒度のメモリ統計情報を公開しています。この統計情報は、http://myserver:6060/debug/pprof/heap?debug=1 の下部にある net/http/pprof を介しても公開されています。統計情報の説明はこちらにあります。重要なフィールドの一部を以下に示します。

  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 を使用してサービスの提供と品質の向上、トラフィックの分析を行っています。詳細はこちら