qを使ったELBログの簡単分析

#Elastic Load Balancing (ELB)

#AWS

横田慎介

2015.11.12

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

はじめに

CSV/TSVなどのテキストファイルをSQLライクに参照できる「q」というツールがあります。本ブログでも紹介したことがあります。 CSV/TSVに対してSQL発行できるツール「q」

今回はこのqでS3に保存されているELBのログを分析してみたので、その手順を紹介いたします。

手順

まず、qを実行するためのEC2インスタンスを起動します。リージョンはログが保存されているS3バケットと揃えた方が良いでしょう。 S3からログをダウンロードする必要があるので、起動の際にAmazonS3ReadOnlyAccess権限を持ったIAM Roleを付与してください。インスタンスタイプやEBSサイズは分析するログの量に合わせて調整してください。一時利用なので大きめのSpotインスタンスでも良いかもしれません。

インスタンスが立ち上がったらqをインストールします。

$ sudo rpm -ihv https://github.com/harelba/packages-for-q/raw/master/rpms/q-text-as-data-1.5.0-1.noarch.rpm

とりあえず、1日分のELBログを使って1時間ごとのリクエスト数と送信データ量の推移を見てみましょう。 S3から１日分のログをまとめてダウンロードし、

$ aws s3 cp s3://{backet-name}/AWSLogs/{account-id}/elasticloadbalancing/ap-northeast-1/2015/11/10 . --recursive
(省略)

時間で集約します。

$ q -O "select strftime('%H',c1) as hour, count(*) as request_count, sum(c11) as response_sent_bytes from *.log group by hour"
hour request_count response_sent_bytes
00 7939 46825152
01 8855 51892292
02 10238 63159849
03 11750 70733310
04 9158 54835924
05 6430 44948361
06 4180 30435577
07 1812 12058668
08 969 7761572
09 704 5717191
10 801 5695640
11 1656 14835893
12 2854 23409888
13 4159 33225466
14 13393 68556506
15 8743 51453679
16 6532 44775112
17 5394 38554788
18 4865 37981625
19 4020 32230221
20 4380 30886330
21 4699 33117316
22 4001 29022821
23 7531 46989717

簡単ですね。

from句ではワイルドカードを使って複数のファイルをまとめて参照しています。 "-O"オプションをつけると出力にヘッダが表示されるようになります。 ELBのログのフォーマットはTSVで1カラム目がリクエスト日時(UTC)、11カラム目がレスポンスのバイト数となっています。 SQL上は"c1"、"c11"というふうに指定しています。ログフォーマットの詳細はこちらをご覧ください。アクセスログのエントリ

レスポンスの遅いリソースを調べる場合はこんな感じでしょうか。

$ q -O "select c12 as request, avg(c6) as time_taken from *.log group by request order by time_taken desc limit 10"
request time_taken
"GET http://example.com:80/index.php HTTP/1.1" 0.07969
"GET http://example.com:80/list.php HTTP/1.1" 0.078014
"GET http://example.com:80/detail.php HTTP/1.1" 0.076487
(省略)

S3オブジェクトは1つだけであればストリーミングダウンロードし、標準入力として利用できます。なので、参照するオブジェクトが1つで良いなら、ローカルにファイルを保存することなく直接qで集計できます。

$ aws s3 cp s3://{backet-name}/AWSLogs/{account-id}/elasticloadbalancing/ap-northeast-1/2015/11/10/xxx.log - | q -O "select c4 as backend, count(*) as backend_processing_count, avg(c6) as backend_processing_time from - group by backend"
backend backend_processing_count backend_processing_time
10.0.0.43:80 3641 0.000728715737435
10.0.1.103:80 3128 0.00261443957801

各バックエンドのインスタンスへのリクエストの振り分けと、各々からのレスポンスタイムの平均を見ています。ほぼ均等に振り分けられていそうです。レスポンスタイムに差があるのはマルチAZにしているからでしょう。このログを吐いたELBインスタンスと同じAZのバックエンドがそうでないものに比べてレスポンスが早くなっているのだと思います。