この記事は KLab Advent Calendar 2015 の19日目の記事です。

pprof 連載最後は、 ここまでで紹介してきたプロファイラがどういう仕組みでプロファイリングしているかを解説します。 pprof が表示している値がどう計算されているのかを把握することで、よりプロファイラを理解して使いこなすことができるようになるはずです。

goroutine profile

スタックダンプ (/debug/pprof/goroutine?debug=1) の出力は次のような形式でした。

...
1 @ 0x42d2b3 0x42d374 0x414cda 0x45d981
#   0x42d2b3    runtime.gopark+0x163        /usr/local/go/src/runtime/proc.go:186
#   0x42d374    runtime.goparkunlock+0x54   /usr/local/go/src/runtime/proc.go:191
#   0x414cda    runtime.runfinq+0xaa        /usr/local/go/src/runtime/mfinal.go:154

213 @ 0x42d2b3 0x42d374 0x403570 0x402ca3 0x4011a8 0x45d981
#   0x4011a8    main.NewCounter.func1+0x48  /home/inada-n/work/techblog/20151218_inada-n/stack-sample.go:13
...

実はこれも pprof が利用できるプロファイル結果と同じフォーマットです。 # で始まる行はコメントで、 サンプル数 @ コールスタック が pprof が利用しているデータです。 (コメント行は ?debug=1 をつけていないときは出力されません。)

スタックダンプは、取得時点の全 goroutine のスタックトレースを取得して、 1 goroutine を 1 サンプルとしてカウントしていました。
他のプロファイラーも、いつどこで1サンプルとなるスタックトレースを取得するかやファイルフォーマットは異なりますが、最終的に go tool pprof が表示する手前でコールスタックごとのサンプル数という形になります。

CPU profile

/debug/pprof/profile のハンドラーから追いかけて行きましょう。

// Profile responds with the pprof-formatted cpu profile.
// The package initialization registers it as /debug/pprof/profile.
func Profile(w http.ResponseWriter, r *http.Request) {
        sec, _ := strconv.ParseInt(r.FormValue("seconds"), 10, 64)
        if sec == 0 {
                sec = 30
        }

        // Set Content Type assuming StartCPUProfile will work,
        // because if it does it starts writing.
        w.Header().Set("Content-Type", "application/octet-stream")
        if err := pprof.StartCPUProfile(w); err != nil {
                // StartCPUProfile failed, so no writes yet.
                // Can change header back to text content
                // and send error code.
                w.Header().Set("Content-Type", "text/plain; charset=utf-8")
                w.WriteHeader(http.StatusInternalServerError)
                fmt.Fprintf(w, "Could not enable CPU profiling: %s\n", err)
                return
        }
        time.Sleep(time.Duration(sec) * time.Second)
        pprof.StopCPUProfile()
}

runtime/pprof の StartCPUProfile を直接レスポンスに出力させて、指定時間 (デフォルトは30秒) 待ってから StopCPUProfile を呼んでいます。

StartCPUProfile は、 Unix では setitimer(ITIMER_PROF, ...) を使って、CPU使用時間 10ms ごとに一度 SIGPROF シグナルを受け取り、そのたびにスタックトレースを取得し渡された io.Writer にバイナリ形式で書き出していきます。 Windows では ITIMER_PROF が無いので、 優先度を最高にしたスレッドで 10ms 周期のタイマーを待ち、タイマーが発火する度に動作中の goroutine のスタックトレースを取得します。

CPUプロファイルの出力は pprof の元となった google perftools の CPU プロファイルのバイナリフォーマットで、スタックトレースを集計せずに追記していき、 pprof ツール側で集計しています。 表示するときは、 10ms に一度サンプルを取得しているので1サンプルあたり10msに換算して時間表示をしています。

この方式は sampling profiler と呼ばれ、ある程度のサンプル数がまとまらないと精度がでないので、 10ms や 20ms という表示は無視しましょう。

heap profile

Go のプログラムでメモリをヒープから確保するとき、アロケータ (runtime の mallocgc という関数) が実際のメモリ確保を行います。
ヒーププロファイラはこのアロケータに統合されていて、 runtime.MemProfileRate で指定された容量を確保する度に、アロケータを呼び出した箇所のスタックトレースを取得します。

