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

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

Webアプリケーションのパフォーマンス改善をするためには、何よりもプロファイリングが大事です。
商用のプロファイリングサービスとしてはNew Relicなどが有名であり、VASILYでも活用をしています。

ですが、この記事ではnginxログを使ってプロファイリングをしてみます。
nginxログからはNew Relicほど細かな情報を取得することはできません。
例えば、DBとの通信にかかった時間や、外部webサービスとの通信にかかった時間はわかりません。
しかし、New Relicのログは集約済みの値しかわかりませんが、nginxにログは生ログなので自由度の高い分析を行うことができます。

ある程度以上の規模のサービスでは複数台のwebサーバーでサービスを提供していることが多いかと思います。
そのような環境下ではそれぞれのサーバーに保存されているログを1つのデータソースに集約すると分析作業を行いやすくなります。
VASILYではすべてのnginxログをBigQueryに保存しているため、BigQueryに保存されたnginxに対して集計を行い、プロファイリングを行います。

ログ収集システム

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とは

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/1 と https://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の機能を利用した自由度の高い分析を行うことができるという利点があります。

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