CloudFrontのアクセスログを集計・分析したい！

CloudFrontのアクセスログを集計・分析したい！

#ビッグデータ
#Hadoop
#Amazon CloudFront
#Amazon EMR
#AWS
都元ダイスケ

都元ダイスケ

facebook logohatena logotwitter logo
Clock Icon2014.01.09

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

よく訓練されたアップル信者、都元です。CloudFrontにはDistributionの設定により、アクセスログを出力する機能があります。アクセスログは定期的に *1、gzip圧縮ファイルとして、指定したS3バケットに配信されます。

cflog1

http://docs.aws.amazon.com/AmazonCloudFront/latest/DeveloperGuide/AccessLogs.html

さてこの設定を行いますと、指定したバケットがこんな感じになります。どんな単位で集約されているのかは定かではありませんが、同じ時間帯に複数のファイルがありますね。これでも数が少ない時間帯を選んだのですが。要するに物凄い数のログファイルがガンガン配信されてくるようになります。アクセス数にもよりますが、今回の検証環境では1日あたり1000ファイルほどが配信されました。

cflog2

さて、このログファイルを集計してください。日毎のアクセス数、日時毎のアクセス数、くらいまではファイルをDLしてきて、ローカルでshellをこねくり回せばどうにかなるでしょう。しかし、期間が増えてきたり、キャッシュヒット率等を算出したくなったら、手に負えなくなってきますね。

という時には、EMRのHiveを使えばいいと思います。

Elastic MapReduceでログ分析をしてみる

MapReduceだとかHiveだとかって難しそうですよね。ただしここで敬遠しないでください。今回のテーマにあたっては、まずは最低限のコトとしてこの辺りをさらっと読んでおけば充分です。

あとはもう、以下の指示に従って操作するだけで、CloudFrontアクセスログの分析ができます。

前提・準備

まず、解析対象のログがなければ話が始まりません。CloudFront Distributionの設定でログ出力をONにし、最低限1〜2日分のログをためておいてください。今回、ログがたまるバケットをcflogsとします。

その他として、PowerUserのIAMロール、EC2キーペアは持ってますね。なければ作っておいてください。

まずはEMRのクラスタを立ち上げる

まずは分析のためのクラスタを立ち上げます。初回からまともな規模設計をしようとすると異様に敷居が上がるので、サイジングは適当です。よし、m1.largeを10台にしましょう。この検証は通常1時間、長くとも2〜3時間で終わるでしょうから、コストは $0.240 × 10台 × 3時間、つまり多く見積もっても7.2ドルです。そのくらいのお小遣いを準備してください。

この数ドルを握りしめてEMRのManagement Consoleに行きます。左上のCreate cluseterボタンをクリックします。

クラスタの設定は、多くはデフォルトで良いのですが、変更する項目は画像内に赤で示した通りです。

  • まず、ログは出力先の用意等をしていないので、ひとまずOFFです。必要に応じて。
  • AMIのバージョン（≒Hadoopのバージョン）は最新を選択しました。
  • 先ほど決めたm1.large×10台となるよう、Masterノードを1台、Coreノードを9台とします。
  • EC2キーペアを設定します。
  • PowerUserのIAMロールを設定します。

2014-01-09_1702-cflog-emr1

以上の設定でクラスタを作成し、ステータスが「Waiting」になるまでしばらく *2待ちます。

2014-01-09_1712-cflog-emr2

SSHでMasterノードに接続してHiveを起動する

上記の画面に「Master public DNS name」という項目がありますね。これがSSH接続先です。

$ ssh -i /path/to/xxxkey.pem hadoop@ec2-XX-XX-XX-XX.ap-northeast-1.compute.amazonaws.com

注意点はec2-userではなくhadoopユーザであることです。ここを間違うと、次のステップでhiveコマンドが実行できません。

