KibanaのDev Toolsの一つにProfilerという機能があります。
このProfilerを利用すると検索や集計のクエリを分析し、どんなクエリが発行されたのか、どのくらいの処理時間がかかっているのか等を簡単に知ることが出来ます。
内部的にはElasticsearchのProfiler APIを利用しているみたいですが、このAPIのレスポンス内容から分析するのは中々大変なのでKibanaを利用した方がお手軽です。
ネットワークのオーバーヘッドやキューの待ち時間等、Profilerで計測出来ない値も色々あるのですが、それでも手探りであれこれ試すよりはProfilerを利用した方が色々と便利かなと思います。
（※参考：Profileの制限）
Profilerは Dev Tools > Search Profiler から開くことが出来ます。
環境
Elasticsearch 6.5.4
Kibana 6.5.4
サンプルデータ
以下のように、日付、URL、ステータスコード、レスポンス時間を持っている簡素なサーバーログっぽいものを用意しました。
{
"date": "2019-01-14T00:01:00",
"url": "/test/huga/",
"status_code": 200,
"response_time": 591
},
{
"date": "2019-01-14T00:02:00",
"url": "/test/hoge/",
"status_code": 404,
"response_time": 632
},
{
"date": "2019-01-14T00:03:00",
"url": "/test/piyo/",
"status_code": 500,
"response_time": 1237
}
検索クエリの分析
Profilerの使い方は簡単で、分析したい検索クエリをそのまま書いて「Profile」ボタンを押すだけです。
結果はQuery Profileタブに表示されます。
検索対象のIndexを指定したい場合はIndex欄で指定してください。
（Typeを指定したい場合はType欄で指定できます。ただTypeはElastic Stack 7系以降で廃止予定ですので、使わなくても大丈夫な状態にしておいた方が良いかなと思います。）
試しに「test-access-log」から始まるIndexに対し、status_codeが200のドキュメントを検索するクエリを分析してみます。
実行すると、test-access-logとtest-access-log-2というIndexが検索対象となったことがわかりました。
test-access-logはShard数を1、test-access-log-2はShard数を3に設定しているため、各Shardに対して検索が実行されているということもわかります。
また、Cumulative Timeを見ることで、このクエリを処理するためにかかった各Shardの処理時間の合計値がわかります。
（※各Shardの処理は並列に実行されるため、Cumulative Timeは検索してからレスポンスを得るまでの実行時間とは異なる、という点に注意してください）
例えば同じ結果が返ってくるクエリを複数のパターンで書くことが出来る場合、この値を比べることでElasticsearch上の処理時間についての参考指標にすることが出来ます。
発行されたクエリの詳細を確認する
「>」を押すと詳細が展開され、実際にどのようなクエリが発行されていたのかを知ることが出来ます。
これを見ると、今回実行したクエリはApache LuceneのPointRangeQueryに変換されて発行されているようです。
status_code:[200 TO 200]となっているので、200～200で検索しているんだろうなというのがわかります。
実際に発行されたクエリの中身を確認できるのが結構便利で、例えばnowを利用して現在時刻を基準に検索を行った場合に、実際には何時で検索されたのかを知りたい場合にも役立ちます。
以下の例では現在時刻を基準にdateが昨日の12時から今日の12時のドキュメントを検索しようとしています。
クエリを書いている最中はnow-1d/d+12hで昨日の12時がうまく指定できているかどうかちょっと不安になりますが、Profilerを使うことでエポックミリ秒の1547348400000で検索出来ていることがわかります。
（例では2019/01/14に実行したので、1547348400000 -> 2019/01/13 12:00:00.000 になっています）
また、右側のTiming Breakdownには処理時間の内訳が表示されています。
ただ、ここの値を自分で調整するのは中々難しいのかなと思いますので、参考程度に見ておけば良さそうです。
| 項目 | 意味 |
|---|---|
| advance | イテレーターが次のドキュメントを取得する時間 |
| build_scorer | スコア計算用のオブジェクト生成にかかった時間 |
| create_weight | weightを保持するためのオブジェクト生成にかかった時間 |
| match | phraseクエリを使用した際にスコアリングに要した時間 |
| next_doc | イテレーターがマッチした次のドキュメントを取得する時間 |
| score | ドキュメントのスコアリングに要した時間 |
（※参考：Query ProfileのTiming Breakdownの項目の詳細）
集計クエリの分析
集計クエリの分析も検索と同様にクエリをそのまま書いて「Profile」ボタンを押すだけです。
結果はAggregation Profileタブに表示されます。
これを見ると、今回実行したクエリの内、status_code_aggsの方はLongTermsAggregatorクラスを利用して集計されているというようなことがわかります。
パフォーマンスチューニングを行う場合、内部的に利用されているクラスを元に色々と調整していくのは中々難しそうです。
ですので、各集計の処理時間を元に時間がかかっている集計を特定し、集計条件の見直しやIndexに持たせるFieldの調整等を行っていくのがよさそうです。
| 項目 | 意味 |
|---|---|
| build_aggregation | 収集したドキュメントを元にした集計処理にかかった時間 |
| collect | 条件にマッチするドキュメントの収集にかかった時間 |
| initialize | 集計開始前の初期化処理にかかった時間 |
| reduce | 現在利用されておらず常に0 |