Maatkit で MySQL チューニン グ YAPC::Asia Tokyo 2010 前夜祭

自己紹介 • 金子 健介 (Kensuke Kaneko) • プログラマ@ペパボ • 刺身☆ブーメラン • id:a666666 • @kyanny

No content

Maatkit とは • MySQL 用のユーティリティ集 • 作者は実践ハイパフォーマンスMySQLの著者 • なぜかエジプトっぽいロゴ • Perl スクリプトなので読みやすい $ wc -l mk-* 127964 total • （12万行もあるけど）読みやすい

MySQL チューニングのいろは • EXPLAIN • SHOW INDEXES • スロークエリログ • mysqldumpslow • mk-query-digest • mk-query-profiler

mk-query-digest • スロークエリログの統計データを表示 o tcpdump の結果なども読めるらしい • 豊富なオプション • 丁寧なドキュメント o perldoc mk-query-digest o でかでかと RISKS と書いてあってびびる

使い方 $ mk-query-digest --fingerprints slow.log # Files: slow.log # Overall: 115 total, 12 unique, 0.00 QPS, 0.03x concurrency _____________ # total min max avg 95% stddev median # Exec time 2323s 3s 338s 20s 49s 43s 5s # Lock time 6ms 22us 270us 55us 98us 31us 42us # Rows sent 22.92k 0 664 204.08 487.09 171.01 166.51 # Rows exam 730.08k 0 123.41k 6.35k 38.40k 18.22k 329.68 # Time range 2010-09-28 05:54:30 to 2010-09-29 04:00:47 # bytes 25.16k 134 2.45k 224.03 381.65 239.90 130.47 # Profile # Rank Query ID Response time Calls R/Call Item # ==== ================== ================ ===== ======== ================ # 1 0x5C552C534D2A3440 1114.2297 48.0% 17 65.5429 SELECT t3 # 2 0xD9C2EFCBECC526D1 549.2743 23.6% 73 7.5243 SELECT t2 # 3 0x0255F509DADB6455 457.1587 19.7% 9 50.7954 UPDATE t1 • オプションはドットファイルに書いておける • t3 テーブルへのクエリが非常に遅い

結果の見方 # Query 1: 0.00 QPS, 0.04x concurrency, ID 0x5C552C534D2A3440 at byte 3907 # pct total min max avg 95% stddev median # Count 14 17 # Exec time 47 1114s 3s 338s 66s 258s 96s 14s # Lock time 18 1ms 33us 86us 68us 80us 15us 73us # Rows sent 2 672 24 90 39.53 88.31 27.42 23.65 # Rows exam 50 372.21k 462 89.27k 21.89k 88.02k 30.14k 4.17k # Users 1 test # Hosts 1 # Databases 1 test # Time range 2010-09-28 05:54:30 to 2010-09-28 13:54:18 # bytes 15 3.97k 237 240 239.06 234.30 0 234.30 • 統計情報（全てのクエリ、個別のクエリ） • 注目すべき部分 o Exec time  これはとてもだめな例  平均 258 秒もかかっている

mk-query-profiler • もう少し詳しい情報を知りたい o 例: ディスク I/O がどれくらい発生しているか？ o EXPLAIN だけではわからないことも多い • プロファイリングツール o SET profiling=1 o oprofile o mk-query-profiler • mk-query-profiler の利点 o 導入が手軽  deb, rpm あります  スクリプト単体で入手可能 o 実行結果が見やすい

使い方 $ mk-query-profiler -u user -D database -vv sql.txt +----------------------------------------------------------+ | 1 (303.3715 sec) | +----------------------------------------------------------+ __ Overall stats _______________________ Value _____________ Total elapsed time 303.372 Questions 27350 COMMIT 0 DELETE 0 DELETE MULTI 0 INSERT 0 INSERT SELECT 0 REPLACE 0 REPLACE SELECT 0 SELECT 1 UPDATE 0 UPDATE MULTI 0 Data into server 208 Data out of server 39153 Optimizer cost 17504.809 • 長いので以下略

結果の見方 (1) • 今回は I/O に関係しそうな部分を重点的にみた +----------------------------------------------------------+ | 1 (303.3715 sec) | +----------------------------------------------------------+ __ Row operations ____________________ Handler ______ InnoDB Reads 92594 1816374 __ I/O Operations _____________________ Memory ________ Disk InnoDB buffer pool Reads 2474442 34106 Random read-aheads 390 Sequential read-aheads 36 __ InnoDB Data Operations ____ Pages _____ Ops _______ Bytes Reads 44271 38091 725336064 • ディスクからの読み込みが多い == 遅い