というわけでSSH接続し、おもむろにhiveというコマンドを入力すると、Hiveのコンソールに入れます。

       __|  __|_  )
       _|  (     /   Amazon Linux AMI
      ___|\___|___|

https://aws.amazon.com/amazon-linux-ami/2013.09-release-notes/
12 package(s) needed for security, out of 41 available
Run "sudo yum update" to apply all updates.
--------------------------------------------------------------------------------

Welcome to Amazon Elastic MapReduce running Hadoop and Amazon Linux.

Hadoop is installed in /home/hadoop. Log files are in /mnt/var/log/hadoop. Check
/mnt/var/log/hadoop/steps for diagnosing step failures.

The Hadoop UI can be accessed via the following commands:

  ResourceManager    lynx http://localhost:9026/
  NameNode           lynx http://localhost:9101/

--------------------------------------------------------------------------------
[hadoop@ip-XX-XX-XX-XX ~]$ hive
14/01/09 07:02:34 INFO Configuration.deprecation: mapred.input.dir.recursive is deprecated. Instead, use mapreduce.input.fileinputformat.input.dir.recursive
14/01/09 07:02:34 INFO Configuration.deprecation: mapred.max.split.size is deprecated. Instead, use mapreduce.input.fileinputformat.split.maxsize
14/01/09 07:02:34 INFO Configuration.deprecation: mapred.min.split.size is deprecated. Instead, use mapreduce.input.fileinputformat.split.minsize
14/01/09 07:02:34 INFO Configuration.deprecation: mapred.min.split.size.per.rack is deprecated. Instead, use mapreduce.input.fileinputformat.split.minsize.per.rack
14/01/09 07:02:34 INFO Configuration.deprecation: mapred.min.split.size.per.node is deprecated. Instead, use mapreduce.input.fileinputformat.split.minsize.per.node
14/01/09 07:02:34 INFO Configuration.deprecation: mapred.reduce.tasks is deprecated. Instead, use mapreduce.job.reduces
14/01/09 07:02:34 INFO Configuration.deprecation: mapred.map.tasks.speculative.execution is deprecated. Instead, use mapreduce.map.speculative
14/01/09 07:02:34 INFO Configuration.deprecation: mapred.reduce.tasks.speculative.execution is deprecated. Instead, use mapreduce.reduce.speculative
14/01/09 07:02:35 WARN conf.Configuration: org.apache.hadoop.hive.conf.LoopingByteArrayInputStream@616a37dc:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval;  Ignoring.
14/01/09 07:02:35 WARN conf.Configuration: org.apache.hadoop.hive.conf.LoopingByteArrayInputStream@616a37dc:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts;  Ignoring.

Logging initialized using configuration in file:/home/hadoop/.versions/hive-0.11.0/conf/hive-log4j.properties
Hive history file=/mnt/var/lib/hive_0110/tmp/history/hive_job_log_hadoop_4527@ip-172-31-16-57.ap-northeast-1.compute.internal_201401090702_178989653.txt
hive>

データ形式の定義

まずは、CloudFrontアクセスログのデータ形式を定義します。と言うと難しく聞こえますが、要するに下記をコピペで入力します。LOCATIONに指定する部分は、バケット名にあわせて適宜調整してください。

CREATE EXTERNAL TABLE IF NOT EXISTS impressions (
  dt STRING,
  tm STRING,
  xedgelocation STRING,
  scbytes INT,
  cip STRING,
  csmethod STRING,
  cshost STRING,
  csuristem STRING,
  csstatus STRING,
  csreferrer STRING, 
  csuseragent STRING,
  csuriquery STRING,
  cscookie STRING,
  edgeresulttype STRING,
  edgerequestid STRING,
  hostheader STRING,
  protocol STRING,
  csbytes INT
)
ROW FORMAT DELIMITED FIELDS TERMINATED BY '\t'
LOCATION 's3://cflogs/';

これに対して、下記のようなレスポンスが返ればOK。十数秒かかる感じですが、じっと待ちましょうね。

OK
Time taken: 14.284 seconds

分析してみよう

日毎のログ数

まずは簡単なところから。日毎のログ数を集計してみましょう。

SELECT
  dt,
  COUNT(*)
FROM `impressions`
GROUP BY dt;

おやまぁ、ただのSQLじゃないですか。ただし、実行には結構な時間がかかります。データ量にもよりますが、数十秒で済むことは無いと思ってください。スピードを上げたければ、お財布と相談してください。

hive> SELECT
    >   dt,
    >   COUNT(*)
    > FROM `impressions`
    > GROUP BY dt;
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):
  set hive.exec.reducers.bytes.per.reducer=<number>
