【elasticsearch】Profile APIでクエリ解析

Profile API

elasticsearch2.2が先月リリースされ(リリースノート)Profile APIという機能が追加されました。
この機能はRDBMSの実行計画のようにクエリ実行の流れがわかる情報をAPIで提供してくれます。
スローなクエリの解析に効果がありそうだと個人的にも期待している機能です。

どうやって使う?

Profile APIの使い方はすごく簡単で、クエリ実行時にprofileをtrueにセットしてあげると

{
   "profile": true,
   "query": {
      "match": {
         "pref": "茨城"
      }
   }
}

こちらのようにクエリの実行情報を実行結果とともに返してくれます。

 {
   "id": "[GjqU-RMDQbiR3zU58ITvgA][population][2]",
   "searches": [
      {
         "query": [
            {
               "query_type": "BooleanQuery",
               "lucene": "pref:茨 pref:城",
               "time": "0.5796450000ms",
               "breakdown": {
                  "score": 6486,
                  "create_weight": 155444,
                  "next_doc": 7623,
                  "match": 0,
                  "build_scorer": 143408,
                  "advance": 0
               },
               "children": [
                  {
                     "query_type": "TermQuery",
                     "lucene": "pref:茨",
                     "time": "0.2137220000ms",
                     "breakdown": {
                        "score": 3054,
                        "create_weight": 92406,
                        "next_doc": 2069,
                        "match": 0,
                        "build_scorer": 116193,
                        "advance": 0
                     }
                  },
                  {
                     "query_type": "TermQuery",
                     "lucene": "pref:城",
                     "time": "0.05296200000ms",
                     "breakdown": {
                        "score": 621,
                        "create_weight": 39380,
                        "next_doc": 798,
                        "match": 0,
                        "build_scorer": 12163,
                        "advance": 0
                     }
                  }
               ]
            }
         ],
         "rewrite_time": 6780,
         "collector": [
            {
               "name": "SimpleTopScoreDocCollector",
               "reason": "search_top_hits",
               "time": "0.01149200000ms"
            }
         ]
      }
}

どんな情報が取れる?

Profile APIで取得できる情報の種類はこちらです

query Lucene内でどのようにクエリが実行されているか
collector LuceneのCollector(検索結果の収集やスコアリング、ソートなどを行うクラス)がどのように実行されているか
rewrite Luceneによって実行クエリがどのようにリライトされたか

そして提供される情報はどんどん増えていく予定です(suggestやhighlightなど)

出力される情報はLucene内での出来事についてなので、Luceneについて詳しくないと
細かいところまで理解することは難しそうです(自分も苦戦しています)

ただ、たとえLuceneがわからなくてもクエリのどこが遅くなってる原因なのか何となく分かる情報になっています。たとえばqueryセクションをみてますと

"query": [
   {
      "query_type": "BooleanQuery",
      "lucene": "pref:茨 pref:城",
      "time": "0.5796450000ms",
      "breakdown": {
         "score": 6486,
         "create_weight": 155444,
         "next_doc": 7623,
         "match": 0,
         "build_scorer": 143408,
         "advance": 0
      },
      "children": [
      {
         "query_type": "TermQuery",
         "lucene": "pref:茨",
         "time": "0.2137220000ms",
         "breakdown": {
            "score": 3054,
            "create_weight": 92406,
            "next_doc": 2069,
            "match": 0,
            "build_scorer": 116193,
            "advance": 0
         }
      },
      {
         "query_type": "TermQuery",
         "lucene": "pref:城",
         "time": "0.05296200000ms",
         "breakdown": {
            "score": 621,
            "create_weight": 39380,
            "next_doc": 798,
            "match": 0,
            "build_scorer": 12163,
            "advance": 0
         }
      }
    ]
  }
]

こちらはアナライズされている県名のフィールドに「茨城」で検索した場合のProfileですが
LuceneのBooleanQuery全体で0.579ms、その子どもとなるTermQueryでそれぞれ0.213ms、
0.052msかかっていることがわかります。

ちなみに各項目は

query_type Lucene内で実行されるクラス名
lucene Luceneクエリ
time 実行時間(ms)
breakdown 時間がどのように使われたかの詳細

とのことです。

おわりに

スローなクエリにはProfile API!とだけ覚えて帰っていただければと思います。