技術関係

Sequel Pro(Ace)のクエリ実行時間は意図しない数値が得られる場合があるのでクエリチューニングでは気を付けよう

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

コメント

タイトルとURLをコピーしました