In order to limit the maximum number of reducers:
  set hive.exec.reducers.max=<number>
In order to set a constant number of reducers:
  set mapred.reduce.tasks=<number>
Starting Job = job_1389248669508_0001, Tracking URL = http://172.31.16.57:9046/proxy/application_1389248669508_0001/
Kill Command = /home/hadoop/bin/hadoop job  -kill job_1389248669508_0001
Hadoop job information for Stage-1: number of mappers: 884; number of reducers: 1
2014-01-09 07:06:43,665 Stage-1 map = 0%,  reduce = 0%
2014-01-09 07:07:12,329 Stage-1 map = 1%,  reduce = 0%, Cumulative CPU 26.39 sec
2014-01-09 07:07:13,397 Stage-1 map = 1%,  reduce = 0%, Cumulative CPU 26.39 sec
2014-01-09 07:07:14,450 Stage-1 map = 1%,  reduce = 0%, Cumulative CPU 26.39 sec
2014-01-09 07:07:15,497 Stage-1 map = 1%,  reduce = 0%, Cumulative CPU 26.39 sec
2014-01-09 07:07:16,560 Stage-1 map = 1%,  reduce = 0%, Cumulative CPU 26.39 sec
2014-01-09 07:07:17,612 Stage-1 map = 1%,  reduce = 0%, Cumulative CPU 26.39 sec
2014-01-09 07:07:18,660 Stage-1 map = 1%,  reduce = 0%, Cumulative CPU 26.39 sec
2014-01-09 07:07:19,725 Stage-1 map = 1%,  reduce = 0%, Cumulative CPU 26.39 sec
2014-01-09 07:07:20,787 Stage-1 map = 1%,  reduce = 0%, Cumulative CPU 26.39 sec
2014-01-09 07:07:21,853 Stage-1 map = 2%,  reduce = 0%, Cumulative CPU 45.2 sec
2014-01-09 07:07:22,915 Stage-1 map = 3%,  reduce = 0%, Cumulative CPU 83.15 sec
2014-01-09 07:07:23,971 Stage-1 map = 4%,  reduce = 0%, Cumulative CPU 105.54 sec

...中略...

2014-01-09 07:17:07,968 Stage-1 map = 100%,  reduce = 100%, Cumulative CPU 2886.53 sec
MapReduce Total cumulative CPU time: 48 minutes 6 seconds 530 msec
Ended Job = job_1389248669508_0001
Counters:
MapReduce Jobs Launched:
Job 0: Map: 884  Reduce: 1   Cumulative CPU: 2886.53 sec   HDFS Read: 205972 HDFS Write: 267 SUCCESS
Total MapReduce CPU Time Spent: 48 minutes 6 seconds 530 msec
OK
#Fields: date time x-edge-location sc-bytes c-ip cs-method cs(Host) cs-uri-stem sc-status cs(Referer) cs(User-Agent) cs-uri-query cs(Cookie) x-edge-result-type x-edge-request-id x-host-header cs-protocol cs-bytes	884
#Version: 1.0	884
2014-01-08	1516
2014-01-09	2084
Time taken: 659.868 seconds, Fetched: 4 row(s)

ひとまず結果が出ました。結果が出るまでは約11分。この例では、ログ出力開始から分析まで20時間前後しか経っていないので、2日分のエントリしか取れませんでしたが。まぁこんな感じです。

時間毎のログ数集計

続いて、時間毎の集計Hiveクエリはこちら。やはりどう見てもSQLですね。

SELECT
  dt,
  hour(tm),
  COUNT(*)
FROM `impressions`
GROUP BY dt, hour(tm);

結果

