まとめ
MySQLの実行時間（performance_schema.events_statements_xxxのTIMER_WAIT）は、「クエリを実行開始してから、クライアントにデータ送信完了するまで」が計上される。
「データ送信完了」とは、NWレベルで見ると、EOFパケットを送信完了するまで、の可能性が高い。
つまり、MySQL側でEOFパケットを送信し終わってから、EOFパケットをクライアント側で受け取るまでの間にはどれだけタイムラグがあっても、MySQL側の実行時間には計上されないはず。
ただし、レコードセットのサイズが大きい場合、クライアント側の仕様やネットワーク関連の設定（ウィンドウサイズ）によっては、クライアント側から追加のデータ送信を許可する「TCP Window Update」をMySQL側に送るまで、MySQL側が追加のレコードセットを送ることを待たされるケースがあり、結果的にEOFパケットの送信が遅れることに伴い、その遅延時間もMySQL側から見た実行時間に計上されるケースがある。
※という、理解です。可能な限り実験していますが、裏どりが不十分な記述もあります。
背景
MySQLのクエリ実行時間を後追いするにはどうすればいいか調べた結果、以下の2パターンに整理されると判断しました。
- スロークエリログには実行時間が情報として含まれるため、ログ記録の閾値を決めるパラメータ
long_query_timeを10ミリ秒など、かなり小さい値 or 0にして広範なクエリをスロークエリログに収集する - performance_schemaを活用する（以下のテーブル群の
TIMER_WAITカラムがピコ秒の単位で実行時間を持っている）- events_statements_current
- events_statements_history
- events_statements_history_long
もちろん、一長一短ありますが、この記事ではTIMER_WAITカラムには「どこからどこまで」が実行時間として計上されるのか気になったのでできる限り調べてまとめた、という内容になっています。
調査
実行環境
MySQL 8.0.39 : ローカル環境のDockerで起動
検証コード：Go
DBに接続して、10万レコード入ったテーブルから全件SELECTするだけのシンプルな処理です。
package main
import (
"database/sql"
"flag"
"fmt"
"log"
"time"
_ "github.com/go-sql-driver/mysql"
)
func main() {
// コマンドライン引数からlimitを受け取る
limit := flag.Int("limit", 0, "取得する最大レコード数")
flag.Parse()
// MySQLの接続情報
dsn := "root:xxx@tcp(127.0.0.1:3306)/test?tls=false" // wireshark使えるようにTLS無効化
db, err := sql.Open("mysql", dsn)
if err != nil {
log.Fatalf("DB接続エラー: %v", err)
}
defer db.Close()
// クエリの組み立て
query := "SELECT * FROM some_table_with_100000_records"
if *limit > 0 {
query = fmt.Sprintf("%s LIMIT %d", query, *limit)
}
// クエリ実行
rows, err := db.Query(query)
time.Sleep(5 * time.Second)
if err != nil {
log.Fatalf("クエリエラー: %v", err)
}
defer func() {
// time.Sleep(5 * time.Second)
rows.Close()
}()
// カラム数の取得
columns, err := rows.Columns()
if err != nil {
log.Fatalf("カラム取得エラー: %v", err)
}
// カラム数分のスライスを作成
values := make([]interface{}, len(columns))
valuePtrs := make([]interface{}, len(columns))
for i := range values {
valuePtrs[i] = &values[i]
}
// 結果を1行ずつ表示
// count := 0
for rows.Next() {
err := rows.Scan(valuePtrs...)
if err != nil {
log.Fatalf("データ読み取りエラー: %v", err)
}
// 結果の出力
for i, col := range columns {
fmt.Printf("%s: %v ", col, values[i])
}
fmt.Println()
// count++
// if count%10000 == 0 {
// fmt.Printf("sleep 5s\n")
// time.Sleep(5 * time.Second)
// }
}
if err = rows.Err(); err != nil {
log.Fatalf("クエリエラー: %v", err)
}
}
クエリープロファイリングによる調査
ドキュメントに従い、performance_schemaを用いて、特定のクエリの実行時間の内訳をステージ単位で確認しました。
↓のように、プログラム側でクエリ実行直後にsleepしてみます。
// クエリ実行後、すぐに5秒sleepしてみる
rows, err := db.Query(query)
time.Sleep(5 * time.Second)
ドキュメントの手順6を実行し、ステージ単位でのクエリ実行時間の内訳を取得します。
SELECT *, TRUNCATE(TIMER_WAIT/1000000000000,6) AS Duration FROM performance_schema.events_stages_history_long WHERE NESTING_EVENT_ID = 146 AND THREAD_ID = 501 order by event_id;
以下の結果となり、stage/sql/executingに7.2424秒と、大半を費やしている結果となりました。
+-----------+----------+--------------+--------------------------------+----------------------------------+------------------+------------------+---------------+----------------+----------------+------------------+--------------------+----------+
| THREAD_ID | EVENT_ID | END_EVENT_ID | EVENT_NAME | SOURCE | TIMER_START | TIMER_END | TIMER_WAIT | WORK_COMPLETED | WORK_ESTIMATED | NESTING_EVENT_ID | NESTING_EVENT_TYPE | Duration |
+-----------+----------+--------------+--------------------------------+----------------------------------+------------------+------------------+---------------+----------------+----------------+------------------+--------------------+----------+
| 501 | 147 | 158 | stage/sql/starting | init_net_server_extension.cc:123 | 1578465828678000 | 1578465912009000 | 83331000 | NULL | NULL | 146 | STATEMENT | 0.0000 |
| 501 | 159 | 160 | stage/sql/checking permissions | sql_authorization.cc:2267 | 1578465912009000 | 1578465930585000 | 18576000 | NULL | NULL | 146 | STATEMENT | 0.0000 |
| 501 | 161 | 163 | stage/sql/Opening tables | sql_base.cc:6190 | 1578465930585000 | 1578465957326000 | 26741000 | NULL | NULL | 146 | STATEMENT | 0.0000 |
| 501 | 164 | 164 | stage/sql/init | sql_select.cc:787 | 1578465957326000 | 1578465959123000 | 1797000 | NULL | NULL | 146 | STATEMENT | 0.0000 |
| 501 | 165 | 168 | stage/sql/System lock | lock.cc:331 | 1578465959123000 | 1578465967623000 | 8500000 | NULL | NULL | 146 | STATEMENT | 0.0000 |
| 501 | 169 | 169 | stage/sql/optimizing | sql_optimizer.cc:418 | 1578465967623000 | 1578465969658000 | 2035000 | NULL | NULL | 146 | STATEMENT | 0.0000 |
| 501 | 170 | 170 | stage/sql/statistics | sql_optimizer.cc:764 | 1578465969658000 | 1578465979168000 | 9510000 | NULL | NULL | 146 | STATEMENT | 0.0000 |
| 501 | 171 | 172 | stage/sql/preparing | sql_optimizer.cc:848 | 1578465979168000 | 1578465993937000 | 14769000 | NULL | NULL | 146 | STATEMENT | 0.0000 |
| 501 | 173 | 10478 | stage/sql/executing | sql_union.cc:1669 | 1578465993937000 | 1585708394087000 | 7242400150000 | NULL | NULL | 146 | STATEMENT | 7.2424 |
| 501 | 10479 | 10480 | stage/sql/end | sql_select.cc:820 | 1585708394087000 | 1585708403490000 | 9403000 | NULL | NULL | 146 | STATEMENT | 0.0000 |
| 501 | 10481 | 10482 | stage/sql/query end | sql_parse.cc:6850 | 1585708403490000 | 1585708410095000 | 6605000 | NULL | NULL | 146 | STATEMENT | 0.0000 |
| 501 | 10483 | 10485 | stage/sql/closing tables | sql_parse.cc:6932 | 1585708410095000 | 1585708419334000 | 9239000 | NULL | NULL | 146 | STATEMENT | 0.0000 |
| 501 | 10486 | 10489 | stage/sql/freeing items | sql_parse.cc:7504 | 1585708419334000 | 1585708459276000 | 39942000 | NULL | NULL | 146 | STATEMENT | 0.0000 |
| 501 | 10490 | 10493 | stage/sql/logging slow query | log.cc:1783 | 1585708459276000 | 1585708502632000 | 43356000 | NULL | NULL | 146 | STATEMENT | 0.0000 |
| 501 | 10494 | 10495 | stage/sql/cleaning up | sql_parse.cc:3764 | 1585708502632000 | 1585708503395000 | 763000 | NULL | NULL | 146 | STATEMENT | 0.0000 |
+-----------+----------+--------------+--------------------------------+----------------------------------+------------------+------------------+---------------+----------------+----------------+------------------+--------------------+----------+
15 rows in set (0.01 sec)
一方で、データ件数が数千レコードの場合は、全く同じコードでsleepしても、sleepがMySQL側の実行時間に計上されないケースもありました。
SELECT THREAD_ID, EVENT_ID, TRUNCATE(TIMER_WAIT/1000000000000,6) as Duration, SQL_TEXT FROM performance_schema.events_statements_history_long WHERE SQL_TEXT like '%data_locks%' and SQL_TEXT not like '%Duration%';
↓は↑のクエリの実行結果。data_locksテーブルに10万レコード入っている状態で、limit句で少しずつ取得件数を増やした場合に、MySQL側で計上されるDurationの変化を確認した。この結果では、3000件あたりからMySQLの実行時間にコード側のsleep時間が計上される結果となった。
+-----------+----------+----------+-------------------------------------------------------------------------------------------+
| THREAD_ID | EVENT_ID | Duration | SQL_TEXT |
+-----------+----------+----------+-------------------------------------------------------------------------------------------+
| 742 | 146 | 0.0317 | select dl.* from performance_schema.`data_locks` dl limit 100 |
| 885 | 146 | 0.0867 | select dl.* from performance_schema.`data_locks` dl limit 1000 |
| 1143 | 146 | 0.1290 | select dl.* from performance_schema.`data_locks` dl limit 2500 |
| 1319 | 146 | 0.1314 | select dl.* from performance_schema.`data_locks` dl limit 3000 |
| 1323 | 146 | 5.7374 | select dl.* from performance_schema.`data_locks` dl limit 3000 |
| 1168 | 146 | 5.0838 | select dl.* from performance_schema.`data_locks` dl limit 3750 |
| 981 | 146 | 5.1839 | select dl.* from performance_schema.`data_locks` dl limit 5000 |
show processlistで観測
コードでのsleepがMySQLの実行時間に計上されるケースにおいて、show full processlistの実行結果がどうなっているかを確認しました。
下図の通り「Sending to client」というStateになっています。show full processlistを連打してもずっとStateに変化がなかったことから、stage/sql/executingというステージで5秒以上費やした時に、内部的には「Sending to client」していたと推察できます。
Wiresharkでパケットキャプチャ
取得したレコード数次第で、クライアント側のコード実行（sleep）の時間がMySQL側の実行時間（TIMER_WAIT）に計上されるケースとそうでないケースに分かれるため、ネットワークレベルで何か違いないかをWiresharkで確認しました。
ざっくりとは以下の3ステップになっていそうでした。
- 「Request Query」で、クライアントからMySQLにパケット送信
rows.Close()したタイミングで「Request Quit」がクライアントからMySQLに送信されていそうな挙動でした。 - 「Response TABULAR Response」で、MySQLからクライアントにパケット送信
- 「Request Quit」で、クライアントからMySQLにパケット送信
2. コードレベルだと、rows.Close()のタイミングでこれが送られている可能性が高そうだった
また、プログラム側でsleepしている間は新規パケットがキャプチャされることも一時的になくなり、sleepが終わった直後に下図赤枠の「TCP Window Update」をクライアントからMySQL側へ送信していることがわかりました。
調べたところ、これは「クライアントの受信バッファに余裕ができたので、MySQLはもっとデータを送信していいよ」という意図のパケットらしいです。
以上を踏まえると、「クライアント側がバッファリングできる最大データ量に達した場合、[TCP Window Update]をクライアントからMySQL側に送るまで、MySQL側では「Sending to Client」のステータスで待ち続ける」という挙動だと推測しました。
試しに、ウィンドウサイズを以下のコマンドで約50倍にして、同じコードを実行してみました。
sudo sysctl -w net.inet.tcp.recvspace=5310720
sudo sysctl -w net.inet.tcp.sendspace=5310720
結果は以下のように、5秒間のsleepに影響を受けることなく、180ミリ秒程度で実行完了していることを確認しました。
+-----------+----------+----------+---------------------------------------------------------+
| THREAD_ID | EVENT_ID | Duration | SQL_TEXT |
+-----------+----------+----------+---------------------------------------------------------+
| 94 | 1 | 0.1874 | SELECT * FROM performance_schema.data_locks LIMIT 50000 |
クライアント側のウィンドウサイズを大きくしたことで、プログラム側のsleepに影響を受ける前にEOFパケットをMySQLが送信できたため、このような変化が生じたと考えています。
最後のレコードセット（「Request Quit」の1つ前のパケット）には、EOFパケットが含まれていることも確認できました。
Frame 1271: 3255 bytes on wire (26040 bits), 3255 bytes captured (26040 bits) on interface lo0, id 0
Section number: 1
Interface id: 0 (lo0)
Encapsulation type: NULL/Loopback (15)
...
MySQL Protocol - response EOF
Packet Length: 5
Packet Number: 98
Response Code: EOF Packet (0xfe)
EOF marker: 254
Warnings: 0
Server Status: 0x0022
所感
以上を踏まえて、冒頭のまとめに記載した結論へといたりました。調べる前は「DBレイヤの実行時間なんだから、クライアント側の挙動は関係ないだろう」と思い込んでいたのですが、そうではないケースもあると知れて良かったです。
参考記事
https://labs.gree.jp/blog/2014/11/11487/
https://docs.oracle.com/cd/E17952_01/mysql-8.0-en/general-thread-states.html#:~:text=
https://tombo2.hatenablog.com/entry/2018/12/10/075442