Edited at
VASILYDay 1

BigQueryに保存されているnginxログでalpっぽくプロファイリングしてみる

More than 1 year has passed since last update.

こんにちは、バックエンドエンジニアの塩崎です。

Webアプリケーションのパフォーマンス改善をするためには、何よりもプロファイリングが大事です。

商用のプロファイリングサービスとしてはNew Relicなどが有名であり、VASILYでも活用をしています。

ですが、この記事ではnginxログを使ってプロファイリングをしてみます。

nginxログからはNew Relicほど細かな情報を取得することはできません。

例えば、DBとの通信にかかった時間や、外部webサービスとの通信にかかった時間はわかりません。

しかし、New Relicのログは集約済みの値しかわかりませんが、nginxにログは生ログなので自由度の高い分析を行うことができます。

ある程度以上の規模のサービスでは複数台のwebサーバーでサービスを提供していることが多いかと思います。

そのような環境下ではそれぞれのサーバーに保存されているログを1つのデータソースに集約すると分析作業を行いやすくなります。

VASILYではすべてのnginxログをBigQueryに保存しているため、BigQueryに保存されたnginxに対して集計を行い、プロファイリングを行います。


ログ収集システム

スクリーンショット 2017-11-30 14.37.21.png

VASILYではnginxログの収集にfluentdを使用しています。

nginxはltsv形式でログを出力し、各サーバーのfluentdがそのltsvファイルを読み込みます。

各サーバーのfluentdはログ集計サーバーのfluentdにデータをforwardし、ログ集計サーバーのfluentdがBigQueryへのデータ送信を行います。

fluentdからBigQueryへのデータ送信にはfluent-pluginbigqueryを使用しています。

https://github.com/kaizenplatform/fluent-plugin-bigquery

BigQueryに保存するとき際、保存先テーブル名の末尾にYYYYMMDD形式で日付を埋め込むことによって、日毎に別テーブルに保存されるようにしています。


alpっぽく集計してみる

一旦、nginxログがBigQueryに入ってしまえば、様々な集計を行うことができます。

ここでは、試しにalpっぽく集計してみることにします。


alpとは

https://github.com/tkuchiki/alp

alpはtkukichiさんによるアクセスログのプロファイラで、LTSV形式のログを集計するためのものです。

各エントリーポイントごとにレスポンスを返すためにかかった時間の平均値・最大値・中央値などを集計します。

これらのデータを確認は、システムのボトルネックを探しにとても役立ちます。


集計用SQL

以下のSQLでalpと同等の集計を行うことができます。

#standardSQL

CREATE TEMPORARY FUNCTION TRIM_QUERY_STRING (str STRING)
RETURNS STRING AS (
REGEXP_EXTRACT(str, r'[^?]*')
);

CREATE TEMPORARY FUNCTION ROUND_DIGITS (str STRING)
RETURNS STRING AS (
REGEXP_REPLACE(str, r'\d+', '[digits]')
);

WITH log_table AS (
SELECT
apptime,
size,
uri,
method
FROM `mydataset.nginx_access_log_20171201`
), alp AS (
SELECT
count(1) AS count,
min(apptime) AS min,
max(apptime) AS max,
sum(apptime) AS sum,
avg(apptime) AS avg,
APPROX_QUANTILES(apptime, 1000)[offset(10)] AS p1,
APPROX_QUANTILES(apptime, 1000)[offset(500)] AS p50,
APPROX_QUANTILES(apptime, 1000)[offset(990)] AS p99,
STDDEV(apptime) AS stddev,
max(size) AS max_body,
min(size) AS min_body,
avg(size) AS avg_body,
sum(size) AS sum_body,
method,
uri
FROM log_table
GROUP BY uri, method
)

SELECT * FROM alp ORDER BY avg DESC

それぞれの集計結果の説明を以下の表に示します。

列名
説明
備考

count
HTTPリクエスト数

min
レスポンスタイムの最小値

max
レスポンスタイムの最大値

sum
レスポンスタイムの合計値
count * avg

avg
レスポンスタイムの平均値

p1
レスポンスタイムの1パーセンタイル値

p50
レスポンスタイムの50パーセンタイル値
中央値でもある

p99
レスポンスタイムの99パーセンタイル値

max_body
HTTPボディサイズの最大値

min_body
HTTPボディサイズの最小値

avg_body
HTTPボディサイズの平均値

sum_body
HTTPボディサイズの合計値
count * avg_body

method
HTTPメソッド

uri
URI


オプション

上記のSQLをそのまま使うだけでなく、いくつかのオプション機能を使うとより効率的にプロファイリングを行うことができます。


複数の日付のテーブルを対象にする

ログの保存先テーブルを日毎に分け、対象の日だけのテーブルをスキャンすることで、スキャン量を削減するということをやっている方は多いかと思います。

そのようなケースで複数日を対象とした集計を行うためには以下のように、_TABLE_SUFFIX擬似列を使って複数の日付を対象にします。

WITH log_table AS (

SELECT
apptime,
size,
uri AS uri,
method
FROM `mydataset.nginx_access_log_*`
WHERE _TABLE_SUFFIX BETWEEN '20171201' AND '20171231'
), alp AS (


クエリ文字列を削除する

HTTP GETリクエストを受けた時のクエリ文字列 ?hoge=fuga&foo=bar を削除して、クエリ文字列のみが異なるURIを同一のURIとして集計するためには、以下のようにします。

WITH log_table AS (

SELECT
apptime,
size,
TRIM_QUERY_STRING(uri) AS uri,
method
FROM `mydataset.nginx_access_log_20171201`
), alp AS (


連続する数字をまとめる

https://example.com/users/1https://example.com/users/2を同一のURIとして集計するためには、以下のようにします。

数字をまとめるための正規表現が雑なので、意図しない部分でまとめられてしまうかもしれません。

WITH log_table AS (

SELECT
apptime,
size,
ROUND_DIGITS(uri) AS uri,
method
FROM `mydataset.nginx_access_log_20171201`
), alp AS (


まとめ

BigQueryに保存されているnginxログを集計することで、alpと同等の機能を作ることに成功しました。

NewRelicに比べると取得できる情報の粒度が荒いですが、BigQueryの機能を利用した自由度の高い分析を行うことができるという利点があります。

明日は、フロントエンドエンジニアの茨木が開発合宿中に作ったものを書く予定です。