tcpdpのprobeモードで、CPUが100%に張り付くという問題（結果、原因としてはしょうもないミス）がありました。
機能としては正しく動いているので、単純にテストケースを増やしてもどうにもならず、pprofを使って原因となっている箇所を絞り込んでみました。
本エントリはその記録です。なお、原因特定の問題としてはおそらく初級レベルだと思います（わからない）。
現状把握
tcpdp probe は tcpdump のようにインターフェースに流れるパケットをキャプチャするコマンドです。
ところが、以下のように実行したら、まだパケットを流していないのに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/profile に go 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ページが開いて、グラフを確認することができます。
あああ、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
。。。。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
該当の修正Pull Requestはこちら。
まとめ
今回はpprofを使ってCPU100%張り付きの原因特定をしてみました。
自分は、こういう「計測」には慣れていないので、これからも素振りをしていこうと思います。
