slow logの時間は何を計測しているのか？

きっかけ

とあるMySQL インスタンスで1Gbのネットワーク帯域を使い切ってレスポンスタイムが悪化していたという話を聞いた。確かに遅いがlong_query_timeを小さくしてもslow_logは特に出ていなかったため、どのクエリが問題なのかを特定しづらかったらしい。

これを聞いたときはRedisとかインメモリのDBならまだしもMySQLがストレージより先に1GbのNICを使い切ることがあるのかーと驚いた。まあ、100GB以上のメモリも珍しくないので、ほとんどメモリから結果を返していれば1Gb/s以上返すことは難しくなさそうではある。

だが、long_query_timeを小さくしてもslow_logにクエリが出力されなかったという部分は気になった。具体的にlong_query_timeがどれくらいなのか、同時接続数はどれくらいでQPSはどれくらいだったのかなどの詳細を聞かなかったが、long_query_timeって何を計測した結果と比較してるんだ？ということで調査した

ドキュメント

long_query_timeはクエリの実行時間との比較でしょ！以上に何の時間か知らないので、調べてみる。普通にドキュメントを読み直してみる。

long_query_time (8.0 Reference Manual) の説明

If a query takes longer than this many seconds, the server increments the Slow_queries status variable. If the slow query log is enabled, the query is logged to the slow query log file. This value is measured in real time, not CPU time ... (略)

クエリ(の実行時間)にこの秒数より時間をかけたらSlow_queries変数を加算して、slow query logが有効ならログファイルに出力する
CPU時間ではなくて実時間

5.4.5 The Slow Query Log の説明も見てみる

The time to acquire the initial locks is not counted as execution time. mysqld writes a statement to the slow query log after it has been executed and after all locks have been released, so log order might differ from execution order.

最初のロックを取得するのにかかる時間は実行時間(execution time)に含まれない
mysqldは実行が終わって、すべてのロックを解放してからクエリ文(statement)をログに書くので、ログに書かれる順序は実行順序とは別

Slow Query Log Contentsの項目

- Query_time: duration
  - The statement execution time in seconds.

まあ、当初の理解以上の情報はなかった。

疑問

long_query_timeは何の時間なのか？

ざっくり以下のように実行手順を分解してどの部分なのかを考える

クエリをclientから受け取る
クエリのパース
ストレージから結果を取得する
結果をclientに返す

直感的に,(1)のクエリを受け取ってスレッドをディスパッチするあたりから計測を開始して、(4)のclientに結果を返す部分の前後になっているのではないかと予想。今回の現象を聞いた感じだと、(3)のあとか、(4)が非同期になっていて、それを呼び出すまでが計測の終了地点になっていそう。

実験

まずは簡単な方法でめどをつけてみる。 tcコマンドでネットワーク遅延を発生させて様子を見る。

前回組んだUbuntu 19.10 with Ryzen 3950x上での実験です。MySQL 8.0.19 with debug build.

long_query_time = 0

loに1sの遅延を発生させる(往復で2秒遅れる)

sudo tc qdisc add dev lo root netem delay 1000ms

mysql> select * from t where id < 2;
+------+
| id   |
+------+
|    1 |
|    1 |
+------+
2 rows in set (2.00 sec)

# Time: 2020-02-16T12:19:47.888202Z
# User@Host: root[root] @ localhost [127.0.0.1]  Id:     8
# Query_time: 0.001589  Lock_time: 0.000465 Rows_sent: 2  Rows_examined: 6
SET timestamp=1581779987;
select * from t where id < 2;

クライアントでは実行時間は2秒と表示されている, 一方slow_log側ではQuery_timeは0.001589.
(4)の実行結果をclientに返すまでではなく、上記の遅延を発生させた状況だとさきにslow_logがでて、client側で結果が出ることを確認できた。

code上の計測開始と終了

簡単な実験でクライアントへ結果を非同期に返すか、返す前にslow_logに書いていることがわかった。
だが、結局どこからどこまでを計測しているのだろうか？確かめるにはコードを追うしかなさそうなので、gdbでstep実行しつつ追ってみた。

dispatch_command以降の処理を順番に見ていく

sql_parse.cc: dispatch_command() (sql_parse.cc, 1469)

開始時刻(thd->start_utime)取得部分

dispatch_command() (sql_parse.cc, 1469)
- set_time() (sql_class.cc, 2815)
  - start_utime = utime_after_lock = my_micro_time(); (2816)

関数のコール順序をインデントで表現して書いています。
後続のカッコの (ファイル名, 行数) は呼び出し部分だったり、定義部分だったりします（僕自身がコードを読み直すときにわかり易いようにしているので、感覚で、ルールは曖昧です)

クエリの終了時刻(current_utime)取得部分, 書き込み部分

