Elastic MapReduceを使って、FluentdでS3上に格納した、Ltsv形式のNginxのアクセスログを解析してみたお話。 #S3

今回何故、Elastic MapReduce + S3 + Fluentd + nginxを調査したのか

Mysqlとか、analyticsとか、そのほかで色々データは取っていってるのですが、
更に細かく解析するためには、ログレベルでの解析も必要になってくると思い調査し始めたのがきっかけです。
調べてみると、Redshift、Big Query、TreasureDataなど色々あるんですね、

でも今回は、Facebookで流れてきた記事に目がとまったので、まずはとElastic MapReduceの調査をしてみました。

構成としては、Elastic MapReduce + S3 + Fluentd + nginxでやってみます。

Nginxで書きだしたltsv形式のログが、fluentdでS3に転送されています

AWS上で準備（Elastic MapReduce Job Flows作成）

新しいJOBを作成する

JOBの名前とか、versionとか、スクリプト選択

今回は、hiveを選択します。

hive sessionを選択

Start an Interactive Hive Session

マスターinstance、core instanceの台数、グレードなどなどを選択

今回は確認なので、smallで、１台１台にしました。

キーペア、ログ出力先などなど

sshでアクセスする際のキーペアとか
ログ出力先を設定します。

Bootstarap action

Proceed with no Bootstrap Actions

最後は確認して作成

これで、AWS側での準備は完了です！！

では、実戦してみます。

準備や、今回の調査時の環境について

ログを格納しているS3ですが、
<バケット名>/nginx.access/XXXXXXX/2013/09/09/ログファイル
この様に、なっています。
XXXXには、サーバHOST名、年、月、日という感じです。

そしてログファイルは、Ltsvで出力されたファイルです。
ltsv形式のデータの一行抜粋するとこんな感じ（データの一部を当てで変更しています）
2013-09-13T00:00:03+09:00 nginx.access/XXXXXXX {"host":"999.99.99.999","forwardedfor":"999.99.99.999, 182.161.76.45","method":"GET","path":"/","status":"200","size":"20444","referer":"-","ua":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_7_5) AppleWebKit/537.36 (KHTML, like Gecko)

とりあえず、ログイン

$ ssh -i ~/KEY hadoop@ec2-99-999-999-999.ap-northeast-1.compute.amazonaws.com

EC2で使い慣れた、「ec2_user」では無く、「hadoop」ユーザを使用します。

hiveを起動

$ hive
hive>

Fluentdで回収したログのデータを格納するhive上のtableをつくります。

CREATE EXTERNAL TABLE IF NOT EXISTS fluentLog (dt string, tag string, json string)
PARTITIONED BY ( PT STRING )
ROW FORMAT DELIMITED FIELDS TERMINATED BY '\t' LINES TERMINATED BY '\n';
OK

dt string, tag string, json stringがポイントです

ltsvをfluentdで回収すると

日付<タブ>タグ＜タブ＞JSONデータの形式ですので、それを格納するように定義してます。

次はデータをごにょごにょ

hive>  ALTER TABLE fluentLog ADD PARTITION ( pt='2013-09-09' ) LOCATION 's3://<バケット名>/nginx.access/XXXXXXX/2013/09/09'; 
OK
Time taken: 5.252 seconds

hive>  ALTER TABLE fluentLog ADD PARTITION ( pt='2013-09-10' ) LOCATION 's3://<バケット名>/nginx.access/XXXXXXX/2013/09/10'; 
OK
Time taken: 5.252 seconds

日付単位でpartition作成してます。

解析後のデータ格納用tableを作る！

今回は、簡単にステータスコードが何回登場したかという簡単な事をやってみます。

hive> CREATE EXTERNAL TABLE IF NOT EXISTS archiveLog (status int, cnt int)
ROW FORMAT DELIMITED FIELDS TERMINATED BY '\t' LINES TERMINATED BY '\n'
LOCATION 's3://<バケット名>/archives/${DATE}';
OK
Time taken: 0.197 seconds

