MQRのpprofとってみた
sysbenchで適当な負荷をかけてMQRのpprof, general_log, slow_log, tcpdumpをとってみた
pprofの結果
(pprof) peek main
----------------------------------------------------------+------------- [16/90]
flat flat% sum% cum cum% calls calls% + context
----------------------------------------------------------+-------------
4.95s 100% | main.main.func2
0.11s 0.56% 0.56% 4.95s 25.19% | main.sendQuery
2.16s 43.64% | github.com/garyburd/redigo/redis.(*activeConn).Do
1.35s 27.27% | fmt.Sprintf
0.48s 9.70% | github.com/tom--bo/mysql-packet-deserializer.Deseri
alizePacket
0.16s 3.23% | github.com/garyburd/redigo/redis.(*Pool).Get
0.15s 3.03% | runtime.convT2E
0.14s 2.83% | runtime.concatstring2
0.13s 2.63% | runtime.convT2Eslice
0.06s 1.21% | github.com/garyburd/redigo/redis.(*activeConn).Clos
e
0.05s 1.01% | runtime.newobject
0.04s 0.81% | github.com/google/gopacket.(*eagerPacket).Layer
0.04s 0.81% | runtime.convT2E16
0.04s 0.81% | runtime.convT2Estring
0.02s 0.4% | github.com/google/gopacket.(*eagerPacket).Applicati
onLayer
0.01s 0.2% | github.com/google/gopacket.(*Payload).Payload
0.01s 0.2% | github.com/google/gopacket.(*eagerPacket).Metadata
----------------------------------------------------------+-------------
(pprof) peek sendQuery
Showing nodes accounting for 19.65s, 100% of 19.65s total
----------------------------------------------------------+-------------
flat flat% sum% cum cum% calls calls% + context
----------------------------------------------------------+-------------
4.95s 100% | main.main.func2
0.11s 0.56% 0.56% 4.95s 25.19% | main.sendQuery
2.16s 43.64% | github.com/garyburd/redigo/redis.(*activeConn).Do
1.35s 27.27% | fmt.Sprintf
0.48s 9.70% | github.com/tom--bo/mysql-packet-deserializer.DeserializePacket
0.16s 3.23% | github.com/garyburd/redigo/redis.(*Pool).Get
0.15s 3.03% | runtime.convT2E
0.14s 2.83% | runtime.concatstring2
0.13s 2.63% | runtime.convT2Eslice
0.06s 1.21% | github.com/garyburd/redigo/redis.(*activeConn).Close
0.05s 1.01% | runtime.newobject
0.04s 0.81% | github.com/google/gopacket.(*eagerPacket).Layer
0.04s 0.81% | runtime.convT2E16
0.04s 0.81% | runtime.convT2Estring
0.02s 0.4% | github.com/google/gopacket.(*eagerPacket).ApplicationLayer
0.01s 0.2% | github.com/google/gopacket.(*Payload).Payload
0.01s 0.2% | github.com/google/gopacket.(*eagerPacket).Metadata
----------------------------------------------------------+-------------
redisに送信するときに1クエリごとに送ってしまっていてスロットリングしていないのとfmt.Sprintfが予想以上に重いことがわかった。
クエリの取得状況
general_log, slow_log(long_query_time = 0)がSELECTでgrepしたときに完全に一致していた。 コードレベルでどのタイミングを書き出しているのか知らないけれど完全に同じでちょっと安心した。
tcpdump
wiresharkで見たときに[tcp retransmission] となる再送がかなり発生していて、そのときに再送のクエリもMQRではとってしまうので、sequence_idを見るとかして回避しないといけないことがわかった。
