pprofでCPU100%になる原因を特定する

tcpdpのprobeモードで、CPUが100%に張り付くという問題(結果、原因としてはしょうもないミス)がありました。

機能としては正しく動いているので、単純にテストケースを増やしてもどうにもならず、pprofを使って原因となっている箇所を絞り込んでみました。

本エントリはその記録です。なお、原因特定の問題としてはおそらく初級レベルだと思います(わからない)。

現状把握

tcpdp probetcpdump のようにインターフェースに流れるパケットをキャプチャするコマンドです。

ところが、以下のように実行したら、まだパケットを流していないのにCPUが100%に張り付きます。

$ sudo tcpdp probe -c t.toml
Password:
2018-09-30T00:40:42.199+0900    info    Starting probe. interface: lo0, target: 33306
2018-09-30T00:40:42.201+0900    info    Select dumper mysql.
$ sudo ps au
USER    PID  %CPU %MEM      VSZ    RSS   TT  STAT STARTED      TIME COMMAND
root  69915 100.3  0.2  4402600  36692 s003  R+   12:14AM   5:17.36 ./tcpdp probe -c t.toml
root  43796   0.3  0.1  4405812   8708 s002  S+   10:44PM   0:25.13 ./tcpdp probe -c t.toml
[...]

net/http/pprof を設置する

とりあえず net/http/pprof を設置します。

$ git diff
diff --git a/main.go b/main.go
index bc38d4c..2a0119b 100644
--- a/main.go
+++ b/main.go
@@ -20,8 +20,19 @@

 package main

-import "github.com/k1LoW/tcpdp/cmd"
+import (
+       "log"
+       "net/http"
+       _ "net/http/pprof"
+       "runtime"
+
+       "github.com/k1LoW/tcpdp/cmd"
+)

 func main() {
+       runtime.SetBlockProfileRate(1)
+       go func() {
+               log.Println(http.ListenAndServe("0.0.0.0:6060", nil))
+       }()
        cmd.Execute()
 }

参考URL

golang の net/http/pprof を触ってみたメモ - sonots:blog

go tool pprof でCPUのプロファイルを見る

net/http/pprof を設置したので、もう一度 tcpdp probe を実行します。そうすると http://localhost:6060/debug/pprof/ でプロファイル情報のページが生成されます。

そのプロファイルページに go tool pprof でアタッチして、CPUのプロファイルを見てみます。

localhost:6060 で起動している pprof のプロファイルページの /debug/pprof/profilego tool pprof でアタッチして、top で確認してみます。

$ go tool pprof -seconds 5 http://localhost:6060/debug/pprof/profile
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=5
Please wait... (5s)
Saved profile in /Users/k1low/pprof/pprof.samples.cpu.007.pb.gz
Type: cpu
Time: Sep 29, 2018 at 12:54am (JST)
Duration: 5.14s, Total samples = 4.40s (85.59%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 3870ms, 87.95% of 4400ms total
Dropped 10 nodes (cum <= 22ms)
Showing top 10 nodes out of 21
      flat  flat%   sum%        cum   cum%
    1440ms 32.73% 32.73%     3550ms 80.68%  runtime.selectgo 👈
     480ms 10.91% 43.64%      480ms 10.91%  runtime.unlock
     450ms 10.23% 53.86%      450ms 10.23%  runtime.lock
     360ms  8.18% 62.05%      360ms  8.18%  runtime.cputicks
     240ms  5.45% 67.50%      720ms 16.36%  runtime.selunlock
     240ms  5.45% 72.95%      240ms  5.45%  sync.(*Mutex).Unlock
     220ms  5.00% 77.95%      220ms  5.00%  sync.(*Mutex).Lock
     160ms  3.64% 81.59%      160ms  3.64%  runtime.(*hchan).sortkey (inline)
     140ms  3.18% 84.77%     4350ms 98.86%  github.com/k1LoW/tcpdp/reader.(*PacketReader).ReadAndDump 👈
     140ms  3.18% 87.95%      140ms  3.18%  runtime.duffzero

あああ、、、もう特定できてしましましたね。

runtime.selectgo が実行時間 (flat)では多いですが、関数内の呼び出しを含めた実行時間 (cum) をみると github.com/k1LoW/tcpdp/reader.(*PacketReader).ReadAndDump が支配的です。

この関数の中で何かをやらかしているのは明白です。

参考URL

Go pprof 入門編 (CPU Profile とコマンドラインツール) : KLabGames Tech Blog

go tool pprof -http を使ってWebUI上でグラフで確認する

ここで終わってもそっけないので、今度は pprof の WebUIを使ってグラフで確認してみます。

localhost:6060 で起動している pprof のプロファイルページにアタッチして 8888 で pprof の WebUIを立ち上げます。

$ go tool pprof -http=":8888" localhost:6060

するとWebページが開いて、グラフを確認することができます。

f:id:k1LoW:20180930121902p:plain

あああ、ReadAndDumpさん。。。

参考URL

Go 1.10でGolangのプロファイリングツール pprof のWebUIが入った話 - Keepdata Blog

go-torch を使ってFlame Graphで確認する

懲りずにさらに、go-torch を使ってFlame Graphで確認してみます。

まず、準備として go-torch と FlameGraph を落としておきます。

$ go get github.com/uber/go-torch
$ git clone https://github.com/brendangregg/FlameGraph

localhost:6060 で起動している pprof のプロファイルページにアタッチしてFlame Graphのsvgファイルを生成します。

$ PATH=$PATH:/path/to/FlameGraph go-torch --time 5 --url http://localhost:6060/debug/pprof/profile

f:id:k1LoW:20180930122026p:plain

。。。。ReadAndDumpで決定ですね。

参考URL

GolangでFlame Graphを描く | SOTA

原因特定

原因はReadAndDumpで実行しているforの中のselect句で、「何もしないdefault:が存在している」ことで、ビジーループになっていたことでした。しょうもないバグ。

default: を取り除き、最終的にpprof のプロファイル結果も以下のようにスッキリしました。

$ go tool pprof -seconds 5 http://localhost:6060/debug/pprof/profile
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=5
Please wait... (5s)
Saved profile in /Users/k1low/pprof/pprof.samples.cpu.013.pb.gz
Type: cpu
Time: Sep 29, 2018 at 2:27am (JST)
Duration: 5s, Total samples = 20ms (  0.4%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 20ms, 100% of 20ms total
      flat  flat%   sum%        cum   cum%
      20ms   100%   100%       20ms   100%  github.com/k1LoW/tcpdp/vendor/github.com/google/gopacket/pcap.(*Handle).getNextBufPtrLocked.func1
         0     0%   100%       20ms   100%  github.com/k1LoW/tcpdp/vendor/github.com/google/gopacket.(*PacketSource).NextPacket
         0     0%   100%       20ms   100%  github.com/k1LoW/tcpdp/vendor/github.com/google/gopacket.(*PacketSource).packetsToChannel
         0     0%   100%       20ms   100%  github.com/k1LoW/tcpdp/vendor/github.com/google/gopacket/pcap.(*Handle).ReadPacketData
         0     0%   100%       20ms   100%  github.com/k1LoW/tcpdp/vendor/github.com/google/gopacket/pcap.(*Handle).getNextBufPtrLocked

f:id:k1LoW:20180930122104p:plain

該当の修正Pull Requestはこちら

まとめ

今回はpprofを使ってCPU100%張り付きの原因特定をしてみました。

自分は、こういう「計測」には慣れていないので、これからも素振りをしていこうと思います。