Maatkitはtcpdumpを食べられる上，memcachedも咀嚼出来る．
で紹介したMaatkitのMySQLのクエリ統計ツールmk-query-digest．
mk-query-digest /var/lib/mysql/db.slow.log
という風にして，MySQLのスローログを食べて
# Query 73: 0.00 QPS, 0.00x concurrency, ID 0x2256C8F4C0666085 at byte 322977024 # This item is included in the report because it matches --outliers. # pct total min max avg 95% stddev median # Count 0 10 # Exec time 0 20s 2s 2s 2s 2s 0 2s # Lock time 0 0 0 0 0 0 0 0 # Rows sent 0 6 0 1 0.60 0.99 0.49 0.99 # Rows exam 0 6 0 1 0.60 0.99 0.49 0.99 # Users 1 write_user # Hosts 1 # Databases 1 service # Time range 2010-04-21 07:05:39 to 2010-05-10 05:58:15 # bytes 0 633 56 77 63.30 69.19 6.19 59.77 # Query_time distribution # 1us # 10us # 100us # 1ms # 10ms # 100ms # 1s ################################################################ # 10s+ # Tables # SHOW TABLE STATUS FROM `service` LIKE 'comments'\G # SHOW CREATE TABLE `service`.`comments`\G # EXPLAIN SELECT * FROM `comments` WHERE (subject = '無題') LIMIT 1\G # Profile # Rank Query ID Response time Calls R/Call Item # ==== ================== ================= ===== ======== =============== # 1 0x1AD058F6B2B1C729 283809.0000 39.3% 12707 22.3349 SELECT service.daily_posts service.comments # 2 0x406C0D65D82E1378 85750.0000 11.9% 37685 2.2754 INSERT daily_posts # 3 0x54F9616817F34E26 83601.0000 11.6% 10300 8.1166 SELECT trackbacks refers # 4 0xA0E155F694763885 77228.0000 10.7% 34552 2.2351 INSERT daily_posts
みたいな結果を吐いてくれる，インフラエンジニアがアプリエンジニアを突つくのに大変有用なツールです．
manちゃんと読んで，perlで書かれてるんだからmk-query-digestの中も見てみればわかる話だったのですが，知って感動したのでご紹介．
tcpdumpも食べることができる
実はスローログだけでなく，"--type tcpdump"とすると，tcpdumpを解析してくれて同様の結果を得ることが可能です．
[root@db-server ~]# tcpdump -s 65535 -x -n -q -tttt -i eth0 port 3306 > db-server_tcpdump.log &
といった感じで，16進でMySQLの使っているインタフェースとポートのtcpdumpで取得して*1
[root@db-server ~]$ mk-query-digest --type tcpdump db-server_tcpdump.log
としてmk-query-digestに渡すと
# 23.3s user time, 380ms system time, 50.50M rss, 142.54M vsz # Current date: Thu Oct 28 05:28:54 2010 # Files: db-server_tcpdump.log # Overall: 13.32k total, 169 unique, 0 QPS, 0x concurrency _______________ # total min max avg 95% stddev median # Exec time 17s 0 2s 1ms 2ms 26ms 49us # Time range 2010-10-26 02:12:4.284813 to 2010-10-26 02:13:18.640810 # bytes 1.27M 16 3.40k 99.83 223.14 165.04 76.28 # Rows affe 0 0 0 0 0 0 0 # Warning c 0 0 0 0 0 0 0 # 0% (104) No_index_used # Profile # Rank Query ID Response time Calls R/Call Item # ==== ================== ================ ===== ======== ================ # 1 0x3EAC88605740560E 1.7511 12.8% 13 0.1347 SELECT contents # 2 0x55B5177B0B53B45C 1.5913 11.6% 1 1.5913 SELECT user_extends # 3 0x5A8BCDBF32217A70 1.5874 11.6% 1 1.5874 SELECT users (以下略)
という風に結果が得られる．
利点としては，スローログをMySQLに吐かせるよう設定するのを省けることが大きいです．
スローログの設定適用のためにMySQLを再起動させないといけないとか，スローログのために若干のパフォーマンス劣化が起きてしまうというリスクを避けることが出来るのは有り難い．
ただ，tcpdumpのデータサイズが膨大なので，1日を通してのデータを取ったりすることがストレージ的に困難な場合があるので，解析の目的に応じて使い分けることになりそうです．
今更気づいて驚いた
と，ここまではmanでさーっと読んでて知っていたのですが，実はmemcachedへの操作も解析出来るそうです．
早速試してみました．
memcachedが動作しているサーバで，（勿論memcachedとやり取りしているアプリでも）
[root@memcached-server ~]# tcpdump -s 65535 -x -n -q -tttt -i eth0 port 11211 > memcached_tcpdump.log &
というように，memcachedで使用しているポート（デフォルトなら11211番）のtcpdumpをファイルに出力させて
[hmsk@hmsk maatkit]$ mk-query-digest --type memcached memcached_tcpdump.log
と，--typeでmemcachedを指定すると
# 29.9s user time, 620ms system time, 72.46M rss, 164.49M vsz # Current date: Thu Oct 28 05:45:35 2010 # Files: memcached_tcpdump.log # Overall: 18.41k total, 456 unique, 36.15 QPS, 0.01x concurrency ________ # total min max avg 95% stddev median # Exec time 5s 0 90ms 277us 972us 1ms 66us # Time range 2010-10-26 01:57:11.867607 to 2010-10-26 02:05:41.094805 # bytes 37.34M 0 15.92k 2.08k 8.89k 3.47k 28.75 # 0% (5) Memc_delete # 0% (1) Memc_error # 82% (15k) Memc_get # 26% (5k) Memc_miss # 17% (3k) Memc_set # Profile # Rank Query ID Response time Calls R/Call Item # ==== ================== ================ ===== ======== ==== # 1 0xA84BE88AEDAF9ADA 1.9009 41.0% 9947 0.0002 # 2 0x077519F6209A4D3E 1.4673 31.7% 2115 0.0007 SET # 3 0x51189AA660F3540B 0.2215 4.8% 145 0.0015 SET # 4 0x8BAF56C85EB6A49E 0.1473 3.2% 1107 0.0001 # 5 0x68EC9C5BF90DD38A 0.1240 2.7% 656 0.0002 # 6 0x2DE7943EA7FB8692 0.1225 2.6% 504 0.0002 # 7 0xB200401F70D3B20D 0.1166 2.5% 600 0.0002 # 8 0x26D9CDBD3E55E315 0.1146 2.5% 652 0.0002 # 9 0x972BDD196E7667B2 0.1072 2.3% 134 0.0008 SET # 10 0x5F62BAC30BB7DA9B 0.0935 2.0% 136 0.0007 SET # 11 0xE31DCE3D0B0D1D2A 0.0696 1.5% 116 0.0006 SET # 12 0xB3811846DD0ADA58 0.0531 1.1% 106 0.0005 SET # 13 0x629D210CFA982C5F 0.0192 0.4% 48 0.0004 # 14 0x5AB72B6C086CEF16 0.0169 0.4% 43 0.0004 # 15 0x9E8019F16D3F8EEF 0.0107 0.2% 12 0.0009 SET # 16 0x952992846C6FB389 0.0104 0.2% 11 0.0009 SET # 17 0xA2053E049A7FBA97 0.0100 0.2% 7 0.0014 SET # 18 0x6E9266D43FEF7954 0.0097 0.2% 91 0.0001 # 19 0xC39BD33B065530C0 0.0092 0.2% 87 0.0001 # 20 0x4AFBF650CB22D9AF 0.0090 0.2% 1 0.0090 SET # Query 1: 19.54 QPS, 0.00x concurrency, ID 0xA84BE88AEDAF9ADA at byte 39270389 # This item is included in the report because it matches --limit. # pct total min max avg 95% stddev median # Count 54 9947 # Exec time 37 2s 0 69ms 191us 881us 992us 60us # Hosts 17 192.168.41.61 (718), 192.168.41.77 (686)... 15 more # Time range 2010-10-26 01:57:12.066904 to 2010-10-26 02:05:41.094805 # bytes 28 10.54M 0 15.00k 1.09k 8.06k 2.64k 28.75 # key print 1 cmb:? # 0% (1) Memc_error # 100% (10k) Memc_get # 32% (3k) Memc_miss # Query_time distribution # 1us ## # 10us ################################################################ # 100us ############################# # 1ms #### # 10ms # # 100ms # 1s # 10s+ get cmb:45f17bdc8ba99a920b51618eec993ebe\G （以下略）
という風にmemcachedとのやり取りの統計を得ることが出来ます．すごい．
恥ずかしながら，今までキャッシュヒット率だけを計算させてグラフに描いて眺めてドヤ顔でしたが，getやset,missの割合とキーの内容を土産にもう一歩アプリエンジニアと話す機会が増えました．良かった．
- 作者: Baron Schwartz,Peter Zaitsev,Vadim Tkachenko,Jeremy D. Zawodny,Arjen Lentz,Derek J. Balling,伊藤直也(監訳),田中慎司(監訳),吉川英興(監訳),株式会社クイープ
- 出版社/メーカー: オライリージャパン
- 発売日: 2009/12/14
- メディア: 大型本
- 購入: 17人 クリック: 373回
- この商品を含むブログ (45件) を見る