(sql_parse.cc, 2182) のlog_slow_statement()の中で現在時刻をとってstart_utimeと比較してその時間をクエリの実行時間としてslow_logに書き込み
- log_slow_statement() (log.cc, 1653)
  - log_slow_do() (log.cc, 1626)
    - slow_log_write() (log.cc 1287)
      - current_utime = my_micro_time() (log.cc, 1309)
      - query_utime = (current_utime - thd->start_utime); (log.cc, 1312, 取得部分)
      - log_slow() (log.cc, 1232)
        
        write_slow() (log.cc, 671)
        
        sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime) / 1000000.0); (log.cc, 703, 書き込む文字列を生成)
        
        (log.cc, 833, 書き込む部分)
        
        sql if (my_b_write(&log_file, pointer_cast<const uchar *>(sql_text), sql_text_len) || my_b_write(&log_file, pointer_cast<const uchar *>(";\n"), 2) || flush_io_cache(&log_file)) goto err;

結果の送信部分

(どうやって非同期処理しているのか？)

send_statement_status() (sql_class.cc, 2540)
- Protocol_classic::send_eof() (Protocol_classic.cc, 1320)
  - net_send_ok() (Protocol_classic.cc, 863)
    - net_flush() (net_serv.cc, 246)
      - net_write_packet() (net_serv.cc, 1168)
        
        net_write_raw_loop() (net_serv.cc, 865)
        
        vio_write() (viosocket.cc, 210)
        
        inline_mysql_socket_send() (mysql_socket.h, 698)
        
        send() (mysql_socket.h, 706) システムコールのsend()と思われる
        
        (ここからstep intoするとアセンブリに入ってしまう)

my_socket.h, 706行目のresult = send(mysql_socket.fd, buf, IF_WIN((int), ) n, flags);のflagsはどこで定義されているのかわかっていないが、gdb実行して見てみると値は64になっていることがわかった。

これは16進数だと0x40で、socket.hにMSG_DONTWAITとして定義されていたのでnon blocking IOになってるとわかった

参考

0x40がMSG_DONTWAITに定義されている部分
- https://github.com/torvalds/linux/blob/master/include/linux/socket.h#L279
send() systemcallのマニュアル
- https://linuxjm.osdn.jp/html/LDP_man-pages/man2/send.2.html

lock待ちの時間が考慮されていない件について

ここまでの調査でlong_query_timeの条件と比較される時間が何なのかわかりました！！と終わるつもりでした。

しかし、ここまでの情報だとクエリーがロック待ちになった場合にその待ち時間が無視されてslow logに出力されない現象の説明ができないことに気付きました。さすがに上記で発見したlog.ccの671行目(write_slow())や同833行目(my_b_write())が間違っているとは思えないので、log.ccの1312行目のquery_utime = (current_utime - thd->start_utime); のthd->start_utimeが上書きされているのではないかと予想しました。が、そうではなく、slow_logに出力するかを決定するのにthd->start_utimeが使われていないことがわかりました。

slow_logに出力するかどうかはlog.cc, 1607のbool log_this_queryとこのあとに続くsuppress_loggingの条件に当てはまらないか、で決まっています. 特に(thd->server_status & SERVER_QUERY_WAS_SLOW)、ここを実行中に見ると、thd->server_statusが2082になってSERVER_QUERY_WAS_SLOWは2048に定義されているので、bit積が!=0になる。

このthd->server_statusはどこで設定されているか探してみると、dispatch_command以降の処理で次のように書かれていることがわかった.

dispatch_command (sql_parse.cc, 2156(thd->update_slow_query_status()))
update_slow_query_status() (sql_class.cc, 2841)

void THD::update_slow_query_status() {
  if (my_micro_time() > utime_after_lock + variables.long_query_time)
    server_status |= SERVER_QUERY_WAS_SLOW;
}

これで現在時刻よりも(utime_after_lockの時刻+long_query_timeの時間)が小さければslow_logに書かれることがわかった。

utime_after_lockに時刻を代入している箇所はいくつか見つかるが、順に読んでいけば、時刻を取得しているのはsql_class.ccのset_time_after_lock()内の2836行目utime_after_lock = my_micro_time();とわかる

結論 (全体の流れ)

以下の順序でslow_logへの書き込みがされていることがわかった

dispatch_command()
パース, mysql_parse() (sql_parse.cc, 1777)
実行, mysql_execute_command() (sql_parse.cc, 5288)
slow_logに出力するかを確定(utime_after_lockをもとに判定)
結果の送信(非同期), THD::send_statement_status() (sql_class.cc, 2540)のm_protocol->send_eof(server_status, da->last_statement_cond_count());
slow_logへの書き込み

最初の疑問の回答をまとめると

大雑把に言うと、クエリを受けとってdispach_command()内でいろいろな初期化をしているあたりから、clientに結果セットを返すためにsend(2)を非同期(non blocking IO) オプション付きで呼んだ後までの時間を"実行時間”としてslow_logに書き込んでいる。
ただし、このタイミングでslow_logに出力するかはクエリの実行に必要なロックの取得が終わった時点のutime_after_lockの時刻とlong_query_timeの設定値を使って、結果セットをclientに返す前で決定している。
(詳細なコード箇所は上記の説明を参照のこと)

となります。(合ってますか？)

さらにnonblocking IOがkernelでどうスケジュールされるのかを知りたいけど、今回はここまで。

tom__bo’s Blog

MySQL!! MySQL!! @tom__bo

MySQLのslow_logは何を計測して出力されるのか