運用に便利なgroonga-query-logの使い方

はじめに

groongaを囲む夕べで発表した内容に加筆・修正した内容を記述します。
発表はこちらの内容などを参考にしましたので、あわせてご覧ください。

groonga-query-logとは

執筆時(2014年12月現在)の最新版ですと1.1.2になります。

現在、以下のコマンドが用意されています。

1. groonga-query-log-analyze
2. groonga-query-log-detect-memory-leak
3. groonga-query-log-extract
4. groonga-query-log-format-regression-test-logs
5. groonga-query-log-replay
6. groonga-query-log-verify-server
7. groonga-query-log-run-regression-test
8. groonga-query-log-show-running-queries

ここではよく使う1,4,7,8について触れたいと思います。

インストール

gem install groonga-query-log
これだけで上記すべてが使えるようになります。

groonga-query-log-analyze

特定のクエリログファイルから一定時間以上かかっているクエリやボトルネックが簡単に探せます。
あわせてスロークエリの割合などのサマリ情報が出ます。

使い方

• レスポンスに一定時間以上かかっているクエリを検出する場合

groonga-query-log-analyze--slow-response-threshold=[閾値] [クエリログのパス]


実行例が以下の通りです。

groonga-query-log-analyze --slow-response-threshold=0.01 query.log --color

• クエリのボトルネックを検出する場合

groonga-query-log-analyze--slow-operation-threshold=[閾値] [クエリログのパス]


こちらも実行例を示します。

groonga-query-log-analyze --slow-operation-threshold=0.01 query.log --color

いずれも一定以上時間がかかっている箇所に色がついて表示されていることが分かります。
Linux環境だとcolorオプションをつけなくても問題がある部分に色がついて表示されるのですが、Mac環境ですと--colorオプションを付けないといけないかもしれないです。

groonga-query-log-run-regression-test

回帰テストを簡単に実施できます。

使い方

1. 以下を準備します

   • クエリログ
   • 新旧のバージョンのGroonga
   • 回帰テストをしたいGroongaのダンプ（DDLとデータ）

2. 以下の名前のディレクトリを作ります。

   • data
   • 
indexes
   • 

query-logs
   • 

schema 今回はすべて~/demo/というディレクトリ作ることにします。

3. 2.で作ったディレクトリに1.で用意した物を入れます。

   • data ← データ
   • 
indexes ← INDEX（省略可能）
   • 

query-logs ← クエリログ（複数ファイル可）
   • 

schema　←　DDL

4. 以下のコマンドを実行します。
   groonga-query-log-run-regression-test
 --old-groonga=[古いGroongaのパス]
 --new-groonga=[新しいGroongaのパス]

   ※~/demo/配下で実行してください

5. 結果を確認します。
   ~/demo/配下にresultというディレクトリが新しく出来ています。
   この中にファイルが吐き出されているのですが、何か差分を検知した場合は

   • 差分を検出したクエリ
   • そのクエリの実行結果 の２種が出力されます。

出力の例はこんな感じです。

command: /d/select?table=test&match_columns=pr_short&query=TEST
response1: [[[0], [["_id", "UInt32"], ["_key", "ShortText"], ["name", "ShortText"], ["text", "ShortText"]]]]
response2: [[[1], [["_id", "UInt32"], ["_key", "ShortText"], ["name", "ShortText"], ["text", "ShortText"]], [50, "test50", "TEST TEST TEST"]]]

• command ：実行したクエリ
• response1：旧Groongaの結果
• response2：新Groongaの結果

新Groongaでは１件多く結果が検出されているということがこちらの例から分かると思います。
回帰テストの他にDDLのチューニングにも使える（というか私は使っている）のですが、それはここでは記述しません。

groonga-query-log-format-regression-test-logs

上記で説明したgroonga-query-log-run-regression-testで検出した差分を抽出することが出来ます。
例で検出した差分は１件のみでしたが、差分を大量に検知したときなどにとても便利です。

使い方

groonga-query-log-format-regression-test-logs [差分ファイル]

上記のgroonga-query-log-run-regression-testの例では、~/demo/result/配下にデータが吐き出されました。
ですので、
groonga-query-log-format-regression-test-logs ~/demo/results/query.log
と実行すれば、差分がターミナルに出力されます。

groonga-query-log-show-running-queries

指定した時間に実行中だったクエリを抽出することが出来ます。
これを用いると、膨大なクエリログの中からエラーを吐いた・CRASHしたなど問題のあるクエリを簡単に抽出することが出来ます。

使い方

groonga-query-log-show-running-queries --base-time '時間' [クエリログのパス]


実行例が以下になります。

$ groonga-query-log-show-running-queries --base-time '2014-12-18 16:01:10.210486' query.log 
2014-12-18 16:01:10.210486:/d/select?table=test&match_columns=text&query=TEST

この例では１件のみですが、該当した分だけHITします。
例が簡単すぎて、このツールの良さが伝わらないのですが、時間をまたいで実行されていたクエリ（指定した時間にfilterやdrilldownが実行中だったとか)も抽出できるのでとても重宝すると思います。

おわりに

groonga-query-logからよく使う機能の使い方を紹介しました。
いずれも日々の運用で便利な機能だと思いますので、是非使ってみてください。