結果の見方 (2) • 同じクエリのプロファイル結果（連続して実行） +----------------------------------------------------------+ | 1 (0.6755 sec) | +----------------------------------------------------------+ __ Row operations ____________________ Handler ______ InnoDB Reads 92599 94843 __ I/O Operations _____________________ Memory ________ Disk InnoDB buffer pool Reads 323664 0 Random read-aheads 0 Sequential read-aheads 0 __ InnoDB Data Operations ____ Pages _____ Ops _______ Bytes Reads 0 0 0 • ディスクからの読み込みが減った o バッファプール（メモリ）に載っているのではやい

mk-query-profiler は何をしているか • 大半はオプションのパースと出力のフォーマット • 実際に仕事をしてるのは get_status_info() sub get_status_info { my ( $o, $dbh, $have_session ) = @_; my $res = $dbh->selectall_arrayref( $have_session ? ($o->get('external') ? 'SHOW GLOBAL STATUS' : 'SHOW SESSION STATUS') : 'SHOW STATUS' ); my %result = map { @{$_} } @$res; return { map { $_ => $result{$_} || 0 } @important_vars }; } • SHOW STATUS の結果を整形してる

プロファイル結果をふまえて • ディスクからのランダムリードが発生して遅くなっていた • Convering Index を使えるようにインデックスを追加した o 参考書籍  Linux-DB システム構築/運用入門  実践ハイパフォーマンスMySQL 第2版 • ブログにも少し書きました o http://d.hatena.ne.jp/a666666/20100920/1284992435

チューニング後 (1) # Files: slow.log # Overall: 68 total, 8 unique, 0.00 QPS, 0.02x concurrency _______________ # total min max avg 95% stddev median # Exec time 1152s 3s 80s 17s 49s 18s 9s # Lock time 3ms 22us 312us 49us 84us 36us 38us # Rows sent 18.11k 0 1.45k 272.78 487.09 257.13 223.14 # Rows exam 75.33k 0 46.46k 1.11k 1.20k 5.33k 271.23 # Time range 2010-10-02 08:19:13 to 2010-10-03 04:00:46 # bytes 17.99k 134 4.02k 270.90 363.48 499.75 130.47 # Profile # Rank Query ID Response time Calls R/Call Item # ==== ================== ================ ===== ======== ================ # 1 0xD9C2EFCBECC526D1 644.6672 55.9% 51 12.6405 SELECT t2 # 2 0x0255F509DADB6455 357.9470 31.1% 7 51.1353 UPDATE t1 # 3 0xE4D15EB8FF64B268 45.1097 3.9% 5 9.0219 SELECT t3 • t3 テーブルへのクエリに改善がみられた

チューニング後 (2) # Query 3: 0.01 QPS, 0.10x concurrency, ID 0xE4D15EB8FF64B268 at byte 6136 # pct total min max avg 95% stddev median # Count 7 5 # Exec time 3 45s 6s 12s 9s 12s 2s 8s # Lock time 8 285us 39us 90us 57us 89us 18us 47us # Rows sent 0 120 24 24 24 24 0 24 # Rows exam 5 4.20k 586 1006 861 964.41 144.29 918.49 # Users 1 test # Hosts 1 # Databases 1 test # Time range 2010-10-02 15:59:14 to 2010-10-02 16:06:35 # bytes 9 1.69k 346 346 346 346 0 346

考察 • mk-query-digest について o 統計情報をすばやく把握 o 平均や 95% など情報量が多い  慣れるまではちょっと多すぎるかも • mk-query-profiler について o より詳細なデータが取得できる  SHOW STATUS や SHOW ENGINE INNODB STATUS も大事ですね o 「たぶんディスク読み込みが遅いんでメンテします」と か言わずに済む o 仮説、調査、裏付け（！）、実行 o 自信をもってチューニングに取り組める

まとめ • Maatkit は便利で導入も簡単 • 豊富なオプションと丁寧なドキュメント • なぜかエジプトっぽいロゴ • MySQL チューニングのお供にぜひどうぞ o 参考  http://www.maatkit.org/  http://code.google.com/p/maatkit/  http://d.hatena.ne.jp/marqs/20100515/1273861805  http://d.hatena.ne.jp/hxmasaki/20100726/1280117979

終わり