Groongaを使っていると、時々他の検索と比べて応答が遅い検索があることがあります。 そういった時は、ボトルネックを改善するために、どのクエリーの応答がどのくらい遅いのかを測定したくなります。

Groongaには、groonga-query-logという便利なツールがあります。 このgroonga-query-logには、クエリーログを解析して、どのクエリーの応答がどのくらい遅いのかを出力してくれるスクリプトが含まれています。 したがって、このツールを使えば、クエリーログを取得するだけでボトルネックの測定ができます。

ちなみに、groonga-query-logには、今回紹介する遅いクエリーを特定するスクリプトだけではなく、先日このブログで紹介されていた、クラッシュ時のログを解析するスクリプトや クエリーログを手軽に再生するスクリプト、回帰テストを実行するスクリプト等、様々なスクリプトがありますので、興味が湧いたら他の機能についても使ってみて下さい。

遅いクエリーを特定するスクリプトの使い方は以下の通りです。

事前にRubyをインストールします。Rubyをインストールしたら以下のコマンドでgroonga-query-logをインストールします。

% gem install groonga-query-log

その後は、ボトルネックを測定するためにクエリーログを取得します。 クエリーログは以下のように--query-log-pathを指定してGroongaを起動することで取得できます。 例えば、サーバーモードでGroongaを起動して、クエリーログを取得する場合は、以下のように実行します。

% groonga -s --protocol http --query-log-path ~/benchmark/query.log ~/testdb/db

クエリーログを取得したら、取得したクエリーログを解析します。 クエリーログの解析は以下のコマンドで実行できます。

% groonga-query-log-analyze ~/benchmark/query.log

上記のコマンドを実行すると、標準出力に以下のような結果が出力されます。標準出力ではなく、ファイルに結果を出力したい場合は、--outputオプションで保存先を指定することができます。 情報が多いですが、１つずつ解説していきます。

Summary:
  Threshold:
    slow response     : 0.2
    slow operation    : 0.1
  # of responses      : 20
  # of slow responses : 1
  responses/sec       : 0.1351168407649807
  start time          : 2018-06-26T13:26:01.958965+09:00
  last time           : 2018-06-26T13:28:29.979003+09:00
  period(sec)         : 148.020038707
  slow response ratio : 5.000%
  total response time : 0.9940333010000002
  Slow Operations:

Slow Queries:
 1) [2018-06-26T13:26:42.318254+09:00-2018-06-26T13:26:42.853803+09:00 (0.53554963)](0): load --table Site
  name: <load>
  parameters:
    <table>: <Site>
  1) 0.53550895:       load(     9)

 2) [2018-06-26T13:27:20.700551+09:00-2018-06-26T13:27:20.838092+09:00 (0.13754151)](0): column_create --table Terms --name blog_title --flags COLUMN_INDEX|WITH_POSITION --type Site --source title
  name: <column_create>
  parameters:
    <table>: <Terms>
    <name>: <blog_title>
    <flags>: <COLUMN_INDEX|WITH_POSITION>
    <type>: <Site>
    <source>: <title>

 3) [2018-06-26T13:26:30.927046+09:00-2018-06-26T13:26:31.062374+09:00 (0.13532895)](0): column_create --table Site --name title --type ShortText
  name: <column_create>
  parameters:
    <table>: <Site>
    <name>: <title>
    <type>: <ShortText>

 4) [2018-06-26T13:26:13.510750+09:00-2018-06-26T13:26:13.599616+09:00 (0.08886603)](0): table_create --name Site --flags TABLE_HASH_KEY --key_type ShortText
  name: <table_create>
  parameters:
    <name>: <Site>
    <flags>: <TABLE_HASH_KEY>
    <key_type>: <ShortText>

 5) [2018-06-26T13:27:12.821842+09:00-2018-06-26T13:27:12.909721+09:00 (0.08787940)](0): table_create --name Terms --flags TABLE_PAT_KEY --key_type ShortText --default_tokenizer TokenBigram --normalizer NormalizerAuto
  name: <table_create>
  parameters:
    <name>: <Terms>
    <flags>: <TABLE_PAT_KEY>
    <key_type>: <ShortText>
    <default_tokenizer>: <TokenBigram>
    <normalizer>: <NormalizerAuto>

 6) [2018-06-26T13:28:10.403229+09:00-2018-06-26T13:28:10.407243+09:00 (0.00401451)](0): select --table Site --offset 7 --limit 3
  name: <select>
  parameters:
    <table>: <Site>
    <offset>: <7>
    <limit>: <3>
  1) 0.00010690:     select(     9)
  2) 0.00387348:     output(     2)

 7) [2018-06-26T13:26:56.509382+09:00-2018-06-26T13:26:56.509947+09:00 (0.00056562)](0): select --table Site --query _id:1
  name: <select>
  parameters:
    <table>: <Site>
    <query>: <_id:1>
  1) 0.00037286:     filter(     1) query: _id:1
  2) 0.00001580:     select(     1)
  3) 0.00010979:     output(     1)

 8) [2018-06-26T13:27:45.307960+09:00-2018-06-26T13:27:45.308409+09:00 (0.00044912)](0): select --table Site --output_columns _key,title,_score --query title:@test
  name: <select>
  parameters:
    <table>: <Site>
    <output_columns>: <_key,title,_score>
    <query>: <title:@test>
  1) 0.00029620:     filter(     9) query: title:@test
  2) 0.00001499:     select(     9)
  3) 0.00008281:     output(     9) _key,title,_score

 9) [2018-06-26T13:28:24.234937+09:00-2018-06-26T13:28:24.235383+09:00 (0.00044695)](0): select --table Site --query title:@test --output_columns _id,_score,title --sort_keys -_score
  name: <select>
  parameters:
    <table>: <Site>
    <query>: <title:@test>
    <output_columns>: <_id,_score,title>
    <sort_keys>: <-_score>
  1) 0.00027925:     filter(     9) query: title:@test
  2) 0.00001296:     select(     9)
  3) 0.00004034:       sort(     9)
  4) 0.00005845:     output(     9) _id,_score,title

10) [2018-06-26T13:28:29.978590+09:00-2018-06-26T13:28:29.979003+09:00 (0.00041371)](0): select --table Site --query title:@test --output_columns _id,_score,title --sort_keys -_score,_id
  name: <select>
  parameters:
    <table>: <Site>
    <query>: <title:@test>
    <output_columns>: <_id,_score,title>
    <sort_keys>: <-_score,_id>
  1) 0.00023013:     filter(     9) query: title:@test
  2) 0.00000878:     select(     9)
  3) 0.00004086:       sort(     9)
  4) 0.00005566:     output(     9) _id,_score,title

Summary

まず、Summaryの内容について解説します。 Summaryには、以下の項目があります。

• Threshold：実行に何秒かかったら、遅いクエリー、遅いオペレーションとするかのしきい値を表示しています。

  • slow responseに表示されている値より時間のかかったクエリーを遅いクエリーと判定します。

    • 単位は秒で、デフォルト値は、0.2秒ですが、groonga-query-log-analyze実行時に--slow-response-thresholdオプションを使って、しきい値を変更できます。

  • slow operationに表示されている値より時間のかかったオペレーションを、遅いオペレーションと判定します。

    • 単位は秒で、デフォルト値は、0.1秒ですが、groonga-query-log-analyze実行時に--slow-operation-thresholdオプションを使って、しきい値を変更できます。

  • 例えば、slow responseのしきい値を1.0秒、slow operationのしきい値を1.0秒にしたい場合は、以下のようにgroonga-query-log-analyzeを実行します。

% groonga-query-log-analyze --slow-response-threshold=1.0 --slow-operation-threshold=1.0 query.log

• of responses：解析に使用したクエリーログに含まれる全てのクエリーの数を表します。

  • 例えば、of responsesが10だったとすると、query.logというクエリーログには、全部で10個のクエリーが記録されている事になります。

• of slow responses：slow responseに設定したしきい値を超えたクエリーがいくつあったかを表します。

  • 例えば、of slow responsesが2だったとすると、slow responseに指定したしきい値を超えたクエリーが2つあった事になります。

