Goのnet/http/pprofは pprofで可視化できる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のもの。
ここから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()の割合が少なくなり他の関数が表に出てくる。
内部実装
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)
}
...
}