Goのnet/http/pprofでCPUやMemoryをprofileする流れと内部実装

(2019-09-16)

Goのnet/http/pprofpprofで可視化できるprofile.protoを返すAPIを提供するpackage。 profileを出力する方法はほかにもあるが、サーバーのような動き続けるアプリケーションのprofileを取るのに使う。

go testでベンチマークを取ってpprofで時間がかかっている箇所を調べる - sambaiz-net

profileを取る

import _ "net/http/pprof"してhttp.ListenAndServe()する。

package main

import (
	"fmt"
	"net/http"
	_ "net/http/pprof"
	"time"

	"golang.org/x/crypto/bcrypt"
)

func handler(w http.ResponseWriter, r *http.Request) {
	for i := 0; i < 3; i++ {
		bcrypt.GenerateFromPassword([]byte("PASSWORD"), bcrypt.DefaultCost)
	}
	arr := []int{}
	for i := 0; i <  10000; i++ {
		arr = append(arr, i)
	}
	fmt.Fprintf(w, "OK")
}

func main() {
	http.HandleFunc("/foo", handler)
	fmt.Println("Listening on :8080")
	if err := http.ListenAndServe(":8080", nil); err != nil {
		panic(err)
	}
}

CPUはdebug/pprof/profileを叩いた後の一定時間のみprofileするのでその間にリクエストを送る必要がある。

.PHONY: build clean run request cpu_profile memory_profile

build: clean
	go build main.go

clean:
	rm main

run: build
	./main

cpu_profile: request
	bash -c 'sleep 5s; for var in `seq 100`; do curl -s http://localhost:8080/foo; done' > /dev/null &
	go tool pprof -http=":8000" ./main localhost:8080/debug/pprof/profile?seconds=10

memory_profile: request
	bash -c 'sleep 5s; for var in `seq 100`; do curl -s http://localhost:8080/foo; done' > /dev/null
	go tool pprof -http=":8000" ./main localhost:8080/debug/pprof/allocs

profileが終わるとWeb UIが立ち上がる。Flame Graphの縦はスタックを、横の長さは時間や量を表す。これはCPUのもの。

CPUのFlame Graph

ここからblowfish.ExpandKey()で呼ばれているblowfish.encryptBlock()が実行時間のほとんど全てを占めていることが分かり、Sourceからコードと合わせて行ごとのかかった時間を見ることができる。

行ことのかかった時間

flatとcumの違いは呼び出した関数の時間も含めるかどうかで、他の関数を呼んでいないencryptBlock()では同じ値になっているが、呼び出し元をみると微小のflatに対してcumが大きくなっていることが確認できる。

49 10ms 10ms   for i := 0; i < 256; i += 2 { 
50 20ms 2.44s    l, r = encryptBlock(l, r, c) 
51 .    .        c.s0[i], c.s0[i+1] = l, r 
52 .    .      } 

Costを最小にして再度profileを取ってみると、encryptBlock()の割合が少なくなり他の関数が表に出てくる。

MinCostでのFlame Graph

内部実装

importするとinit()でエンドポイントが追加される。

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)
}

/debug/pprof/*

profileの一覧ページおよびCPU以外のprofileを返す。

func Index(w http.ResponseWriter, r *http.Request) {
	if strings.HasPrefix(r.URL.Path, "/debug/pprof/") {
		name := strings.TrimPrefix(r.URL.Path, "/debug/pprof/")
		if name != "" {
			handler(name).ServeHTTP(w, r)
			return
		}
	}

	var profiles []profile
	for _, p := range pprof.Profiles() {
		profiles = append(profiles, profile{
			Name:  p.Name(),
			Href:  p.Name() + "?debug=1",
			Desc:  profileDescriptions[p.Name()],
			Count: p.Count(),
		})
	}
	...
	if err := indexTmpl.Execute(w, profiles); err != nil {
		log.Print(err)
	}
}

func (name handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
	p := pprof.Lookup(string(name))
	...
	p.WriteTo(w, debug)
}

Lookup()は 名前からprofileを取得する関数。 built-inのprofileに加えて独自のprofileをAdd()することもできる。

func Lookup(name string) *Profile {
	lockProfiles()
	defer unlockProfiles()
	return profiles.m[name]
}

func lockProfiles() {
	profiles.mu.Lock()
	if profiles.m == nil {
		// Initial built-in profiles.
		profiles.m = map[string]*Profile{
			"goroutine":    goroutineProfile,
			"threadcreate": threadcreateProfile,
			"heap":         heapProfile,
			"allocs":       allocsProfile,
			"block":        blockProfile,
			"mutex":        mutexProfile,
		}
	}
}

Profileはcount()write()する関数を持つstruct。それぞれ p.Count()p.WrireTo()で呼ばれる。

type Profile struct {
	name  string
	mu    sync.Mutex
	m     map[interface{}][]uintptr
	count func() int
	write func(io.Writer, int) error
}

var allocsProfile = &Profile{
	name:  "allocs",
	count: countHeap,
	write: writeAlloc,
}

func countHeap() int {
	n, _ := runtime.MemProfile(nil, true)
	return n
}

func writeAlloc(w io.Writer, debug int) error {
	return writeHeapInternal(w, debug, "alloc_space")
}

/debug/pprof/profile

CPU profileをStartして一定時間経ったらStopする。

if err := pprof.StartCPUProfile(w); err != nil {
	...
}
sleep(w, time.Duration(sec)*time.Second)
pprof.StopCPUProfile()

StartCPUProfile()SetCPUProfileRate()してprofileを書いていく。

func StartCPUProfile(w io.Writer) error {
	const hz = 100
	...
	cpu.profiling = true
	runtime.SetCPUProfileRate(hz)
	go profileWriter(w)
	return nil
}

SetCPUProfileRate()の内部では、OSに対応する setProcessCPUProfiler()setThreadCPUProfiler() が呼ばれ、Unixの場合setitimer(ITIMER_PROF)システムコールでCPU時間10ms経過後SIGPROFが送られるようにして、これをハンドリングしている。

func setProcessCPUProfiler(hz int32) {
	if hz != 0 {
		// Enable the Go signal handler if not enabled.
		if atomic.Cas(&handlingSig[_SIGPROF], 0, 1) {
			atomic.Storeuintptr(&fwdSig[_SIGPROF], getsig(_SIGPROF))
			setsig(_SIGPROF, funcPC(sighandler))
		}
	}
	...
}

func setThreadCPUProfiler(hz int32) {
	var it itimerval
	if hz == 0 {
		setitimer(_ITIMER_PROF, &it, nil)
	} else {
		it.it_interval.tv_sec = 0
		it.it_interval.set_usec(1000000 / hz)
		it.it_value = it.it_interval
		setitimer(_ITIMER_PROF, &it, nil)
	}
	...
}