#Fields: date time x-edge-location sc-bytes c-ip cs-method cs(Host) cs-uri-stem sc-status cs(Referer) cs(User-Agent) cs-uri-query cs(Cookie) x-edge-result-type x-edge-request-id x-host-header cs-protocol cs-bytes	NULL	990
#Version: 1.0	NULL	990
2014-01-08	9	126
2014-01-08	10	317
2014-01-08	11	189
2014-01-08	12	185
2014-01-08	13	140
2014-01-08	14	118
2014-01-08	15	146
2014-01-08	16	54
2014-01-08	17	15
2014-01-08	18	3
2014-01-08	19	3
2014-01-08	20	21
2014-01-08	21	4
2014-01-08	22	20
2014-01-08	23	175
2014-01-09	0	283
2014-01-09	1	502
2014-01-09	2	455
2014-01-09	3	474
2014-01-09	4	349
2014-01-09	5	500
Time taken: 794.739 seconds, Fetched: 23 row(s)

ちなみに先頭の2行は、各ファイルのヘッダが集計されちゃったものです。ひとまず無視すればいいです。

日毎のキャッシュヒット状況

最後にキャッシュヒット状況を見てみましょう。

SELECT 
  dt,
  edgeresulttype,
  COUNT(*) 
FROM `impressions`
GROUP BY dt, edgeresulttype;

結果

2014-01-08	Error	6
2014-01-08	Hit	1460
2014-01-08	Miss	50
2014-01-09	Error	2
2014-01-09	Hit	2868
2014-01-09	Miss	73
Time taken: 808.076 seconds, Fetched: 8 row(s)

キャッシュヒット率は97%前後ですね。いい感じかと思います。エラーが数件出てるのが気になりますね。

エラーとなったログを表示

先ほど最後と言いましたが、気持ち悪いので見ておきましょうか。。。

SELECT
  *
FROM `impressions`
WHERE edgeresulttype = 'Error';

結果

