golang profiling の基礎

golang profiling の基礎

• 1.
  golang profilingの基礎 CA.go#1 (2017/06/21) 株式会社AbemaTV中澤優⼀郎
• 2.
  ⾃⼰紹介 中澤 優⼀郎 (はせ) 経歴 •2012/06~AmebaスマートフォンPF •2014/01~ 『タップル誕⽣』 •2015/12~ 『AbemaTV』 Golang歴 2年
• 3.
  Profiling of golang pprof(runtime/pprof) • GolangのProfilingを⾏うパッケージ • CPU・Memory・goroutineなどの情報を収集 • protocol buffer形式でプロファイルを保存 • `go tool pprof` によりプロファイルを分析
• 4.
  runtime/pprof CPU Profiler • 関数の実⾏時間をプロファイリング •(UNIX) settimerを利⽤し10msごとに SIGPROFシグナル送信 • サンプラはシグナルをハンドリングし スタックトレースを保存 f, err := os.Create(*cpuprofile)
 if err != nil {
 log.Fatal("could not create CPU profile: ", err)
 }
 if err := pprof.StartCPUProfile(f); err != nil {
 log.Fatal("could not start CPU profile: ", err)
 }
 defer pprof.StopCPUProfile()
• 5.
  runtime/pprof CPU Proflier以外のProfilerはLookupで呼び出し f, err := os.Create("./mem.prof") if err != nil { log.Fatal("could not create memory profile: ", err) } defer func() { pprof.Lookup("heap").WriteTo(f, 0) f.Close() }()
• 6.
  runtime/pprof “heap” (Heap Profiler) •メモリの情報(GCとアロケーション)をプロファイリング “goroutine” (Goroutine Profiler) • 実⾏中のgoroutineのプロファイリング heap options (go tool pprof -inuse_space mem.prof ) -inuse_space 利⽤中のメモリ領域 -inuse_objects メモリ利⽤中のオブジェクト数 -alloc_space 前回のGCからアロケートされたメモリ領域
• 7.
  runtime/pprof “block” (Blocking Profiler) ※runtime.SetBlockProfileRate を 1 以上に設定することで有効化 • 同期処理でwaitingしているgoroutineをプロファイリング “mutex” (Mutex Profiler) ※go1.8から追加 ※ runtime.SetMutexProfileFraction を 1 以上に設定することで有効化 • 同期処理をブロックする ”mutexのみ” をプロファイリング • time.Tickerなどパフォーマンスに深刻な影響を与えない項⽬は表⽰されない
• 8.
  runtime/pprof Custom Profilers Profilerの実装によりカスタムプロファイラを作成可能 import “runtime/pprof" prof := pprof.New(“custom”) prof.Add(obj, 1) prof.Remove(1)
• 9.
  Relational Packages runtime/pprof net/http/pprof •HTTP Server⽤のプロファイラ github.com/pkg/profile •`runtime/pprof`をより簡単に利⽤できるようなwrapper •元はdevecheneyの `https://github.com/davecheney/profile`
• 10.
  net/http/pprof Web Server向けpprofパッケージ • http経由でプロファイリングを取得 •2種類のバインド⽅法 • DefaultServeMuxにバインド (blank import) • ServeMuxをNewしてバインド import ( "net/http" "net/http/pprof" "runtime" ) --- mux := http.NewServeMux() mux.Handle("/debug/pprof/", http.HandlerFunc(pprof.Index)) mux.Handle("/debug/pprof/cmdline", http.HandlerFunc(pprof.Cmdline)) mux.Handle("/debug/pprof/profile", http.HandlerFunc(pprof.Profile)) mux.Handle("/debug/pprof/symbol", http.HandlerFunc(pprof.Symbol)) mux.Handle("/debug/pprof/trace", http.HandlerFunc(pprof.Trace)) --- go func() { log.Println(http.ListenAndServe("localhost:6060", mux)); } import _ "net/http/pprof" go func() { log.Println(http.ListenAndServe("localhost:6060", nil)) }()
• 11.
  github.com/pkg/profile runtime/pprofをシンプルなインターフェースで提供 • shutdown signalのハンドリング 以下のプロファイラを利⽤可能 •CPU Profiler • Heap Profiler • Block Profiler • Trace Profiler (runtime/trace) package main import ( "github.com/pkg/profile" ) func main() { defer profile.Start(profile.BlockProfile).Stop() }
