こんにちは、ミツバチワークス stoneです。
今日は、DECOLOGで行われている、Apacheのログ解析について、
ご紹介してみようかと思います。
現在、DECOLOGでは、リバースプロキシが8台あって、
その8台の1日のApacheのログは、全部で、200Gバイト以上になっています。
これを、13台のHadoopのスレーブノードで解析を行っています。
全体の流れとしては、
1) リバースプロキシからHDFSにログを転送
2) 解析用のサーバーで、HDFSにログの転送が終わるのを監視
3) ログの転送が終わったら、Hadoopを起動、解析
4) Hadoopの解析結果をデータベースに保存
以下では、各々のステップを個別に見て行くことにしますね。
1. リバースプロキシからHDFSにログを転送
当初、Hadoopのプロセスが立ち上がっていないと、HDFSにはアクセスできない、
と思い込んでいたので、解析用のサーバーが、
1) 各リバースプロキシからのログをscpで収集
2) 収集したログをHDFSへ
というステップを踏んでいたのですが、
このステップだけで、昼過ぎまでかかるようになったため、
現在では、リバースプロキシから直接HDFSへ展開するように変更しました。
Apacheのログは、cron.dailyで起動されるlogroateでローテーションがかかるので、
そのcron.dailyの最後にHDFSへの展開するスクリプトが起動するようになっています。
/etc/cron.daily/zz_log_to_hdfs.sh
#! /bin/sh HOST=`hostname -s` TODAY=`date +%Y%m%d` HADOOP='/path/to/hadoop/bin/hadoop dfs' HDFS_BASE='hdfs://hadoop-master:9000/accesslog' LOG_FILE="$HDFS_BASE/$TODAY/$HOST" SIGNUP_FILE="$HDFS_BASE/signup/$HOST" LOCAL_SRC="/path/to/log/access_log.1" $HADOOP -copyFromLocal $LOCAL_SRC $LOG_FILE $HADOOP -chmod 777 $LOG_FILE $HADOOP -touchz $SIGNUP_FILE $HADOOP -chmod 777 $SIGNUP_FILE
2. 解析用サーバーで、HDFSにログの転送が終わるのを監視
各リバースプロキシから直接HDFSへ展開することで、時間は大幅に短縮できたのですが、
1点、問題がありました。
それは、
リバースプロキシからのログの転送がいつ終わったのか、わからない
という問題です。
そのため、ちょっと、工夫をして、HDFS上にsignupディレクトリというモノを作りました。
各リバースプロキシは、ログの転送が終わったタイミングで、
このsignupディレクトリにホスト名のファイルをtouchします。
前出のスクリプトの下から２行目でそのtouchをしています。
$HADOOP -touchz $SIGNUP_FILE解析用のサーバーは、適当な時間に起動した後、このsignupディレクトリを監視して、
すべてのサーバーが出そろった段階で、次のHadoopでの解析のステップに進みます。
(signupディレクトリは、転送が始まる前に事前に空にしています。)
3. Hadoopでの解析
3.1 Key-Valueのマッピング
ご存知のように、Hadoopでは、mapのステップで、
あるデータを「key => value」の形にマッピングして、
reduceのステップで、同一のkeyの値を取りまとめてくれます。
DECOLOGでは、以下のような切り口でログ解析をしています
・１時間ごとのHit数、PV数
・ページグループ毎のPV数
・携帯キャリアごとのHit数
具体的なキーは、こんな感じです。
YYMMDD-hourly_hit-HH (時間ごとのヒット数)
YYMMDD-hourly_page-HH (時間ごとのPV数)
YYMMDD-page_group-PAGE (ページグループごとのHit数)
YYMMDD-page_group_pv-PAGE (ページグループごとのPV数)
YYMMDD-user_agent-CARRIER (携帯キャリアごとのHit数)
アクセスされたURLから、
・ページビューなのか画像なのか？
・ページビューの場合、HTTPステータスが200か？
・どのページグループに属するURLか？
を判別しています。
なので、例えば、記事ページへのアクセスがあった場合、
aaa.bbb.ccc.ddd - - [13/Oct/2010:11:05:09 +0900] "GET /en/00000/00000 HTTP/1.1" 200 999 "-" "DoCoMo/2.0 D905i(c100;TB;W24H17)" "-"という感じのログになるのですが、これをmapperに通すと、
20101013-hourly_hit-11 1 20101013-hourly_page-11 1 20101013-page_group-Entry 1 20101013-page_group_pv-Entry 1 20101013-user_agent-docomo 1という結果が出力されることになります。
3.2 mapper/reducerの記述
実際のmapperとreducerは、Javaではなく、Perlで記述しています。
Perlで記述したスクリプトをhadoop-streamingを利用して、
mapper/reducerとして、稼働させています。
hadoop-streamingは、データの入出力に標準入力／標準出力を使用するため、
動作の検証は、実際のログデータをmapperに標準入力から流し込んだときに、
想定通りの出力が得られるか？で、行うことが出来ます。
(reducerは、そのmapperの出力を流しこめばOKです。)
4.解析結果をDBに保存
Hadoopの解析結果は、「part-0001」みたいなファイル名でHDFS上に出力されているのですが、
これをうまい具合に取り出す方法がよくわかっていなくて、
現状、以下のようにして、ローカルに取り出しています。
$HADOOP dfs -cat "$OUTPUT_DIR/part-*" | grep $YESTERDAY > $TMP_FILE
保存するデータベースは、以下のようなテーブル定義になってます。
(データベースは、MySQLです)
| カラム名 | データタイプ |
|---|---|
| log_date | char(8) |
| section | enum("hourly_hit", "houly_page" ...) |
| section_key | varchar(255) |
| log_count | int unsigned |
解析結果は、上記のmapperの出力に準じた形になっているので、
20101013-hourly_hit-11 999と出力されていて、これを、
log_date: 20101013と保存しています。
section: houry_hit
section_key: 11
log_count: 999
ごく初期の段階では、webalizerを使って、サーバー１台で解析をしていたですが、
解析が夜までかかるようになったため、Hadoopによる解析に切り替えました。
当時(2009年4月ごろ)は、サーバーの負荷対策で、ほぼ毎日のようにサーバーの増設や、役割の変更、
それに伴うプログラムの修正を行っていました。
その際、その対策の根拠となるのが、前日のZABBIXのグラフとアクセス解析の結果でした。
なので、アクセス解析が夜までかかると、負荷対策の立案にとても困った記憶があります。
参考までに、切り替えを行ったタイミングでは、１日あたり、だいたい4700万PV/2億6000万Hitでした。
(ログのサイズは、データが残っていませんでした。)
現在は、１日あたり、だいたい2億PV/15億Hitなのですが、お昼までには解析が終了しています。
蛇足ですが。。。。。。。。。。。。。
ウチでは、このシステムを「HAL」と読んでます。
「Hadoop for Apache Log」の頭文字をとって「HAL」としていますが、
本当は、HAL9000からパクって、「Hadoop for なんちゃら」は、
後からこじつけました。
が、他の年下のエンジニアからは、「何スか？HAL9000って？」と言われ、
ジェネレーションギャップを感じました。
(え？知らない方が多数派ですかね、これって？)
では、また次回に♪