# 【Mysql】大量のスロークエリログを簡単に解析できる mysqldumpslow > Mysql の大量のスロークエリログを簡単に解析できる mysqldumpslow を使ってみる。 - Canonical: https://c-a-p-engineer.github.io/mysql-mysqldumpslow/ - Published: 2022-10-18T09:00:00.000Z - Modified: 2022-10-18T09:00:00.000Z - Categories: Database - Tags: Database, MySQL # 【Mysql】スロークエリを簡単に解析できる mysqldumpslow Mysql のスロークエリログを簡単に解析できる mysqldumpslow を使ってみる。 ## mysqldumpslow `mysqldumpslow` コマンドを使用することで大量のスロークエリログを簡単に解析できます。 ### インストール `mysqldumpslow` コマンドを使用するにには `mysql-server` のインストールが必要なようです。 僕は面倒なので mysql のコンテナを使用しました。 ### 使用方法 使用方法は以下です。 ``` mysqldumpslow [オプション] [ログファイル] ``` オプション一覧 * `-a` すべての数字を N に、文字列を 'S' に抽象化しません * `-n` 少なくとも指定された桁数の数字を抽象化 * `--debug`,`-d` デバッグ情報を書き込み * `-g` grepオプション、パターンに一致するステートメントのみを考慮 * `--help` ヘルプメッセージを表示して終了 * `-h` ログファイル名内のサーバーのホスト名 * `-i` サーバーインスタンスの名前 * `-l` 合計時間からロック時間を減算しない * `-r` ソート順序を逆転 * `-s` 出力のソート方法 * `t`,`at` クエリー時間または平均クエリー時間でソート * `l` ,`al` ロック時間または平均ロック時間でソート * `r`,`ar` 送信行数または平均送信行数でソート * `c` カウントでソート * `-t` 最初から指定された数だけのクエリーのみ表示 * `--verbose` 冗長モード ### 返却値説明 `mysqldumpslow` を実行すると以下のような返却がされます。 ``` Reading mysql slow query log from /usr/local/mysql/data/mysqld80-slow.log Count: 1 Time=4.32s (4s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@localhost insert into t2 select * from t1 Count: 3 Time=2.53s (7s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@localhost insert into t2 select * from t1 limit N Count: 3 Time=2.13s (6s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@localhost insert into t1 select * from t1 ``` * `Count` 実行回数 * `Time` 実行平均時間（合計時間 * `Lock` ロック平均時間（合計時間 * `Rows` 返却平均行（返却合計行 ### スロークエリログの項目説明 第154回　スロークエリログに出力される項目とlog_slow_extra | gihyo.jp から引用 ``` # Time: 2021-08-29T08:49:05.382813Z # User@Host: root[root] @ [172.17.0.1] Id: 10 # Query_time: 9.685363 Lock_time: 0.000210 Rows_sent: 1 Rows_examined: 2097153 SET timestamp=1630226935; SELECT * FROM test WHERE col1=10; ``` Mysql 5.7までの項目 * `Time` スロークエリログに書き込んだ時間 * `User@Host` クエリを実行したユーザアカウント * `Id` SHOW PROCESSLISTのID * `Query_time` ステートメントの実行時間（秒） * `Lock_time` ロックを取得した時間（秒） * `Rows_sent` クライアントに送信された行数 * `Rows_examined` MySQLが内部で走査した行数 ``` # Time: 2021-08-29T08:50:58.916765Z # User@Host: root[root] @ [172.17.0.1] Id: 10 # Query_time: 9.076753 Lock_time: 0.000243 Rows_sent: 1 Rows_examined: 2097153 Thread_id: 10 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 251 Read_first: 1 Read_last: 0 Read_key: 1 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 2097154 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2021-08-29T08:50:49.840012Z End: 2021-08-29T08:50:58.916765Z SET timestamp=1630227049; SELECT * FROM test WHERE col1=10; ``` Mysql 8.0以降の項目 * `Thread_id` Idと同じくSHOW PROCESSLISTのID * `Errno` エラー番号、エラーが発生しなかった場合は0 * `Killed` 終了した場合、理由を示すエラー番号。ステートメントが正常に終了した場合は0 * `Bytes_received` ステートメントのステータスBytes_receivedの値 * `Bytes_sent` ステートメントのステータスBytes_sentの値 * `Read_xx` ステートメントのステータス Handler_Read_xxのそれぞれの項目の値 * `Sort_merge_passes` ステートメントのステータスSort_merge_passesの値 * `Sort_range_count` ステートメントのステータスSort_range_countの値 * `Sort_rows` ステートメントのステータスSort_rowsの値 * `Sort_scan_count` ステートメントのステータスSort_scan_countの値 * `Created_tmp_disk_tables` ステートメントのステータスCreated_tmp_disk_tablesの値 * `Created_tmp_tables` ステートメントのステータスCreated_tmp_tablesの値 * `Start` ステートメントの実行開始時間 * `End` ステートメントの実行終了時間 ### 複数ファイルを一括で解析 以下のようにすると複数のスロークエリログを一括で解析してくれます。 ``` mysqldumpslow slow_001.log slow_002.log ``` ## サンプル 多用しそうなものをサンプルとして置いておきます。 ### 発生回数でソート 10件表示 発生回数でソートして10件表示 ``` mysqldumpslow -s c -t 10 mysql-slowquery.log ``` ### 合計処理時間でソート 10件表示 合計処理時間でソートして10件表示 ``` mysqldumpslow -s t -t 10 mysql-slowquery.log ``` `-a` を付けると抽象化されないので一番処理時間がかかっているクエリが出てきます。 （まったく同じクエリを何度も投げていたら集計されてしまいますが… ## 参考 * MySQL :: MySQL 8.0 リファレンスマニュアル :: 4.6.9 mysqldumpslow — スロークエリーログファイルの要約 * 第154回　スロークエリログに出力される項目とlog_slow_extra | gihyo.jp