パフォーマンス分析
プログラムが完成した後、単に実行できるだけではなく、安定して効率的なアプリケーションであることを期待します。様々なテストを通じて、プログラムの大部分の安定性を保証できますが、プログラムが効率的かどうかは、パフォーマンス分析を行う必要があります。これまでの内容では、パフォーマンス分析の唯一の手段は Benchmark を通じて、特定の機能ユニットの平均実行時間、メモリ割り当て状況などをテストすることだけでした。しかし、実際にはプログラムのパフォーマンス分析に対するニーズはこれだけでは远远不够ません。時にはプログラム全体の CPU 使用率、メモリ使用量、ヒープ割り当て状況、ゴルーチン状態、ホットコードパスなどを分析する必要があります。これは Benchmark では満足できません。幸いなことに、Go ツールチェーンには多くのパフォーマンス分析ツールが統合されており、開発者が使用できるようになっています。以下で 1 つずつ説明します。
エスケープ分析
Go では、変数のメモリ割り当てはコンパイラによって決定され、一般的にはスタック上とヒープ上の 2 つの場所に割り当てられます。スタック上に割り当てられるべき変数がヒープ上に割り当てられた場合、この状況をエスケープと呼び、エスケープ分析はプログラム内のメモリ割り当て状況を分析するものです。これはコンパイル時に実行されるため、静的分析の一種です。
TIP
メモリ割り当て 記事で Go が具体的にどのようにメモリを割り当てるかをご覧ください。
ローカルポインタの参照
package main
func main() {
GetPerson()
}
type Person struct {
Name string
Mom *Person
}
func GetPerson() Person {
mom := Person{Name: "lili"}
son := Person{Name: "jack", Mom: &mom}
return son
}GetPerson 関数内で mom 変数を作成しました。これは関数内で作成されたため、本来はスタック上に割り当てられるべきですが、son の Mom フィールドによって参照され、かつ son が関数の戻り値として返されるため、コンパイラはこれをヒープ上に割り当てます。これは非常にシンプルな例なので、理解するのにそれほど労力はかかりませんが、プロジェクトが大きくなり、コード行数が数万行ある場合、人手で分析するのはそれほど簡単ではありません。そのため、ツールを使用してエスケープ分析を行う必要があります。前述したように、メモリの割り当てはコンパイラが主導するため、エスケープ分析もコンパイラによって完了します。使用は非常に簡単で、以下のコマンドを実行するだけです。
$ go build -gcflags="-m -m -l"gcflags はコンパイラ gc のパラメータです。
-m：コード最適化の提案を出力します。2 つ指定すると、より詳細な出力になります。-l：インライン最適化を無効にします。
出力は以下の通りです。
$ go build -gcflags="-m -m -l" .
# golearn/example
./main.go:13:2: mom escapes to heap:
./main.go:13:2: flow: son = &mom:
./main.go:13:2: from &mom (address-of) at ./main.go:14:35
./main.go:13:2: from Person{...} (struct literal element) at ./main.go:14:15
./main.go:13:2: from son := Person{...} (assign) at ./main.go:14:6
./main.go:13:2: flow: ~r0 = son:
./main.go:13:2: from return son (return) at ./main.go:15:2
./main.go:13:2: moved to heap: momコンパイラは変数 mom がエスケープしたことを明確に示しており、その原因は戻り値が関数内のローカルポインタを含んでいることです。この状況以外にも、エスケープ現象が発生する可能性があります。
::: tips
エスケープ分析の詳細に興味がある場合は、標準ライブラリ cmd/compile/internal/escape/escape.go でさらに多くの内容を理解できます。
:::
クロージャによる参照
クロージャが関数外の変数を参照している場合、その変数もヒープ上にエスケープします。これは非常に理解しやすいです。
package main
func main() {
a := make([]string, 0)
do(func() []string {
return a
})
}
func do(f func() []string) []string {
return f()
}出力
$ go build -gcflags="-m -m -l" .
# golearn/example
./main.go:10:9: f does not escape
./main.go:4:2: main capturing by value: a (addr=false assign=false width=24)
./main.go:4:11: make([]string, 0) escapes to heap:
./main.go:4:11: flow: a = &{storage for make([]string, 0)}:
./main.go:4:11: from make([]string, 0) (spill) at ./main.go:4:11
./main.go:4:11: from a := make([]string, 0) (assign) at ./main.go:4:4
./main.go:4:11: flow: ~r0 = a:
./main.go:4:11: from return a (return) at ./main.go:6:3
./main.go:4:11: make([]string, 0) escapes to heap
./main.go:5:5: func literal does not escape容量不足
スタック容量が不足している場合も、エスケープ現象が発生します。以下で作成されたスライスは 1<<15 の容量を申請しています。
package main
func main() {
_ = make([]int, 0, 1<<15)
}出力
$ go build -gcflags="-m -m -l" .
# golearn/example
./main.go:4:10: make([]int, 0, 32768) escapes to heap:
./main.go:4:10: flow: {heap} = &{storage for make([]int, 0, 32768)}:
./main.go:4:10: from make([]int, 0, 32768) (too large for stack) at ./main.go:4:10
./main.go:4:10: make([]int, 0, 32768) escapes to heap長さ不明
スライスの長さが変数の場合、その長さが不明であるため、エスケープ現象が発生します（map はエスケープしません）。
package main
func main() {
n := 100
_ = make([]int, n)
}出力
$ go build -gcflags="-m -m -l" .
# golearn/example
./main.go:5:10: make([]int, n) escapes to heap:
./main.go:5:10: flow: {heap} = &{storage for make([]int, n)}:
./main.go:5:10: from make([]int, n) (non-constant size) at ./main.go:5:10
./main.go:5:10: make([]int, n) escapes to heap还有一种特殊情况便是函数参数为 ...any 类型时也可能会发生逃逸
package main
import "fmt"
func main() {
n := 100
fmt.Println(n)
}出力
$ go build -gcflags="-m -m -l" .
# golearn/example
./main.go:7:14: n escapes to heap:
./main.go:7:14: flow: {storage for ... argument} = &{storage for n}:
./main.go:7:14: from n (spill) at ./main.go:7:14
./main.go:7:14: from ... argument (slice-literal-element) at ./main.go:7:13
./main.go:7:14: flow: {heap} = {storage for ... argument}:
./main.go:7:14: from ... argument (spill) at ./main.go:7:13
./main.go:7:14: from fmt.Println(... argument...) (call parameter) at ./main.go:7:13
./main.go:7:13: ... argument does not escape
./main.go:7:14: n escapes to heap私たちがエスケープ分析を行う理由は、メモリ割り当てをこれほど細かく制御するため、主に GC の負荷を軽減するためです。ただし、Go は C 言語ではなく、メモリ割り当ての最終決定権は依然としてコンパイラの手中にあります。極端なパフォーマンス要件の状況を除き、ほとんどの場合、メモリ割り当ての詳細にあまり専念する必要はありません。GC が誕生した目的は、開発者を解放するためです。
小細節
一部の参照型について、使用しなくなった後は nil に設定することで、GC に回収可能であることを知らせることができます。
type Writer struct {
buf []byte
}
func (w Writer) Close() error {
w.buff = nil
return nil
}pprof
pprof（program profiling）は、プログラムパフォーマンス分析の強力なツールです。実行時のデータの一部をサンプリングし、CPU、メモリ、ゴルーチン、ロック、スタック情報など多くの側面をカバーし、その後ツールを使用してサンプリングされたデータを分析し、結果を表示します。
したがって、pprof の使用手順は 2 つだけです。
- データ収集
- 結果分析
収集
データ収集の方法は 2 つあり、自動と手動で、それぞれに長所と短所があります。その前に、メモリと CPU の消費をシミュレートするシンプルな関数を作成します。
func Do() {
for i := 0; i < 10; i++ {
slice := makeSlice()
sortSlice(slice)
}
}
func makeSlice() []int {
var s []int
for range 1 << 24 {
s = append(s, rand.Int())
}
return s
}
func sortSlice(s []int) {
slices.Sort(s)
}手動
手動収集はコードを通じて制御するもので、その利点は制御可能で、柔軟で、カスタマイズ可能であることです。直接使用するには runtime/pprof パッケージをインポートする必要があります。
package main
import (
"log"
"os"
"runtime/pprof"
)
func main() {
Do()
w, _ := os.Create("heap.pb")
heapProfile := pprof.Lookup("heap")
err := heapProfile.WriteTo(w, 0)
if err != nil {
log.Fatal(err)
}
}pprof.Lookup がサポートするパラメータは以下のコードの通りです。
profiles.m = map[string]*Profile{
"goroutine": goroutineProfile,
"threadcreate": threadcreateProfile,
"heap": heapProfile,
"allocs": allocsProfile,
"block": blockProfile,
"mutex": mutexProfile,
}この関数は収集されたデータを指定されたファイルに書き込みます。書き込み時に渡される数字には以下の意味があります。
0：圧縮された Protobuf データを書き込み、可読性はありません。1：テキスト形式のデータを書き込み、読むことができます。HTTP インターフェースが返すのはこの種類のデータです。2：goroutineのみ使用可能で、panicスタイルのスタック情報を出力することを示します。
CPU データの収集には、個別に pprof.StartCPUProfile 関数を使用する必要があります。これにはサンプリングに一定の時間が必要で、元のデータは読み取れません。以下の通りです。
package main
import (
"log"
"os"
"runtime/pprof"
"time"
)
func main() {
Do()
w, _ := os.Create("cpu.out")
err := pprof.StartCPUProfile(w)
if err != nil {
log.Fatal(err)
}
time.Sleep(time.Second * 10)
pprof.StopCPUProfile()
}trace データの収集も同様です。
package main
import (
"log"
"os"
"runtime/trace"
"time"
)
func main() {
Do()
w, _ := os.Create("trace.out")
err := trace.Start(w)
if err != nil {
log.Fatal(err)
}
time.Sleep(time.Second * 10)
trace.Stop()
}自動
net/http/pprof パッケージは、上記の分析関数を HTTP インターフェースにカプセル化し、デフォルトルートに登録します。以下の通りです。
package pprof
import ...
func init() {
http.HandleFunc("/debug/pprof/", Index)
http.HandleFunc("/debug/pprof/cmdline", Cmdline)
http.HandleFunc("/debug/pprof/profile", Profile)
http.HandleFunc("/debug/pprof/symbol", Symbol)
http.HandleFunc("/debug/pprof/trace", Trace)
}これにより、ワンクリックで pprof データ収集を実行できます。
package main
import (
"net/http"
// 必ずこのパッケージをインポートしてください
_ "net/http/pprof"
)
func main() {
go func(){
http.ListenAndServe(":8080", nil)
}
for {
Do()
}
}この時点でブラウザで http://127.0.0.1:8080/debug/pprof にアクセスすると、以下のようなページが表示されます。
ページにはいくつかのオプションがあります。それぞれが以下を表します。
allocs：メモリ割り当てのサンプリングblock：同期プリミティブのブロッキング追跡cmdline：現在のプログラムのコマンドライン呼び出しgoroutine：すべてのゴルーチンを追跡heap：生存オブジェクトのメモリ割り当てサンプリングmutex：相互排他ロック関連情報の追跡profile：CPU 分析。一定時間分析し、ファイルをダウンロードします。threadcreate：新しい OS スレッドの作成原因を分析trace：現在のプログラムの実行状況の追跡。同様にファイルをダウンロードします。
ここのデータのほとんどは可読性が高くなく、主にツール分析用に使用されます。以下の図の通りです。
具体的な分析作業は後で行います。profile と trace の 2 つのオプションを除き、ウェブページでデータファイルをダウンロードしたい場合は、query パラメータ debug=1 を削除します。また、これらのインターフェースをデフォルトルートではなく、自分のルートに統合することもできます。以下の通りです。
package main
import (
"net/http"
"net/http/pprof"
)
func main() {
mux := http.NewServeMux()
mux.HandleFunc("/trace", pprof.Trace)
servre := &http.Server{
Addr: ":8080",
Handler: mux,
}
servre.ListenAndServe()
}これにより、他の Web フレームワーク（例えば gin、iris など）に統合することもできます。
分析
収集したデータファイルを取得した後、分析には 2 つの方法があります。コマンドラインまたはウェブページです。どちらも pprof コマンドラインツールを使用します。Go にはデフォルトでこのツールが統合されているため、追加でダウンロードする必要はありません。
pprof オープンソースアドレス：google/pprof: pprof is a tool for visualization and analysis of profiling data (github.com)
コマンドライン
収集したデータファイルをパラメータとして使用します。
$ go tool pprof heap.pbデータが Web から収集された場合は、ファイル名の代わりに Web URL を使用します。
$ go tool pprof -http :8080 http://127.0.0.1/debug/pprof/heapその後、インタラクティブなコマンドラインが表示されます。
15:27:38.3266862 +0800 CST
Type: inuse_space
Time: Apr 15, 2024 at 3:27pm (CST)
No samples were found with the default sample value type.
Try "sample_index" command to analyze different sample values.
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)help を入力すると、他のコマンドを表示できます。
Commands:
callgrind Outputs a graph in callgrind format
comments Output all profile comments
disasm Output assembly listings annotated with samples
dot Outputs a graph in DOT format
eog Visualize graph through eog
evince Visualize graph through evince
...コマンドラインでデータを表示するには、通常 top コマンドを使用します。traces コマンドも使用できますが、その出力は非常に冗長です。top コマンドは単に概要を確認するだけです。
(pprof) top 5
Showing nodes accounting for 117.49MB, 100% of 117.49MB total
flat flat% sum% cum cum%
117.49MB 100% 100% 117.49MB 100% main.makeSlice (inline)
0 0% 100% 117.49MB 100% main.Do
0 0% 100% 117.49MB 100% main.main
0 0% 100% 117.49MB 100% runtime.mainいくつかの指標（CPU も同様）を簡単に紹介します。
flat：現在の関数が消費するリソースcum：現在の関数とその後続の呼び出しチェーンが消費するリソースの合計flat%：flat/totalcum%：cum/total
呼び出しスタック全体のメモリ使用量が 117.49MB であることがはっきりとわかります。Do 関数自体は何もせず、他の関数を呼び出しているだけなので、flat 指標は 0 です。スライスの作成は makeSlice 関数が担当しているため、その flat 指標は 100% です。
可視化形式に変換することもできます。pprof は非常に多くの形式をサポートしています。例えば pdf、svg、png、gif などです（Graphviz のインストールが必要です）。
(pprof) png
Generating report in profile001.png
画像を通じて、呼び出しスタック全体のメモリ状況をより明確に確認できます。
list コマンドを使用して、ソースコード形式で表示します。
(pprof) list Do
Total: 117.49MB
ROUTINE ======================== main.Do in D:\WorkSpace\Code\GoLeran\golearn\example\main.go
0 117.49MB (flat, cum) 100% of Total
. . 21:func Do() {
. . 22: for i := 0; i < 10; i++ {
. 117.49MB 23: slice := makeSlice()
. . 24: sortSlice(slice)
. . 25: }
. . 26:}
. . 27:
. . 28:func makeSlice() []int {画像とソースコードについては、web と weblist コマンドを使用して、ブラウザで画像とソースコードを表示することもできます。
ウェブページ
その前に、データをより多様化するために、シミュレート関数を修正します。
func Do1() {
for i := 0; i < 10; i++ {
slice := makeSlice()
sortSlice(slice)
}
}
func Do2() {
for i := 0; i < 10; i++ {
slice := makeSlice()
sortSlice(slice)
}
}
func makeSlice() []int {
var s []int
for range 1 << 12 {
s = append(s, rand.Int())
}
return s
}
func sortSlice(s []int) {
slices.Sort(s)
}ウェブページ分析は結果を可視化し、手動でコマンドラインを操作する手間を省きます。ウェブページ分析を使用する際は、以下のコマンドを実行するだけです。
$ go tool pprof -http :8080 heap.pbデータが Web から収集された場合は、ファイル名の代わりに Web URL を使用します。
$ go tool pprof -http :8080 http://127.0.0.1:9090/debug/pprof/heap
$ go tool pprof -http :8080 http://127.0.0.1:9090/debug/pprof/profile
$ go tool pprof -http :8080 http://127.0.0.1:9090/debug/pprof/goroutineTIP
データの分析方法については、pprof: How to read the graph で詳細をご覧ください。
ウェブページには合計 6 つの表示項目があります。
- Top：コマンド top と同じ
- Graph：直線図
- Flame Graph：火焰図
- Peek：
- Source：ソースコードを表示
- Disassemble：逆アセンブルを表示
メモリについては、4 つの次元で分析できます。
alloc_objects：現在割り当てられたすべてのオブジェクト数（解放済みを含む）alloc_spcae：現在までに割り当てられたすべてのメモリ空間（解放済みを含む）inuse_objects：使用中のオブジェクト数inuse_space：使用中のメモリ空間
上記の図の最下部の白い葉ノードは、異なるサイズのオブジェクトの占有を示しています。
折れ線図については、いくつかの点に注意する必要があります。
- ブロックの色が濃いほど、占有が高く、線が太いほど、占有が高いです。
- 実線は直接呼び出しを示し、点線は一部の呼び出しチェーンを省略していることを示します。
火焰図については、上から下に見ると呼び出しチェーンで、左から右に見ると cum の占有パーセンテージです。
trace
pprof は主にプログラムのリソース占有を分析するのに対し、trace はプログラムの実行詳細を追跡するのに適しています。これは前者のデータファイルと互換性がなく、go tool trace コマンドが関連分析作業を完了します。
手動で収集したデータの場合は、ファイル名をパラメータとして使用できます。
$ go tool trace trace.out自動で収集したデータも同様です。
$ curl http://127.0.0.1:8080/debug/pprof/trace > trace.out && go tool trace trace.out実行後、Web サーバーが開始されます。
2024/04/15 17:15:40 Preparing trace for viewer...
2024/04/15 17:15:40 Splitting trace for viewer...
2024/04/15 17:15:40 Opening browser. Trace viewer is listening on http://127.0.0.1:51805開くと、ページは概ね以下のようになります。
これには主に以下のいくつかの部分が含まれています。これらのデータを理解するのはそれほど簡単ではありません。
Event timelines for running goroutines
trace by proc：そのプロセッサで実行されているゴルーチンのタイムラインを各瞬間に表示します。
trace by thread：OS スレッドで実行されているゴルーチンのタイムラインを各瞬間に表示します。
Goroutine analysis：各グループのメイン関数のゴルーチン関連統計情報を表示します。
Profiles
- Network blocking profile：ネットワーク IO によりブロッキングされたゴルーチン情報
- Synchronization blocking profile：同期プリミティブによりブロッキングされたゴルーチン情報
- Syscall profile：システム呼び出しによりブロッキングされたゴルーチン情報
User-defined tasks and regions
- User-defined tasks：ユーザー定義タスクの関連ゴルーチン情報
- User-defined regions：ユーザー定義コード領域の関連ゴルーチン情報
Garbage collection metrics
Minimum mutator utilization：最近の GC の最大実行時間を表示します。
