Apache DrillでnginxのLTSVログにドリドリとSQLを投げつける

2015/09/02

Apache DrillでnginxのLTSVログにドリドリとSQLを投げつける

さてみなさんApache Drillでドリドリしてますか? えっ、ドリドリしてない? あ、そういうぼくもドリドリしてないですよ〜。そんな感じですが、今日は「Apache Drillつかってみた」的な話です。

具体的には、Apache DrillでnginxのログをSQLで集計してエンドポイント別の平均値とか最大最小を出したりとか、レスポンスボディのサイズの平均を出したりとかそういう感じの使い方です。

はじめてのApache Drill

なんでApache Drillを使ってみたかというと、昨日、社内で「Apache Drillを分散モードで使うのにZooKeeper必須なの…」みたいな謎のぼやき(?)が流れまして、あーApache Drillとかあったな〜とその存在を思い出したという感じなんです。

ちょうどその時、Webサービスのパフォーマンス分析をやるというタスクが手元にありまして。具体的には、Webアプリの応答速度をエンドポイント別に集計して「このエンドポイントが遅いから改善してこ」みたいな事をサービス担当エンジニアに言い渡す必要があったんですが、それの集計どうやってやるかな〜と思ってた矢先にローカルファイルのJSONにSQL投げれるApache Drill!!!! ということに気がついたのでさっそくやってみることにしました。もうちょっと詳しいApache Drillの話についてはクラスメソッドさんのブログを読めばいいかとおもいます。

で、とりあえずウチの会社は基本的にサービスのnginxのログをLTSVで取っていて、upstream_response_timeも取っています。データ自体はちゃんとあるから、あとはサーバからaccess.logを持って来てLTSVログをJSONに変換すれば手元のMacでドリドリしてSELECT uri, avg(upstream_response_time) AS avgtime FROM 〜 GROUP BY uri ORDER BY avgtime DESC LIMIT 30とやることで遅いAPIの上位30件がわかるなーと思いついてしまったわけです。

ということで、紆余曲折(記事の後半にあります)を経て、こんなRubyスクリプトを書いてnginxのLTSVログをJSONに変換しました。

require 'ltsv'
require 'json'

STDIN.each do |line|
  record = LTSV.parse(line)
  result = {}
  record[0].each { |key, value|
    case key
    when :request_time, :upstream_response_time
      result[key] = Float(value) rescue 0.0
    when :status, :size
      result[key] = Integer(value) rescue 0
    when :uri
      result[key] = value.gsub(/\?.*/, "")
    else
      result[key] = value
    end
  }
  puts JSON.generate(result)
end

普段Ruby書かないので今見てみると do-end と { } が混ざってるけどまぁそのへんはご愛敬ということで、とりあえずこれを convert.rb という名前で保存して実行してJSONを保存します。処理内容は読めば分かりますが、ざっくり言うとLTSVの時点では全部の値は文字列なので、適切な下ごしらえもやるという感じです。

値が小数値なrequest_timeとupstream_response_timeをFloatに変換
値が整数値なstatusとsizeをIntegerに変換
GETなリクエストはQueryStringがuriにくっついているので?以下を削除
他のフィールドはそのままポン

さて実行するぞ!

$ cat access.log | ruby convert.rb > access_log.json

中身を確認してみます…。

{"host":"***.***.***.***","user":"-","time":"2015-09-01T03:26:18+09:00","method":"GET","uri":"/api/********","protocol":"HTTP/1.1","status":200,"size":2023,"request_time":0.107,"upstream_response_time":0.107,"upstream_addr":"127.0.0.1:9001","referer":"-","user_agent":"*********/*** CFNetwork/711.5.6 Darwin/14.0.0","geo":"MX"}

ヨッシャーJSONデキター! ってことでApache Drillを起動してクエリを投げつけます。

0: jdbc:drill:zk=local> SELECT uri, COUNT(*) AS req_count, SUM(upstream_response_time) AS total_time, AVG(upstream_response_time) AS avg_time, MIN(upstream_response_time) AS min_time, MAX(upstream_response_time) AS max_time FROM dfs.`/Users/kawazoel/json/access_log.json` GROUP BY uri ORDER BY avg_time DESC LIMIT 10;
+----------------------------+------------+------------+----------+-----------+-----------+
|            uri             | req_count  | total_time | avg_time | min_time  | max_time  |
+----------------------------+------------+------------+----------+-----------+-----------+
| /api/shop/********         | 3          | 3.983      | 1.327    | 1.165     | 1.546     |
| /api/market/********       | 79         | 60.129     | 0.761    | 0.656     | 1.131     |
| /api/********/recommend    | 133        | 88.382     | 0.664    | 0.147     | 1.816     |
| /api/shop/********         | 356        | 223.876    | 0.628    | 0.009     | 1.955     |
| /api/********/list         | 453        | 256.193    | 0.565    | 0.463     | 0.675     |
| /api/********/equip        | 1527       | 792.481    | 0.518    | 0.011     | 1.262     |
| /api/extension/********    | 1241       | 580.872    | 0.468    | 0.009     | 1.011     |
| /api/********              | 26         | 10.560     | 0.406    | 0.003     | 0.503     |
| /api/practice/********     | 11255      | 4427.391   | 0.393    | 0.009     | 0.641     |
| /api/********/list         | 974        | 363.238    | 0.373    | 0.03      | 0.817     |
+----------------------------+------------+------------+----------+-----------+-----------+
10 rows selected (2.657 seconds)