その為、status(int)とcnt(int）の二つを用意しました。
s3://<バケット名>/archives/${DATE}'は用意する必要ありません、処理実行後に作成されます。
解析後のデータがここに格納されるようです。

ついに処理を実行する時が.....

INSERT OVERWRITE TABLE  archiveLog
SELECT
  status, count(*) as cnt
FROM
  fluentLog LATERAL VIEW
    json_tuple(fluentLog.json,  'ua', 'status') j
      AS ua,status
WHERE pt >='2013-09-09'
GROUP BY status;

2013-09-09と、2013-09-10以下のファイルすべてを対象に、statusとその回数を取得
そして、先ほど作成したtableに格納するという処理を行っています。

見た感じ、SQLライクに掛けるというのが、hiveのいいところですね

上のコマンドを実行したら
Total MapReduce jobs = 1 Launching Job 1 out of 1 Number of reduce tasks not specified. Estimated from input data size: 1 In order to change the average load for a reducer (in bytes): ...

どんどん文字が出力されます

2013-09-14 06:24:57,961 Stage-1 map = 0%,  reduce = 0%
2013-09-14 06:25:16,420 Stage-1 map = 1%,  reduce = 0%, Cumulative CPU 10.2 sec
2013-09-14 06:25:17,433 Stage-1 map = 1%,  reduce = 0%, Cumulative CPU 10.2 sec
2013-09-14 06:25:18,451 Stage-1 map = 1%,  reduce = 0%, Cumulative CPU 10.2 sec
2013-09-14 06:25:19,487 Stage-1 map = 1%,  reduce = 0%, Cumulative CPU 10.68 sec
2013-09-14 06:25:20,514 Stage-1 map = 1%,  reduce = 0%, Cumulative CPU 10.68 sec
2013-09-14 06:25:21,529 Stage-1 map = 1%,  reduce = 0%, Cumulative CPU 10.68 sec
2013-09-14 06:25:22,540 Stage-1 map = 2%,  reduce = 0%, Cumulative CPU 11.08 sec

をmap処理が少しずつ始まったようだ

2013-09-14 06:26:10,262 Stage-1 map = 8%,  reduce = 0%, Cumulative CPU 20.52 sec
2013-09-14 06:26:11,273 Stage-1 map = 8%,  reduce = 2%, Cumulative CPU 21.18 sec
2013-09-14 06:26:12,284 Stage-1 map = 8%,  reduce = 2%, Cumulative CPU 21.18 sec
2013-09-14 06:26:13,301 Stage-1 map = 8%,  reduce = 2%, Cumulative CPU 21.18 sec
2013-09-14 06:26:14,315 Stage-1 map = 9%,  reduce = 2%, Cumulative CPU 21.91 sec

Reduceも始まったようだ

マスター１台、ノード１台で確認しているので速度はあれみたい

2013-09-14 06:38:31,627 Stage-1 map = 100%,  reduce = 100%, Cumulative CPU 208.05 sec
2013-09-14 06:38:32,636 Stage-1 map = 100%,  reduce = 100%, Cumulative CPU 208.05 sec
MapReduce Total cumulative CPU time: 3 minutes 28 seconds 50 msec

少なめのデータで確認したとはいえ、３分半かかりました。むしろ３分半でおわりました？

どんな結果か確認してみます

解析後のデータは、s3://<バケット名>/archives/${DATE}'以下に格納されます。
恐る恐るひらいてみると

200     116080
302     2148
400     44
404     40
500     5

なるほど、なるほど

後始末

DROP TABLE fluentLog;
DROP TABLE archiveLog;

いらないので消しました。

簡単な調査を終えて

思った事

nginxのログ解析とかは、ltsv形式で出力、Fluentdで回収してS3へ転送する
という設定ができていれば、容易に解析処理を行えるなと思いました！
hiveのクエリを勉強する必要はありますが。

アプリケーションログに関しては、まだまだ調査できていないのでなんとも言えませんので
コレに関しては、調査してからまたまとめてみよう。
そしてやっていけそうなら、本番でつかう

最後に一言

おもしろい