最近、稼働中のアプリケーションが「たまに遅い」という事象に遭遇しました。体感的には、リクエストが10回に1回程度、ほんの一瞬ですが引っかかりがあるという感じです。原因を探るため、リクエストログをBigQueryとData Studioを使って分析し、無事に原因を特定することができました。とても簡単に設定でき継続的に使える方法なので、紹介したいと思います。
ステップ1: リクエストログをBigQueryに送る
リクエストログは、URLとLatencyが含まれていればどんな形式でも良いです。今回のケースでは、アプリケーションはGoogle CloudのApp Engine（フレキシブル環境）で稼働していましたので、デフォルトでCloud Loggingに出力されているnginxのログを、Cloud LoggingのLog Router（Sink）を使ってBigQueryに転送しました。
Sinkの設定としては、宛先を「BigQuery データセット」に指定し、ログフィルタを以下のように設定します。
resource.type="gae_app"
log_name="projects/PROJECT_ID/logs/appengine.googleapis.com%2Fnginx.request"
httpRequest.requestUrl!="/nginx_metrics"
しばらくすると、BigQuery側に新しいログが転送され、自動的にデータセットのスキーマが登録されるはずです。
ステップ2: Data Studioでログを分析する
Data StudioからBigQueryに接続し、リクエストログのデータセットを参照できるようにします。
分布図からリクエスト数が多くレイテンシが大きいエンドポイントを特定する
グラフは「分布図」でもいいのですが、より視覚的にわかりやすい「バブルチャート」を選択します。
- ディメンション:
URLに相当するカラム - 指標X:
Record Countの合計値 - 指標Y:
Latencyに相当するカラムの平均値 - バブルサイズの指標:
Record Countの合計値 - 指標スライダー:
ON - 並べ替え:
Record Countの合計値の降順// ここは変えてみてもいいです
以下は、事象が発生していた当時のグラフです。
リクエスト数は少ないですが、レイテンシが非常に大きいエンドポイントがたくさんあることが分かります。（実際にはパスパラメータの違いなので、エンドポイントとしては１つなのですが。）
このグラフにより、今回の事象の原因は「もともとレイテンシが大きいエンドポイントのキャッシュの有効時間を短くしたため」だったことが分かりました。レイテンシが大きいエンドポイントのリクエストを処理している間、他のリクエストに待ちが生じる頻度が多くなり、「たまに遅い」が発生していました。
以下は、対策を講じた後のグラフです。
キャッシュ時間の調整ではなく、レイテンシが遅い原因自体を修正しました。レイテンシが大きいエンドポイントが明らかに減ったことが分かると思います。
１つのグラフに表示できるデータポイントの数に限界があるため、並べ替えを変えたり、指標スライダーでフィルタリングすると、また違ったデータが見えてきます。例えばLatencyを0.2以上にフィルタリングすると以下のようになります。まだ改善の余地がありますね！
折れ線グラフでレイテンシの変動を前期間と比較して表示する
今回のような事象は、どんなに注意していても起きてしまうことはあります。起きてしまったことをより早く検知できるよう、レイテンシの変動に気がつけるようなグラフも用意してみました。
グラフは「折れ線グラフ」を選択します。
- ディメンション:
timestamp - 指標:
Latencyに相当するカラムの平均値 - デフォルトの日付範囲:
過去７日間（今日を除く） - 比較期間:
前の期間
以下は、事象が発生した前後のグラフです。
前の期間のグラフ（薄い青）に比べて、現在の期間のグラフ（濃い青）の方が、レイテンシが高くなっていることが分かります。これだけ大きくグラフに変動があると、なにかやっちまったなと分かりますね。
Data Studioは定期的にレポートをメールで送信してくれる機能があるので、定期的にチェックするようにすると良いと思います。
まとめ
今回はじめてData Studioを使ってみたんですが、とても簡単にログ分析ができました。同じようなことは既成のモニタリングツールでも簡単にできると思いますが、Data Studioのグラフだったり、BigQueryのクエリで実際にデータをいじってみると、よりデータに興味が湧いて能動的な分析が行えるので良いですよ。
Discussion