ElasticsearchのQueryが遅い時のトラブルシューティング

これはFJCT 2018 Advent Calendar2日目の記事です。
1日目は@ichikkのニフクラの高品質クラウドへの取り組みです。

概要

こんちは二フクラPaaSを担当している@hunter9xです。
現在チームのログ基盤の運用と開発に携わっています。
そこでよく起きる問題はKibanaでの検索が期待より遅いことです。
特にサーバのスペックアップしても効果があまり感じられないこともありました。

検索の遅延について

検索の速度に対して色々な考え方があると思います。

1. 検索を実行してからその結果が帰ってくるまでの時間
2. 検索を始めてから自分がほしい情報を手に入れる時間

1番は2番の中に含められていると思います。また、私は2番の時間から検索速度だと考えています。
Elasticsearchの検索が遅い理由は次の3つに分けることができるかと思います。

1. ハードウェアスペックが相応しくない
2. Elasticsearchの設定チューニングがもっと必要
3. Query自体が適切でない

今回は3番の簡単なトラブルシューティング方法を一つ紹介しようと思います。
やり方は2つのステップがあります

1. Slow Queryを取得し、その中から問題のQueryを分析する
2. 特定できたQueryを再設計する

Slow Queryの有効設定

ElasticsearchではSlow Queryのロギングはデフォルトで無効になっているため、まず有効にする
必要があります。
Elasticsearchでは2種類のSlowログがあります。

• index slow log : ドキュメントの追加やindexing
• search slow log : slow query 関係

設定方法はドキュメントを参照してください
私の場合は threshold を 0ms にしておきました。そうすると全てのQueryを拾うことができると考えたからです。
curl からこういうコマンドで設定できるかと思います。

curl -XPUT 'localhost:9200/testindex-slowlogs/_settings' -H 'Content-Type: application/json' -d '{
"index.search.slowlog.threshold.query.warn": "0ms",
"index.search.slowlog.threshold.query.info": "0ms",
"index.search.slowlog.threshold.query.debug": "0ms",
"index.search.slowlog.threshold.query.trace": "0ms",
"index.search.slowlog.threshold.fetch.warn": "0ms",
"index.search.slowlog.threshold.fetch.info": "0ms",
"index.search.slowlog.threshold.fetch.debug": "0ms",
"index.search.slowlog.threshold.fetch.trace": "0ms"
}'

設定した状態で遅い検索を実行するとこういうログがでてくると思います。
※ バージョンで違いがある可能性があります。

[2017-09-10T12:35:53,352][WARN ][index.search.slowlog.query] [GOgO9TD] [testindex-slowlogs][1] took[197.6micros], took_millis[0], types[], stats[], search_type[QUERY_THEN_FETCH], total_shards[5], source[{"query":{"match":{"name":{"query":"Nariko","operator":"OR","prefix_length":0,"max_expansions":50,"fuzzy_transpositions":true,"lenient":false,"zero_terms_query":"NONE","boost":1.0}}},"sort":[{"price":{"order":"desc"}}]}],
[2017-09-10T12:35:53,352][WARN ][index.search.slowlog.query] [GOgO9TD] [testindex-slowlogs][3] took[279.3micros], took_millis[0], types[], stats[], search_type[QUERY_THEN_FETCH], total_shards[5], source[{"query":{"match":{"name":{"query":"Nariko","operator":"OR","prefix_length":0,"max_expansions":50,"fuzzy_transpositions":true,"lenient":false,"zero_terms_query":"NONE","boost":1.0}}},"sort":[{"price":{"order":"desc"}}]}],
[2017-09-10T12:35:53,352][WARN ][index.search.slowlog.query] [GOgO9TD] [testindex-slowlogs][2] took[1ms], took_millis[1], types[], stats[], search_type[QUERY_THEN_FETCH], total_shards[5], source[{"query":{"match":{"name":{"query":"Nariko","operator":"OR","prefix_length":0,"max_expansions":50,"fuzzy_transpositions":true,"lenient":false,"zero_terms_query":"NONE","boost":1.0}}},"sort":[{"price":{"order":"desc"}}]}],
[2017-09-10T12:35:53,352][WARN ][index.search.slowlog.query] [GOgO9TD] [testindex-slowlogs][4] took[370.8micros], took_millis[0], types[], stats[], search_type[QUERY_THEN_FETCH], total_shards[5], source[{"query":{"match":{"name":{"query":"Nariko","operator":"OR","prefix_length":0,"max_expansions":50,"fuzzy_transpositions":true,"lenient":false,"zero_terms_query":"NONE","boost":1.0}}},"sort":[{"price":{"order":"desc"}}]}],
[2017-09-10T12:35:53,355][WARN ][index.search.slowlog.fetch] [GOgO9TD] [testindex-slowlogs][0] took[150.6micros], took_millis[0], types[], stats[], search_type[QUERY_THEN_FETCH], total_shards[5], source[{"query":{"match":{"name":{"query":"Nariko","operator":"OR","prefix_length":0,"max_expansions":50,"fuzzy_transpositions":true,"lenient":false,"zero_terms_query":"NONE","boost":1.0}}},"sort":[{"price":{"order":"desc"}}]}]

このログでは took というパラメータはQuery実行時間でそのあとにQueryの詳細が書いてあります。

SlowQueryの分析

特定できたSlow Queryを改善するにはもっとその詳細を確認する必要があります。
この時に役に立つのはProfiling APIです。
API仕様はこちらをご参照ください。
Query実行のパラメータやRewite時間、Collectorsの情報が非常に細かく取得することができます。
APIを使用する場合は ?human=true をリクエストに追加することでレスポンスがより見やすくなります。
ただ、私はUIで確認したかったので、xpackの無料枠にあるProfilingツールを使うことにしました。

SlowQueryの改善

詳細なSlowQueryを手に入れたところで今度はQueryの改善ですが、
その前にElasticsearchのQuery実行の基本的な仕組みについて理解することが必要だと思います。
以下の2フェーズに渡ってQueryは実行されます。

• Query フェーズ

1. Coordinator nodeが受け取ったQueryからIndex -> Shard -> Node の順でNodeを特定
2. それらのNodeに対してQueryを投げる
3. ShardがQueryを実行し、top 10 (デフォルト)のdocumentのリストをCoordinatorに返す

• Fetch フェーズ

1. Coordinatorはもらったdocumentリストからshardに対し中身をfetchリクエストを投げる
2. fetchされた結果をClientに返す

Query実行する本体は shardであるため一つのSlow Queryのログはそのshard数に相当すると思います。デフォルトでは5です。
ここで考えられる簡単な改善策はフィルターをかけることと検索対象のindexを予め絞ることです
フィルターについてはこちらの公式チュートリアルがとても勉強になりました。
また、検索対象のindexでは私は絞れるところなら徹底的に指定すようにしています。
例えば 複数のプロジェクトのログはlogstashのoutputからindexを分けるとともに、kibanaのindex pattern設定でさらにリージョンごとに作成することで
検索する時に画面からindex範囲を簡単に変更できるようにしました。

3日目は@ConHumiの他社調査の名目で自分のブログを移築した話です！ぜひチェックしてみてください～