ISUCONの為のpprof
Go Conference ‘19 Summer in Fukuoka
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
Fukuoka Gopher @seike460�
所属：株式会社Fusic �名前：清家史郎 (せいけしろう) �技術：Go、PHP、AWS
カンファレンス運営
2
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
ServerlessなGopherのプロポーザルお待ちしております！
(福岡は鋭意PaperCall準備中…！)
3
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
Agenda
4
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
Agenda
5
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
ISUCONとpprof
6
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
ISUCONとは
7
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
8
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
ISUCON9 予選 採点
9
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
ISUCON9 予選レギュレーション (ソフトウェア事項抜粋）
10
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
レギュレーションの内であれば自由
11
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
推測するな計測せよ
12
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
pprofの概要
13
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
pprofとは
14
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
利用イメージ
15
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
pprofの利用方法
16
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
runtime/pprofの単体での利用方法
17
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
runtime/pprofにて取得出来る項目
18
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
example (golang.org)
19
var cpuprofile = flag.String("cpuprofile", "", "write cpu profile to `file`")
var memprofile = flag.String("memprofile", "", "write memory profile to `file`")
func main() {
flag.Parse()
if *cpuprofile != "" {
f, err := os.Create(*cpuprofile)
if err != nil {
log.Fatal("could not create CPU profile: ", err)
}
defer f.Close()
if err := pprof.StartCPUProfile(f); err != nil {
log.Fatal("could not start CPU profile: ", err)
}
defer pprof.StopCPUProfile()
}
// ... rest of the program ...
if *memprofile != "" {
f, err := os.Create(*memprofile)
if err != nil {
log.Fatal("could not create memory profile: ", err)
}
defer f.Close()
runtime.GC() // get up-to-date statistics
if err := pprof.WriteHeapProfile(f); err != nil {
log.Fatal("could not write memory profile: ", err)
}
}
}
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
net/http/pprofの利用方法
20
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
net/http/pprofの提供URL一覧
21
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
結果入力利用方法（CUI）
22
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
結果入力利用方法（GUI）
23
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
ISUCON におけるオペレーションイメージ
24
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
pprofを使ったISUCONへのアプローチ
25
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
yisuconを利用して初期アプローチ
26
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
pprofの設置
27
runtime.SetBlockProfileRate(1) ← blocking profilerの有効化
runtime.SetMutexProfileFraction(1) ← mutex profilerの有効化
go func() {
log.Println(http.ListenAndServe("0.0.0.0:6060", nil))
}()
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
ビジュアライズの各種の見方の説明
28
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
結果 (Top)
29
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
結果の見方 (Top)
30
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
結果の見方 (Graph)
31
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
結果の見方 (Graph)
32
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
結果の見方 (Flame Graph)
33
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
結果の見方 (Flame Graph)
34
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
結果の見方 (Peek)
35
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
結果の見方 (Peek)
36
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
結果の見方 (source)
37
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
結果の見方 (source)
38
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
特定したボトルネックを対処後
39
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
アプローチ方法のおさらい
40
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
pprofのソースを読んでみる
41
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
net/http/pprof (func init)
42
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)
}
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
net/http/pprof (func Profile)
43
func Profile(w http.ResponseWriter, r *http.Request) {
w.Header().Set("X-Content-Type-Options", "nosniff")
sec, err := strconv.ParseInt(r.FormValue("seconds"), 10, 64)
if sec <= 0 || err != nil {
sec = 30
}
if durationExceedsWriteTimeout(r, float64(sec)) {
serveError(w, http.StatusBadRequest, "profile duration exceeds server's WriteTimeout")
return
}
// Set Content Type assuming StartCPUProfile will work,
// because if it does it starts writing.
w.Header().Set("Content-Type", "application/octet-stream")
w.Header().Set("Content-Disposition", `attachment; filename="profile"`)
if err := pprof.StartCPUProfile(w); err != nil {
// StartCPUProfile failed, so no writes yet.
serveError(w, http.StatusInternalServerError,
fmt.Sprintf("Could not enable CPU profiling: %s", err))
return
}
sleep(w, time.Duration(sec)*time.Second)
pprof.StopCPUProfile()
}
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
runtime/pprof ( func StartCPUProfile)
44
func StartCPUProfile(w io.Writer) error {
// The runtime routines allow a variable profiling rate,
// but in practice operating systems cannot trigger signals
// at more than about 500 Hz, and our processing of the
// signal is not cheap (mostly getting the stack trace).
// 100 Hz is a reasonable choice: it is frequent enough to
// produce useful data, rare enough not to bog down the
// system, and a nice round number to make it easy to
// convert sample counts to seconds. Instead of requiring
// each client to specify the frequency, we hard code it.
const hz = 100
cpu.Lock()
defer cpu.Unlock()
if cpu.done == nil {
cpu.done = make(chan bool)
}
// Double-check.
if cpu.profiling {
return fmt.Errorf("cpu profiling already in use")
}
cpu.profiling = true
runtime.SetCPUProfileRate(hz)
go profileWriter(w)
return nil
}
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
runtime ( func SetCPUProfileRate)
45
func SetCPUProfileRate(hz int) {
// Clamp hz to something reasonable.
if hz < 0 {
hz = 0
}
if hz > 1000000 {
hz = 1000000
}
lock(&cpuprof.lock)
if hz > 0 {
if cpuprof.on || cpuprof.log != nil {
print("runtime: cannot set cpu profile rate until previous profile has finished.\n")
unlock(&cpuprof.lock)
return
}
cpuprof.on = true
cpuprof.log = newProfBuf(1, 1<<17, 1<<14)
hdr := [1]uint64{uint64(hz)}
cpuprof.log.write(nil, nanotime(), hdr[:], nil)
setcpuprofilerate(int32(hz))
} else if cpuprof.on {
setcpuprofilerate(0)
cpuprof.on = false
cpuprof.addExtra()
cpuprof.log.close()
}
unlock(&cpuprof.lock)
}
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
runtime/pprof ( func StopCPUProfile)
46
func StopCPUProfile() {
cpu.Lock()
defer cpu.Unlock()
if !cpu.profiling {
return
}
cpu.profiling = false
runtime.SetCPUProfileRate(0)
<-cpu.done
}
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
まとめ
47
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
まとめ
48
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉
Thank you!
Fusicは技術が大好きなエンジニアを募集しています
https://fusic.github.io/
49
🍉🌴🏄♂️ GoConference’19 🏄♂️🌴🍉