2014-01-09	05:58:09	NRT53	575	XXX.XXX.XXX.XXX	GET	XXXXXXXXXXXXXX.cloudfront.net	/favicon.ico	404	-	Mozilla/5.0%2520(Windows%2520NT%25206.1;%2520WOW64)%2520AppleWebKit/537.36%2520(KHTML,%2520like%2520Gecko)%2520Chrome/31.0.1650.63%2520Safari/537.36	-	-	Error	BdBOb10966aAi7MzkmIVJXBLN-mYOyzICbeopjx06STtRfzExjvmoA==	XXXXXXXXXXXXXX.cloudfront.net	http	303
2014-01-08	22:55:09	LHR5	574	XXX.XXX.XXX.XXX	GET	XXXXXXXXXXXXXX.cloudfront.net	/robots.txt	404	-	Mozilla/5.0%2520(compatible;%2520Googlebot/2.1;%2520+http://www.google.com/bot.html)	-	-	Error	b-0o8jXZFTqUnUEkIS8Xby_ByfdeIndUo2YdHX2KF1BuRbL6rX0W7Q==	XXXXXXXXXXXXXX.cloudfront.net	http	279
2014-01-09	05:04:28	NRT54	575	XXX.XXX.XXX.XXX	GET	XXXXXXXXXXXXXX.cloudfront.net	/favicon.ico	404	-	Mozilla/5.0%2520(compatible;%2520MSIE%25209.0;%2520Windows%2520NT%25206.0;%2520WOW64;%2520Trident/5.0)	-	-	Error	ue5ihm5GJ6GaH_Nu2gS1ff2D9adM8l-ll8DY0tNBA5vSIP-P1qz8IA==	XXXXXXXXXXXXXX.cloudfront.net	htt	219
2014-01-08	17:39:36	SEA50	574	XXX.XXX.XXX.XXX	GET	XXXXXXXXXXXXXX.cloudfront.net	/robots.txt	404	-	Mozilla/5.0%2520(compatible;%2520bingbot/2.0;%2520+http://www.bing.com/bingbot.htm)	-	-	Error	nO9e0_X9D2yoZ-EUrt9nKXLP75WF6EAjHUOUeVCWY4tgUPVNhmcJpw==	XXXXXXXXXXXXXX.cloudfront.net	http	281
2014-01-08	22:16:55	SEA50	574	XXX.XXX.XXX.XXX	GET	XXXXXXXXXXXXXX.cloudfront.net	/robots.txt	404	-	Mozilla/5.0%2520(compatible;%2520bingbot/2.0;%2520+http://www.bing.com/bingbot.htm)	-	-	Error	PZ8nXhEZC78sAONqe3MGe4TOAY6xlwkV2_1vafJNhzwP_FrxDNny9g==	XXXXXXXXXXXXXX.cloudfront.net	http	281
2014-01-08	20:45:32	ICN50	574	XXX.XXX.XXX.XXX	GET	XXXXXXXXXXXXXX.cloudfront.net	/robots.txt	404	-	Mozilla/5.0%2520(compatible;%2520YandexImages/3.0;%2520+http://yandex.com/bots)	-	-	Error	9EDkTmqIbKZIPnEaoiuMgd4f_kqcbFqvkEs36R2cDrkrwZk2InBgGw==	XXXXXXXXXXXXXX.cloudfront.net	http	202
2014-01-08	11:35:36	SEA50	574	XXX.XXX.XXX.XXX	GET	XXXXXXXXXXXXXX.cloudfront.net	/robots.txt	404	-	Mozilla/5.0%2520(compatible;%2520bingbot/2.0;%2520+http://www.bing.com/bingbot.htm)	-	-	Error	vxvCiN_sU1TZXQt7sIj_D3qcm0xZ0epOnhMtVEgsweTQB7qXTG2HBQ==	XXXXXXXXXXXXXX.cloudfront.net	http	281
2014-01-08	22:28:32	HKG1	574	XXX.XXX.XXX.XXX	GET	XXXXXXXXXXXXXX.cloudfront.net	/robots.txt	404	-	Mozilla/5.0%2520(compatible;%2520coccoc/1.0;%2520+http://help.coccoc.com/)	-	-	Error	gjf2IWkWVwm9lqjJ4nTS719unuvftqGSsz2L4P3EeWOJBuCZLyuOgA==	XXXXXXXXXXXXXX.cloudfront.net	http	292
Time taken: 780.391 seconds, Fetched: 8 row(s)

単なるrobots.txtとfavicon.icoの404レスポンスですね。問題無いことが確認できました。

後片付け

これを忘れないでくださいね。EMRのコンソールから、Terminateボタンをクリックし、クラスタを終了させておきましょう。

2014-01-09_1758-emr-terminate

まとめ

CloudFrontが吐き出すログは大量です。ログ出力の設定はしてみたものの、内容の精査は諦めてしまっていたことが多いのではないでしょうか。MapReduceだHiveだと、新しいことを覚えなければならない敷居の高さを感じるかもしれませんが、何も考えずにやってみると、これほど簡単なものかとびっくりしたと思います。

難しいことは考えず、この手法を是非ご活用いただければと。

脚注

  1. リアルタイムに、ではない。 ↩
  2. 10〜20分くらいだと思います。 ↩

Share this article

facebook logohatena logotwitter logo

関連記事

【CDI】Informatica Cloud Data Integrationで、ソースのスキーマを自動的に読み込めるという「スキーマ変更処理」を検証してみた

【CDI】Informatica Cloud Data Integrationで、ソースのスキーマを自動的に読み込めるという「スキーマ変更処理」を検証してみた

User avatar
渡部晃季
2023.05.02
Redshiftで各テーブルのカラム毎の利用ブロック数を確認する

Redshiftで各テーブルのカラム毎の利用ブロック数を確認する

User avatar
k.uehara
2023.03.07
[レポート]AWSでデータメッシュアーキテクチャを構築する#ANT336 #reinvent

[レポート]AWSでデータメッシュアーキテクチャを構築する#ANT336 #reinvent

User avatar
nayu.t.s
2023.01.01
dbt Coalesce 2022と来年の告知

dbt Coalesce 2022と来年の告知

User avatar
ちゃあこ
2022.10.28
Classmethod's white logo
Facebook's logo
X's logo
YouTube's logo

© Classmethod, Inc. All rights reserved.