logo

twihike's website

プロファイリング（pprof）

GoではCPUやメモリのボトルネックを調査するためのプロファイリングツールが付属しています。

プロファイリングの方法

プロファイルを取得するにはいくつかの方法があります。

  • ベンチマークテストを実行する（go test）
  • 対象処理の前後にコードを追加する（runtime/pprof）
  • 測定を制御するためのhttpエンドポイントを追加する（net/http/pprof）

go test

ベンチマークテストによるプロファイリングについて説明します。

プロファイルを取得するには、-cpuprofileオプションや-memprofileオプションを追加します。

go test -bench BenchmarkSprintfPadding -cpuprofile cpu.pprof -memprofile mem.pprof fmt

プロファイルを参照するにはgo tool pprofコマンドを使います。 引数にはプロファイルのファイルパスを指定します。

$ go tool pprof cpu.pprof
File: fmt.test
Type: cpu
Time: Jan 1, 2021 at 9:00am (UTC)
Duration: 1.61s, Total samples = 3.50s (217.98%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

go tool pprofが起動したら、もっとも重要なtopNコマンドを実行します。これは上位N件のサンプルを表示します。

(pprof) top10
Showing nodes accounting for 2240ms, 64.00% of 3500ms total
Dropped 52 nodes (cum <= 17.50ms)
Showing top 10 nodes out of 48
      flat  flat%   sum%        cum   cum%
     480ms 13.71% 13.71%      500ms 14.29%  strconv.(*decimal).Assign
     410ms 11.71% 25.43%      440ms 12.57%  strconv.rightShift
     250ms  7.14% 32.57%     2610ms 74.57%  fmt.(*pp).doPrintf
     210ms  6.00% 38.57%      230ms  6.57%  strconv.fmtF
     180ms  5.14% 43.71%      180ms  5.14%  runtime.duffzero
     170ms  4.86% 48.57%     1780ms 50.86%  strconv.genericFtoa
     160ms  4.57% 53.14%     1610ms 46.00%  strconv.bigFtoa
     140ms  4.00% 57.14%      220ms  6.29%  runtime.mallocgc
     140ms  4.00% 61.14%      140ms  4.00%  unicode/utf8.RuneCount
     100ms  2.86% 64.00%      100ms  2.86%  fmt.(*fmt).writePadding

出力結果の見方は次の通りです。

  • flat：関数の処理時間。関数の中で呼び出した関数の時間を含まない
  • sum：flatの現在行までの合計。3行目のsumは1行目から3行目の処理時間の合計
  • cum：関数の処理時間。関数の中で呼び出した関数の時間を含む

デフォルトではflatの列でソートされます。cumの列でソートするには-cumオプションを指定します。

(pprof) top10 -cum
Showing nodes accounting for 0.88s, 25.14% of 3.50s total
Dropped 52 nodes (cum <= 0.02s)
Showing top 10 nodes out of 48
      flat  flat%   sum%        cum   cum%
     0.05s  1.43%  1.43%      3.42s 97.71%  fmt_test.BenchmarkSprintfPadding.func1
         0     0%  1.43%      3.42s 97.71%  testing.(*B).RunParallel.func1
     0.07s  2.00%  3.43%      3.37s 96.29%  fmt.Sprintf
     0.25s  7.14% 10.57%      2.61s 74.57%  fmt.(*pp).doPrintf
     0.03s  0.86% 11.43%      2.29s 65.43%  fmt.(*pp).printArg
     0.04s  1.14% 12.57%      2.26s 64.57%  fmt.(*pp).fmtFloat
     0.07s  2.00% 14.57%      2.22s 63.43%  fmt.(*fmt).fmtFloat
     0.04s  1.14% 15.71%      1.82s 52.00%  strconv.AppendFloat (inline)
     0.17s  4.86% 20.57%      1.78s 50.86%  strconv.genericFtoa
     0.16s  4.57% 25.14%      1.61s 46.00%  strconv.bigFtoa

メモリも同様に参照できます。

$ go tool pprof mem.pprof
File: fmt.test
Type: alloc_space
Time: Jan 1, 2021 at 9:00am (UTC)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top10
Showing nodes accounting for 132.54MB, 99.25% of 133.54MB total
Dropped 8 nodes (cum <= 0.67MB)
Showing top 10 nodes out of 20
      flat  flat%   sum%        cum   cum%
  129.50MB 96.98% 96.98%      130MB 97.35%  fmt.Sprintf
    1.16MB  0.87% 97.84%     1.16MB  0.87%  runtime/pprof.StartCPUProfile
       1MB  0.75% 98.59%        1MB  0.75%  testing.(*T).Run
    0.88MB  0.66% 99.25%     0.88MB  0.66%  compress/flate.NewWriter
         0     0% 99.25%     0.88MB  0.66%  compress/gzip.(*Writer).Write
         0     0% 99.25%      130MB 97.35%  fmt_test.BenchmarkSprintfPadding.func1
         0     0% 99.25%     2.16MB  1.62%  main.main
         0     0% 99.25%     2.16MB  1.62%  runtime.main
         0     0% 99.25%     0.88MB  0.66%  runtime/pprof.(*profileBuilder).appendLocsForStack
         0     0% 99.25%     0.88MB  0.66%  runtime/pprof.(*profileBuilder).build
(pprof)

runtime/pprof

プロファイリング対象の処理の前後にコードを追加して、プロファイルを取得する方法を説明します。

CPUは測定対象の処理の前後にpprof.StartCPUProfile関数とpprof.StopCPUProfile関数を実行します。

func main() {
    f, err := os.Create("cpu.prof")
    if err != nil {
        log.Fatal("CPUプロファイル作成失敗： ", err)
    }
    defer func() {
        if err := f.Close(); err != nil {
            log.Fatal("CPUプロファイルクローズ失敗： ", err)
        }
    }()
    if err := pprof.StartCPUProfile(f); err != nil {
        log.Fatal("CPUプロファイル開始失敗： ", err)
    }
    defer pprof.StopCPUProfile()

    // ここに測定対象の処理があるとする
}

メモリは測定対象の処理を実行後にpprof.WriteHeapProfile関数を実行します。

func main() {
    // ここに測定対象の処理があるとする

    f, err := os.Create("mem.prof")
    if err != nil {
        log.Fatal("メモリプロファイル作成失敗： ", err)
    }
    defer func() {
        if err := f.Close(); err != nil {
            log.Fatal("メモリプロファイルクローズ失敗： ", err)
        }
    }()
    // runtime.GC()
    if err := pprof.WriteHeapProfile(f); err != nil {
        log.Fatal("メモリプロファイル開始失敗： ", err)
    }
}

プロファイルの参照方法はgo testによるプロファイリングと同様です。

net/http/pprof

Webサーバやその他の常駐プログラムのプロファイリングには測定を制御するためのhttpエンドポイントを追加します。

デフォルトのマルチプレクサを利用する場合はnet/http/pprofパッケージをブランクインポートするだけです。

package main

import (
    "log"
    "net/http"
    _ "net/http/pprof"
)

func main() {
    http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
        w.Write([]byte("Hello."))
    })
    log.Fatal(http.ListenAndServe(":8080", nil))
}