Memo: 実際には MemProfileRate を平均とした乱数でサンプリングすることで、プログラムのメモリ確保のパターンによって特定の箇所を実際の割合以上にサンプリングしてしまうことを避けています)

そしてアロケータはスタックトレースごとにアロケート回数、アロケートしたバイト数を記録しておき、さらにGCによってそのメモリオブジェクトが解放されるときに解放した回数、開放したバイト数を保存するようにします。

最終的にメモリプロファイルを取得しフォーマットするときは、 google-perftools のヒーププロファイラと同じフォーマットを利用しています。これは次のようなフォーマットになっています。

heap profile: 46592: 90221136 [105937: 236992760] @ heap/2048
1: 71303168 [1: 71303168] @ 0x40aaa2 0x4099eb 0x401289 0x401808 0x42dd60 0x45e4d1
1: 17768448 [1: 17768448] @ 0x440ed1 0x401739 0x401816 0x42dd60 0x45e4d1
15304: 244864 [15304: 244864] @ 0x445397 0x44521f 0x463876 0x401149 0x401808 0x42dd60 0x45e4d1
15284: 244544 [15284: 244544] @ 0x445397 0x44521f 0x463876 0x40123b 0x401808 0x42dd60 0x45e4d1

最初の1行はヘッダで、 46592: 90221136 の部分はトータルの inuse_objects: inuse_space で、 次の [105937: 236992760] は [alloc_objects: alloc_space] です。 @ heap/2048 は、 MemProfileRate * 2 が 2048 であることを示しています。 (2倍になっているのは google-perftools との互換性のため。)

以降の行がプロファイル結果です。 @ マークの後がスタックトレースなのは他のプロファイルと同様です。 @ マークの左側はヘッダと同じ書式で、そのスタックトレースにおける inuse_objects: inuse_space [alloc_objects, alloc_space] を表しています。

pprof ツールは、 inuse と alloc のどちらをパースするかを最初に選択したうえで、 objects: space を読み込んで、 MemProfileRate を元に推定値を計算します。
例えば 15304: 244864 の場合、平均のアロケートサイズは 244846 / 15304 = 16 バイトになります。 MemProfileRate が 1024 のとき、 16 バイトのアロケートは 16/1024 = 1/64 なので 64 回に1回の割合でサンプリングされることになります。 そこで objects と space 両方を 64 倍した値が pprof が表示する推定値となります。

保存したプロファイルを利用するときの注意点

pprof は http 経由でプロファイルを取得したときに protobuf を圧縮した形式 (.pb.gz) で $HOME/pprof 配下にプロファイル結果を保存しますが、元になるプロファイル結果をパースする段階で inuse か alloc を選んでいるので、保存するファイルにも http 経由で取得する段階で選択していた方だけが記録されています。

前の記事でメモリーリーク調査のために pprof の -base オプションを使って差分を計算する手順を紹介しましたが、この時に inuse と alloc の差分を取ってしまうと全く意味のない結果が表示されることになるので注意が必要です。

なお、 objects: space はペアで保存されているので、例えば -inuse_objects で取得した .pb.gz を -inuse_space で参照するのは問題ありません。

いっそのこと、ヒーププロファイルは生のプロファイル結果を curl で取得してしまって、差分を計算するスクリプトを作ったほうがリークの調査には良いかもしれません。この記事を書くために調査していて気づいたので、今度試してみます。

count profile

runtime/pprof パッケージを使って、 goroutine プロファイルと同じように単純なスタックトレースごとのカウントを表現するプロファイラーを自作できます。次のソースコードは、コネクションプールの利用状況をプロファイルすることを想定したサンプルコードです。

package main

import (
    "math/rand"
    "net/http"
    _ "net/http/pprof"
    "runtime/pprof"
    "sync"
    "time"
)

var poolProf = pprof.NewProfile("conns")

type Conn int

type ConnPool struct {
    m        sync.Mutex
    freelist []*Conn
}

func (p *ConnPool) Get() *Conn {
    p.m.Lock()
    defer p.m.Unlock()
    var c *Conn

    if len(p.freelist) > 0 {
        last := len(p.freelist) - 1
        c = p.freelist[last]
        p.freelist = p.freelist[:last]
    } else {
        c = new(Conn)
    }

    poolProf.Add(c, 2)
    return c
}

