引き続きPerconaシリーズ機能紹介で、今回はスロークエリについてです。
Slow Query Log – Percona Server 5.5 Documentation に綺麗に書かれていますが、日本語での要約ということで・・・
スロークエリログの基本設定
処理時間が0.5秒以上 かつ 検索対象が10000行以上のクエリを残す場合はこんな感じ。秒数はマイクロまで可能だけど、まぁ0.1でもやりすぎなくらいでしょう。あと、インデックスを使わないけど軽いクエリってのもあるから、log-queries-not-using-indexes は直接調査する時用かと。|
1 2 3 4 5 |
slow_query_log slow_query_log_file = /fio/mysql_log/system/slow-queries.log long_query_time = 0.5 #log-queries-not-using-indexes min_examined_row_limit = 10000 |
スロークエリ関係はほとんどがDynamicだけど、SET GLOBAL しても新しいセッションに対してしか反映されないので、持続接続を使っている場合だとAPサーバの再起動が必要になるでしょう。
データ作成
時間のかかる処理を行うために、適当な量のデータを作成します。ここでは sysbench を使って、1GB / 440万行 のデータを作成しています。|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 |
# sysbenchインストール apt-get install sysbench # DB作成 mysqladmin -u root -p create sbtest # テーブル作成 sysbench --mysql-host=localhost --mysql-user=test --mysql-password=test \ --test=oltp --oltp-table-size=4400000 \ prepare # データ容量確認 ls -lh /fio/mysql/sbtest/sbtest.ibd -rw-rw---- 1 mysql mysql 1.0G 2012-09-13 12:29 /fio/mysql/sbtest/sbtest.ibd |
記録内容
実際のログ
MySQLとPerconaを比較してみると、Perconaの方が多いことがわかります。MySQL
|
1 2 3 4 5 |
# Time: 120913 12:39:36 # User@Host: root[root] @ localhost [] # Query_time: 27.651141 Lock_time: 0.063576 Rows_sent: 50 Rows_examined: 8800050 SET timestamp=1347507576; SELECT * FROM sbtest ORDER BY RAND() LIMIT 50; |
Percona Server
|
1 2 3 4 5 6 7 8 |
# Time: 120913 12:38:19 # User@Host: root[root] @ localhost [] # Thread_id: 41 Schema: sbtest Last_errno: 0 Killed: 0 # Query_time: 51.573579 Lock_time: 0.000133 Rows_sent: 50 Rows_examined: 8800050 Rows_affected: 0 Rows_read: 50 # Bytes_sent: 3502 Tmp_tables: 1 Tmp_disk_tables: 1 Tmp_table_sizes: 2450800000 # InnoDB_trx_id: B07 SET timestamp=1347507499; SELECT * FROM sbtest ORDER BY RAND() LIMIT 50; |
接続情報
スレッドIDが入っているので、セッション単位で追うことができます。でもAPから持続接続使ってて同じ種類のIDがズラーってのが普通かもです。
|
1 |
# Thread_id: 41 Schema: sbtest Last_errno: 0 Killed: 0 |
行数の追加情報
Rows_examinedは検索対象となった行数。Rows_affectedは更新クエリ時の更新行数。
Rows_readはレスポンス行数のようで、ドキュメント説明となんか違う感じ。Rows_sentとの違いはわかりません。
|
1 |
# Query_time: 51.573579 Lock_time: 0.000133 Rows_sent: 50 Rows_examined: 8800050 Rows_affected: 0 Rows_read: 50 |
TMPテーブル情報
特にTmp_diskの量は改善対象となるので重要です。|
1 |
# Bytes_sent: 3502 Tmp_tables: 1 Tmp_disk_tables: 1 Tmp_table_sizes: 2450800000 |
追加記録内容
log_slow_verbosity を設定することで、追加情報を記録できます。|
1 |
log_slow_verbosity = full |
fullでとった内容はこんな感じ。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 |
# Time: 120913 12:58:21 # User@Host: root[root] @ localhost [] # Thread_id: 45 Schema: sbtest Last_errno: 0 Killed: 0 # Query_time: 34.452360 Lock_time: 0.000134 Rows_sent: 50 Rows_examined: 8800050 Rows_affected: 0 Rows_read: 50 # Bytes_sent: 3499 Tmp_tables: 1 Tmp_disk_tables: 1 Tmp_table_sizes: 2450800000 # InnoDB_trx_id: B08 # QC_Hit: No Full_scan: Yes Full_join: No Tmp_table: Yes Tmp_table_on_disk: Yes # Filesort: Yes Filesort_on_disk: Yes Merge_passes: 202 # InnoDB_IO_r_ops: 58994 InnoDB_IO_r_bytes: 966557696 InnoDB_IO_r_wait: 8.327283 # InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000 # InnoDB_pages_distinct: 60281 SET timestamp=1347508701; SELECT * FROM sbtest ORDER BY RAND() LIMIT 50; |
Query Plan
EXPLAINと同様の、チューニングに重要な情報が簡潔に記録されます。|
1 2 |
# QC_Hit: No Full_scan: Yes Full_join: No Tmp_table: Yes Tmp_table_on_disk: Yes # Filesort: Yes Filesort_on_disk: Yes Merge_passes: 202 |
InnoDB Usage Information
普段Global情報としてしか見れないInnoDB情報を、クエリ単独の数値で残すことができます。各値の説明は、ドキュメント参照で。|
1 2 3 |
# InnoDB_IO_r_ops: 58994 InnoDB_IO_r_bytes: 966557696 InnoDB_IO_r_wait: 8.327283 # InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000 # InnoDB_pages_distinct: 60281 |
フィルター
どのようなログを残すかのフィルターをかけることができます。例えばDISK上の処理になってしまっているクエリを全て残すなら、このように設定します。
|
1 |
log_slow_filter = tmp_table_on_disk,filesort_on_disk |
フィルターの種類は log_slow_filter を参照してください。
スロークエリの条件的な設定は全てand条件になり、コンマ区切りの設定値はorになるので、ここまでを合わせると、
保存割合
log_slow_rate_type と log_slow_rate_limit で残すログの割合を調整できます。ここまで細かく調整して利用することは少ないかもしれませんが、スロークエリの改善は最も効果的なチューニングの１つであり、スロークエリの改善に注力する時期は必ずあるので、知っておいて損はないはずです。
個人的には、他人が書いたクエリやスキーマのチューニングという仕事は好きな部類でして、スロークエリ・ゼロを目指す楽しさもさることながら、改善点を見つけ出して
へいへ～い、何この●●●！？
って報告してあげる下衆な喜び！！