• 12.
  go test profiling テストコードのプロファイリング テストオプションに指定することによりプロファイリング可能 -blockprofileblock.out : Block Profileの取得 -cpuprofile cpu.out : CPU Profileの取得 -memprofile mem.out : Heap Profileの取得 -mutexprofile mutex.out : Mutex Profileの取得
• 13.
  Go tool pprof $ go tool pprof --text mpeg-probe sample.prof/cpu.pprof 108.45s of 112.28s total (96.59%) Dropped 148 nodes (cum <= 0.56s) flat flat% sum% cum cum% 78.03s 69.50% 69.50% 78.18s 69.63% syscall.Syscall 8.47s 7.54% 77.04% 8.47s 7.54% runtime.mach_semaphore_wait 7.19s 6.40% 83.44% 7.19s 6.40% runtime.mach_semaphore_signal 3.43s 3.05% 86.50% 3.43s 3.05% runtime.mach_semaphore_timedwait 3.02s 2.69% 89.19% 3.02s 2.69% runtime.memclrNoHeapPointers プロファイリングの集計・可視化 •`go tool pprof` を利⽤して • コマンドラインでの実⾏と、インタラクティブシェルを提供
• 14.
  Go tool pprof (pprof)web • svg形式で吐き出されたプロファイルをwebブラウザで表⽰ • function名の指定で絞り込み • graphvizのインストールが必要 $ go tool pprof mpeg-probe sample.prof/cpu.pprof Entering interactive mode (type "help" for commands) (pprof) web main
• 15.
  Go tool pprof (pprof)top • 取得したプロファイルの上位N件の表⽰ • `-FIELD` 指定によりソート (pprof) top 5 -flat 100.14s of 112.28s total (89.19%) Dropped 148 nodes (cum <= 0.56s) Showing top 5 nodes out of 92 (cum >= 3.02s) flat flat% sum% cum cum% 78.03s 69.50% 69.50% 78.18s 69.63% syscall.Syscall 8.47s 7.54% 77.04% 8.47s 7.54% runtime.mach_semaphore_wait 7.19s 6.40% 83.44% 7.19s 6.40% runtime.mach_semaphore_signal 3.43s 3.05% 86.50% 3.43s 3.05% runtime.mach_semaphore_timedwait 3.02s 2.69% 89.19% 3.02s 2.69% runtime.memclrNoHeapPointers flat : 関数の使⽤した値 flat% : flat値の全体の占める割合 sum% : 現在のソート順でのflat値の累計値 cum : 関数の他の関数の呼び出しも含めた値 cum% : cum値の全体に占める割合
• 16.
  Go tool pprof (pprof)list • go tool実⾏時にバイナリファイルの指定が必要 • ソースコード上でのflat,cum値を表⽰ (pprof) list io.Copy Total: 1.87mins ROUTINE ======================== io.Copy in /usr/local/Cellar/go/1.8.1/libexec/src/io/io.go 0 1.09mins (flat, cum) 58.15% of Total . . 355:// If src implements the WriterTo interface, . . 356:// the copy is implemented by calling src.WriteTo(dst). . . 357:// Otherwise, if dst implements the ReaderFrom interface, . . 358:// the copy is implemented by calling dst.ReadFrom(src). . . 359:func Copy(dst Writer, src Reader) (written int64, err error) { . 1.09mins 360: return copyBuffer(dst, src, nil) . . 361:} . . 362: . . 363:// CopyBuffer is identical to Copy except that it stages through the . . 364:// provided buffer (if one is required) rather than allocating a
• 17.
  Check Point runtime.mallocgc • メモリアロケーションが多く発⽣している runtime.chanrecv,sync.Mutex • ロック処理により多くの待ちが発⽣している syscall Read / Write • ioの読み書きが⼤量に発⽣している GCコンポーネント • ヒープサイズの⼩ささにより、GCの発⽣が頻繁に発⽣している
• 18.
  Go Debug Options MemoryAllocator Trace - GODEBUG=allocfreetrace=1 Garbage Collector Trace - GODEBUG=gctrace=1 . Scheduler Trace - GODEBUG=schedtrace=1000 ./