MacのDBクライアントツール、Sequel Proを使っていた時の話。
ここで言ってるクエリ実行時間はこれ。左下にでるメッセージ。ここだとあるクエリで2.5msかかっています。
ある日、複雑なクエリをSequel Proのクエリの実行時間を参考に色々チューニングしているとあることに気付いた。
あれ、Sequel Proのクエリ実行時間の数値おかしくない・・・？バグ・・・？
Sequel Pro のクエリ実行時間なんかがおかしい
あるクエリの実行時間が 「0.8s」 と表示された。
ふむふむ。こんなもんかな？でもなんか速すぎる気がするな。
念のためCLIでも同じクエリを実行してみる「13s」
あれ・・・？
別のDBクライアントツール「DBeaver」でも試してみる「13s」
他と比べるとSequel Proが出す実行時間だけ明らかにおかしい。速すぎる・・・。
Sequel Pro のクエリ実行時間の罠
調べてみたらSequel Proのissueにcloseされてるもののそれっぽいのがありました。
Reported query execution time is wrong #264 / sequelpro
Sequel Proの時間よりCLIの時間の方が遅く表示される。これっぽい。
Just came across this issue today while trying to debug server performance. Sequel pro says query takes 82.4ms while command-line mysql says 12.91 sec. Perhaps Sequel pro should report both timings.
更にissueにわかりやすい図が記載されてたの紹介
https://github.com/sequelpro/sequelpro/issues/264#issuecomment-207645163
そして原因はこれ。
“how long did the client wait until getting something”, but I would still like to know “how long did the database server spin its wheels on this query”
https://github.com/sequelpro/sequelpro/issues/264#issuecomment-354057462
「クライアントが何かを取得するまでどれくらい待ったか」
をクエリ実行時間として表示しているのが現在のSequel Pro
でも本当に知りたいのは
「データベースサーバーがこのクエリに対して処理に時間を要した時間」では？
ということらしい。
この違いが「クエリとクエリによって取得できるデータ」によっては想定外の実行時間とも取れる数値を返す。
ややこしいけどバグではないってこと。SequelProが返す実行時間をどのタイミングで算出してるかというだけの話。
対策
悲しいですが現状だとSequel Proを使わないことです。そしてSequel Proは更新が止まっており修正が当たることも絶望的。
後継と言われてるSequel Aceでも動作を確認しましたが、記事を書いている現在ではSequel Proと同じ挙動でした。
クエリチューニングなど実行時間の結果を気にする場合は違うクライアントツール等を使ったほうが良いでしょう。
Sequel Pro(Ace)でクエリ処理時間を正確に測る
記事にコメント頂いた方法を載せておきます。
こちらの「実際のクエリを実行」に計測したいクエリを書けば正確に処理時間が測れそうです。
# 実行開始時間を取得
SET @start_time = NOW();
# 実際のクエリを実行
SELECT * FROM your_table;
# 実行完了時間を取得
SET @end_time = NOW();
# 開始時間と完了時間および実行時間を小数点第２位まで表示
SELECT
@start_time AS start_time,
@end_time AS end_time,
TIMESTAMPDIFF(SECOND, @start_time, @end_time) AS execution_time_seconds;
環境
- Sequel Pro 1.1.2
- Sequel Ace 4.0.5
コメント
同じ問題にぶつかりまして、
SequelAceでどうしてもやる場合において
厳密ではないかもしれませんが、ある程度の実行時間を計測する手段としては
下記の方法でやるのもありかもしれません。参考までに。
“`
— 実行開始時間を取得
SET @start_time = NOW();
— 実際のクエリを実行
SELECT * FROM your_table;
— 実行完了時間を取得
SET @end_time = NOW();
— 開始時間と完了時間および実行時間を秒単位で表示
SELECT
@start_time AS start_time,
@end_time AS end_time,
TIMESTAMPDIFF(SECOND, @start_time, @end_time) AS execution_time_seconds;
“`
なるほど、SequelAceでやろうと頑張るならそういう方法も出来ますね。
自分はこの現象が原因で計測系はちょっとSequelAce使うの離れてしまったんですが、参考までに上記のクエリを記事に追記させてもらってもいいでしょうか？
もちろんです、参考になっていただけたら幸いです。
ちなみに、ミリ秒の方が結果の確認で都合がよかったので、ミリ秒バージョンです↓
“`
— 実行開始時間を取得
SET @start_time = NOW(6);
— 実際のクエリを実行
SELECT * FROM your_table;
— 実行完了時間を取得
SET @end_time = NOW(6);
— 開始時間と完了時間および実行時間を秒単位で表示
SELECT
@start_time AS start_time,
@end_time AS end_time,
ROUND(TIMESTAMPDIFF(MICROSECOND, @start_time, @end_time) / 1000000, 2) AS execution_time_seconds;
“`
先ほど投稿した内容に不備がありました。失礼しました。
「ミリ秒単位」→「秒単位での小数点第２位まで表示」でした。
ありがとうございます。
コメントアウトの記法をちょっとだけ変えたうえで記事に追記させてもらいました。