• responses/sec：平均応答時間を表します。解析したクエリーが平均してどのくらいの応答時間なのかを表示します。単位は秒です。

• start time、last time：クエリーの実行開始時間と終了時間を表します。

• period(sec)：クエリーを流していた時間を表します。start timeとend timeの差を表します。

• slow response ratio：全体の中で遅いクエリーが占める割合を表します。例えば、slow response ratioの値が5.000%だった場合は、実行したクエリーのうち5%が遅いクエリーということになります。

• total response time：クエリーの総実行時間を表します。単位は秒です。例えば、total response timeが0.9940333010000002だった場合は、全てのクエリーを実行するのに、約0.99秒かかったことになります。

Slow Operations

Slow Operationsは、具体的に遅いオペレーションを表示します。 例えば以下のような表示になります。

  Slow Operations:
    [56.021284]( 3.77%) [168](70.59%)    filter: title == "test"

この例の場合は、filter条件のtitle == "test"が遅いオペレーションと出ています。

• 一番左の[56.021284]は、このオペレーションを実行した総実行時間を表します。単位は秒です。したがって、この場合は、filter == "test"というオペレーションを全部で約56秒実行したことになります。

• 左から二番目の( 3.77%)は、他のオペレーションも含めた全実行時間のうちこのオペレーションが占める割合を表しています。したがって、この例の場合は、title == "test"というオペレーションが、全体のうち3.77%を占める事を表しています。

• 左から3番目の[168]はこのオペレーションを実行した回数を表しています。この例の場合は、[168]となっているので、title == "test"というオペレーションが168回実行されています。

• 左から4番目の(70.59%)は、他のオペレーションも含めた全実行回数のうちこのオペレーションが占める割合を表しています。この例の場合は、(70.59%)となっているので、全体のオペレーションのうち約70%は、title == testを実行していることになります。

Slow Queries

Slow Queriesは、具体的に遅いクエリーを遅い順に表示します。表示件数は、--n-entriesまたは-nオプションで変更でき、デフォルトでは10件表示されます。 例えば、5件表示させたい場合は、以下のように実行します。

% groonga-query-log-analyze --n-entries=5 ~/benchmark/query.log

or

% groonga-query-log-analyze -n 5 ~/benchmark/query.log

クエリーに複数の条件が含まれている場合は、それぞれの条件にどのくらい時間がかかったかも表示されます。 例えば以下のような表示の場合は、filter、select、outputの実行にそれぞれ0.00037286秒、0.00001580秒、0.00010979秒かかったことになります。

クエリー全体の実行時間は、最初の行に出力されます。以下の表示の場合は、7) [2018-06-26T13:26:56.509382+09:00-2018-06-26T13:26:56.509947+09:00 (0.00056562)](0): select --table Site --query _id:1の(0.00056562)の部分がクエリー全体の実行時間を表しています。

 7) [2018-06-26T13:26:56.509382+09:00-2018-06-26T13:26:56.509947+09:00 (0.00056562)](0): select --table Site --query _id:1
  name: <select>
  parameters:
    <table>: <Site>
    <query>: <_id:1>
  1) 0.00037286:     filter(     1) query: _id:1
  2) 0.00001580:     select(     1)
  3) 0.00010979:     output(     1)

まとめ

groonga-query-log-analyzeを使うことで、このようにして遅いクエリーや、オペレーションを特定することができます。 どのくらい遅いのかの他に、全体に占める割合も出力することができ、また、どの条件に時間がかかっているかも出力できるので、チューニングのポイントを探すのに役に立ちます。

例えば、とても遅いクエリーだが、全体に占める割合が少ないクエリーをチューニングするよりも、そこそこ遅いクエリーで全体に占める割合が多いクエリーをチューニングしたほうが、性能向上に寄与します。 どのクエリー、オペレーションが遅いかだけの情報だと、上記のような判断はできませんが、groonga-query-log-analyzeを使った解析なら、上記のような判断もでき、より効果的なチューニングが実施できます。

ツイートする

フォローする