で、できたー! レスポンスタイムの平均順で並べていますが、これを見る限り9位のやつが呼び出し頻度的に支配的に時間を食っていますので、まずはこれからかなぁ…みたいな感じで眺めるわけですね。

Apache Drill、当然ビッグなデータを相手にすることが多いとは思いますが、こういったRedshiftとかTDとかHadoopとかBigQueryに投げるまでもないようなスモールデータにカジュアルにクエリを投げるのに結構便利ですね。例えばステータスコード別にGROUP BYするとか、エンドポイント別にsizeの平均を出してみてレスポンスボディがデカすぎるやつを探すとか、そういう感じで使うことができそうです。

さて本日の記事はここまでです。以下は、余興としてここまでたどり着くまでに踏みまくった罠の数々を参考までにお楽しみください。

Javaのバージョンが古いとApache Drillがうまく動かない(っぽい)

Drillをインストールして最初に手元の適当なJSONでまずは試してみるかーと実行してみたんですが、Error: PARSE ERROR: java.net.URISyntaxException: Relative path in absolute URI: Thumbs.db:encryptableとか出ていきなり動かない。

fujiwaraさんにも試してもらったところ問題無く動くとのことでどうやら自分の日頃の行いがわるいようだということが分かったので、Javaのバージョンを比較してみたところ、ぼくのMacに入ってるJavaは1.8.0u5とかいうめっちゃ古いバージョンだったので最新のu60にアップデートしてみたところちゃんと動きました。完全に日頃の行いが悪い。

数値を文字列で渡すと集計関数が死ぬ

当たり前といえば当たり前ですね。最初にLTSVからJSONへの変換を試したときはLTSVログをltsviewを使ってJSONに変換したんです。

$ cat access.log | ltsview -j --no-colors > access_log.json

という感じで-jオプションを付ければJSONを吐いてくれるので便利ですね!

ということで1文字もスクリプトを書くこと無くJSONファイルが出来上がりました。ここで、GROUP BY uriしてリクエストの件数をCOUNT(*)するだけだったら問題無かったのですが、一番時間使ってるAPIを調べるぞーとSUM(upstream_response_time)したらApache Drillがエラー吐いて死にました。ドリドリ失敗。

このときのメッセージがjava.lang.RuntimeException: java.sql.SQLException: SYSTEM ERROR: CompileException: Line 112, Column 177: Unknown variable or type "logger"と書いてあって完全に意味不明なのですが、とりあえずSQLがエラーになるってことは集計中に型がダメだったんだろうということで、JSONで値が文字列じゃなくて数値になるように変換して回避することにしました。

とりあえずこのときはuriとupstream_response_timeがあれば良かったので、jqを使って文字列に| tonumberのフィルタを通してやればOKです。upstream_response_timeは静的ファイルみたいにnginxが直接返してるやつは値が文字列の"-"になるので、jqでif使って"-"のときは0をフィールドに入れるようにしてやりましょう。

jq -c 'if .upstream_response_time == "-" then { uri: .uri, upstream_response_time: 0 } else { uri: .uri, upstream_response_time: .upstream_response_time | tonumber } end' access_log.json

ここまで長くなると職人技っぽいですが、これでSUMが動くようになりました。しかし…次の項に続く。

JSONの同じキーで0と0.5が混ざっているとDrillが死ぬ

JSONデータの30行目でError: DATA_READ ERROR: Error parsing JSON - You tried to write a BigInt type when you are using a ValueWriter of type NullableFloat8WriterImpl.というエラーが出たんです。

えーと30行目はどうなってるんだ…とless -N(行番号オプション付き)で見ていくと

  29 {"uri":"/api/*****/convert","upstream_response_time":0.108}
  30 {"uri":"/api/ios/******.json","upstream_response_time":0}
  31 {"uri":"/api/*****_info","upstream_response_time":0.083}

(一部伏せ字にしています)

なるほど! ぴったり0なのね! 30行目のやつはnginxで直接配信してるのでupstream_respose_timeを0にしたやつでした。このほかにも3.000秒ぴったりなやつもjqで数値に変換すると3になっています。

で、これはどういうエラーかというと、Apache DrillはSchema lessだけどオンデマンドに値を見ていって型を決めているので、upstream_response_timeはFloatだな! って判断したようなのですが、そこに0とか3みたいな整数値が来るとそれはBigIntとして解釈してしまうので、FloatなカラムのテーブルにBigIntを入れようとしてエラーになっているようです。

うぐぐぐぐぐ…それはちょっと困るんですけど…。

まぁそれが仕様ならならそれはそれでいいけど、それだとjqは今回使い物になりそうにないので、素直にIntegerとFloatが言語仕様上ちゃんと別れているRubyでLTSVのaccess.logを処理してJSONを出力しましょうかね〜となった、というのがRubyで変換スクリプトを書いた理由でした。

ちなみにPerlだとIntとFloatを区別することが難しい(IVとかNVとかあるけど普通それ意識して書かない)ので、こんな感じで0は0.0じゃなくて0になっちゃいます。これだとDrillの求めるJSONにはマッチしてないので今回は出番がない感じですね。

$ perl -MJSON::XS -e 'print encode_json { zero => 0.0, half => 0.5}';
{"half":0.5,"zero":0}

ということで、LTSVのデータを加工してApache Drillに食わせるときは何かとRubyが便利、という知見でした。

2015/09/02