ブランクインポートをすると/debug/pprofの配下にいくつかのエンドポイントが追加されます。

独自のマルチプレクサを利用する場合は、次の通りエンドポイントを追加します。

package main

import (
    "log"
    "net/http"
    "net/http/pprof"
)

func main() {
    mux := http.NewServeMux()
    mux.HandleFunc("/debug/pprof/", pprof.Index)
    mux.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline)
    mux.HandleFunc("/debug/pprof/profile", pprof.Profile)
    mux.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
    mux.HandleFunc("/debug/pprof/trace", pprof.Trace)
    mux.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
        w.Write([]byte("Hello."))
    })
    log.Fatal(http.ListenAndServe(":8080", mux))
}

プロファイルを取得するには、対象のプログラムを起動します。 その後、go tool pprofコマンドを使ってプロファイルの取得と参照をします。引数にはエンドポイントを指定します。

CPUのプロファイルを取得にはエンドポイント/debug/pprof/profileを指定します。コマンドを実行すると測定が始まります。デフォルトでは30秒間続きます。

$ go tool pprof http://localhost:8080/debug/pprof/profile
Fetching profile over HTTP from http://localhost:8080/debug/pprof/profile

30秒経過すると、それまでのプロファイルを参照できます。

$ go tool pprof http://localhost:8080/debug/pprof/profile
Fetching profile over HTTP from http://localhost:8080/debug/pprof/profile
Saved profile in /home/go/pprof/pprof.a.samples.cpu.001.pb.gz
File: a
Type: cpu
Time: Jan 1, 2021 at 9:00am (UTC)
Duration: 30s, Total samples = 20ms (0.067%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top3 
Showing nodes accounting for 20ms, 100% of 20ms total
Showing top 3 nodes out of 9
      flat  flat%   sum%        cum   cum%
      10ms 50.00% 50.00%       10ms 50.00%  runtime.checkTimers
      10ms 50.00%   100%       10ms 50.00%  runtime.futex
         0     0%   100%       10ms 50.00%  runtime.findrunnable

メモリのプロファイルを参照するにはエンドポイント/debug/pprof/heapを指定します。コマンドを実行すると、その時点のメモリのプロファイルを取得します。

$ go tool pprof http://localhost:8080/debug/pprof/heap
Fetching profile over HTTP from http://localhost:8080/debug/pprof/heap
Saved profile in /home/go/pprof/pprof.a.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz
File: a
Type: inuse_space
Time: Jan 1, 2021 at 9:00am (UTC)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top3 
Showing nodes accounting for 650.62kB, 100% of 650.62kB total
Showing top 3 nodes out of 14
      flat  flat%   sum%        cum   cum%
  650.62kB   100%   100%   650.62kB   100%  compress/flate.(*compressor).init
         0     0%   100%   650.62kB   100%  compress/flate.NewWriter
         0     0%   100%   650.62kB   100%  compress/gzip.(*Writer).Write

参考リンク