func (p *ConnPool) Put(c *Conn) {
    poolProf.Remove(c)
    p.m.Lock()
    p.freelist = append(p.freelist, c)
    p.m.Unlock()
}

var pool = &ConnPool{}

func workerA() {
    for {
        time.Sleep(time.Duration(rand.Intn(100)) * time.Millisecond)
        c := pool.Get()
        time.Sleep(time.Duration(rand.Intn(100)) * time.Millisecond)
        pool.Put(c)
    }
}

func workerB() {
    for {
        time.Sleep(time.Duration(rand.Intn(50)) * time.Millisecond)
        c := pool.Get()
        time.Sleep(time.Duration(rand.Intn(100)) * time.Millisecond)
        pool.Put(c)
    }
}

func main() {
    go http.ListenAndServe(":6000", nil)

    for i := 0; i < 10; i++ {
        go workerA()
        go workerB()
    }
    for {
        time.Sleep(time.Second)
    }
}

pprof.NewProfile でプロファイルを作成し、 .Add でスタックトレースを登録し、 .Remove で解除します。 .Add と .Remove の第一引数は、 .Remove が解除するスタックトレースを指定するためのキーで、 .Add と .Remove のペアで同じ値を利用します。同じキーを並行で利用することはできませんが、 .Remove 後に同じキーを .Add で再利用することは可能です。

このプロファイルを pprof を使って解析してみます。

$ go tool pprof pool-prof localhost:6000/debug/pprof/conns
Fetching profile from http://localhost:6000/debug/pprof/conns
Saved profile in /home/inada-n/pprof/pprof.pool-prof.localhost:6000.conns.002.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) top
10 of 10 total (  100%)
      flat  flat%   sum%        cum   cum%
         6 60.00% 60.00%          6 60.00%  main.workerB
         4 40.00%   100%          4 40.00%  main.workerA
         0     0%   100%         10   100%  runtime.goexit
(pprof) list main.main
Total: 10
(pprof) list main
Total: 10
ROUTINE ======================== main.workerA in /home/inada-n/t/pprof/pool-prof.go
         4          4 (flat, cum) 40.00% of Total
         .          .     45:var pool = &ConnPool{}
         .          .     46:
         .          .     47:func workerA() {
         .          .     48:   for {
         .          .     49:       time.Sleep(time.Duration(rand.Intn(100)) * time.Millisecond)
         4          4     50:       c := pool.Get()
         .          .     51:       time.Sleep(time.Duration(rand.Intn(100)) * time.Millisecond)
         .          .     52:       pool.Put(c)
         .          .     53:   }
         .          .     54:}
         .          .     55:
ROUTINE ======================== main.workerB in /home/inada-n/t/pprof/pool-prof.go
         6          6 (flat, cum) 60.00% of Total
         .          .     54:}
         .          .     55:
         .          .     56:func workerB() {
         .          .     57:   for {
         .          .     58:       time.Sleep(time.Duration(rand.Intn(50)) * time.Millisecond)
         6          6     59:       c := pool.Get()
         .          .     60:       time.Sleep(time.Duration(rand.Intn(100)) * time.Millisecond)
         .          .     61:       pool.Put(c)
         .          .     62:   }
         .          .     63:}
         .          .     64:
(pprof)

workerA が4つ、 workerB が6つのコネクションを利用中であることが判りました。

このプロファイルは goroutine プロファイルど同じ種類 (カウントプロファイル) なので、 ?debug=1 というクエリパラメータをつけてプレインテキストで見ても十分役に立ちます。

$ curl http://localhost:6000/debug/pprof/conns?debug=1
conns profile: total 14
6 @ 0x401315 0x45dcf1
#   0x401315    main.workerA+0x45   /home/inada-n/t/pprof/pool-prof.go:50

8 @ 0x4013b5 0x45dcf1
#   0x4013b5    main.workerB+0x45   /home/inada-n/t/pprof/pool-prof.go:59

例えば DB にクエリを投げてから結果が返ってくるまでをプロファイルしてみると面白いかもしれません。