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 1.1.2
- Sequel Ace 4.0.5
コメント