Enjoy IT Life

alpのインストールからNginxのアクセスログ解析までの手順【ISUCON】

（更新: 2021-06-19）
インフラ

こんにちは。@nishina555です。

前回こちらの記事でISUCON環境をConoHaに構築しました。

ISUCONではパフォーマンスチューニングのスコアで勝敗を決めるわけですが、チューニングをする前にまずはどこを改善するか計測をする必要があります。

チューニング対象はWebサーバー、アプリケーション、データベースが主にあります。

今回はWebサーバーであるNginxのアクセスログを解析するのに便利なaplというツールのインストール方法の手順と、実際のログの確認のしかたについて説明をします。今回利用するalpのバージョンは0.3.1です。

今回のゴール
  • alpをインストールする
  • Nginxのアクセスログをaplで確認する
  • alpのラベルの意味を理解する
  • alpのオプションについて理解する

nginxのアクセスログを見やすくするプロファイリングツールalp

alpとは『Access Log Profiler』の頭文字をとったもので、プロファイリングツールの一種です。

プロファイリングツールにはalpの他にもkataribeなどがあります。

alpにはアクセスログを集計したりソートしたりするオプションが豊富に用意されているため、aplを導入することでリクエストの解析がしやすくなります。

なお、aplはTSVファイル(tab-separated values)にラベルがついた、LTSV(Labeled tab-separated values)形式のアクセスログを集計します。

よく目にするCSVファイルは(comma-separated values)の略なので、TSVファイルとはCSVのコンマがタブに変わった形式のファイルです。

alpのインストール

まずはalpをインストールします。

こちらで配布されているalpをダウンロードし、インストールコマンドを実行します。

$ wget https://github.com/tkuchiki/alp/releases/download/v0.3.1/alp_linux_amd64.zip
$ unzip alp_linux_amd64.zip

# パスの通っているディレクトリにalpをインストール
$ sudo install ./alp /usr/local/bin

nginx.confを編集し、アクセスログの出力フォーマットをLTSV形式にする

alpはLTSV形式のアクセスログを集計します。

そのため、alpを利用してアクセスログを解析するためにはnginxのログフォーマットをLTSVに変更する必要があります。

まずはベンチマークを実行する前にnginxの設定ファイルを修正します。

$ sudo vim /etc/nginx/nginx.conf

設定ファイルのhttp {の部分に以下の内容を追加します。

http {
  log_format ltsv "time:$time_local"
    "\thost:$remote_addr"
    "\tforwardedfor:$http_x_forwarded_for"
    "\treq:$request"
    "\tmethod:$request_method"
    "\turi:$request_uri"
    "\tstatus:$status"
    "\tsize:$body_bytes_sent"
    "\treferer:$http_referer"
    "\tua:$http_user_agent"
    "\treqtime:$request_time"
    "\truntime:$upstream_http_x_runtime"
    "\tapptime:$upstream_response_time"
    "\tcache:$upstream_http_x_cache"
    "\tvhost:$host";

  access_log  /var/log/nginx/access.log ltsv;
}

設定を反映するためにnginxをリロードします。

新しくベンチマークを取るため、前回のベンチマークで出力されたアクセスログを削除しておきます。

$ sudo rm /var/log/nginx/access.log && sudo systemctl reload nginx

ベンチマークの実行

ここまで準備できたらベンチマークの実行をしていきます。

ベンチマークのコマンドはConoHaの公式ページに書いてあるものを参考にします。

$ /home/isucon/isubata/bench/bin/bench -data=/home/isucon/isubata/bench/data -remotes=localhost -output=result.json

アクセスログの確認方法とラベルの意味

ベンチマークの実行が終わるとアクセスログにリクエストの内容がLTSV形式で保存されています。

これをalpを利用して確認していきます。

alpでは-fで対象のファイルを指定できるので、以下のコマンドでアクセスログをみることができます。

なお、alpではMAXの降順がデフォルトの表示順になります。

$ alp -f /var/log/nginx/access.log
+-------+-------+-------+--------+-------+-------+-------+-------+--------+------------+------------+-------------+------------+--------+-----------------------------------------------------+
| COUNT |  MIN  |  MAX  |  SUM   |  AVG  |  P1   |  P50  |  P99  | STDDEV | MIN(BODY)  | MAX(BODY)  |  SUM(BODY)  | AVG(BODY)  | METHOD |                         URI                         |
+-------+-------+-------+--------+-------+-------+-------+-------+--------+------------+------------+-------------+------------+--------+-----------------------------------------------------+
|    42 | 0.000 | 0.000 |  0.000 | 0.000 | 0.000 | 0.000 | 0.000 |  0.000 | 108738.000 | 108738.000 | 4566996.000 | 108738.000 | GET    | /fonts/glyphicons-halflings-regular.svg             |
|    42 | 0.000 | 0.000 |  0.000 | 0.000 | 0.000 | 0.000 | 0.000 |  0.000 |    318.000 |    318.000 |   13356.000 |    318.000 | GET    | /favicon.ico                                        |
|    42 | 0.000 | 0.000 |  0.000 | 0.000 | 0.000 | 0.000 | 0.000 |  0.000 |   1741.000 |   1741.000 |   73122.000 |   1741.000 | GET    | /css/main.css                                       |
|    42 | 0.000 | 0.000 |  0.000 | 0.000 | 0.000 | 0.000 | 0.000 |  0.000 | 150996.000 | 150996.000 | 6341832.000 | 150996.000 | GET    | /css/bootstrap.min.css                              |
|    42 | 0.000 | 0.000 |  0.000 | 0.000 | 0.000 | 0.000 | 0.000 |  0.000 |  23424.000 |  23424.000 |  983808.000 |  23424.000 | GET    | /fonts/glyphicons-halflings-regular.woff            |
...
...
(以下略)
ラベル意味
COUNTリクエスト回数
MINアクセスの最小時間
MAXアクセスの最大時間
SUMアクセスの合計時間
AVGアクセスの平均時間
P11パーセンタイル
P5050パーセンタイル
P9999パーセンタイル
STDDEV標準偏差
MIN(BODY)レスポンスのサイズ
MAX(BODY)レスポンスの最大サイズ
SUM(BODY)レスポンスの合計サイズ
AVG(BODY)レスポンスの平均サイズ
METHODリクエストメソッド
URIリクエスト対象

ラベルの補足をします。

P(パーセンタイル)は全体を100としたときに小さい方から数えて何番目になるのかを示した数値で、よく聞くパーセンテージとは違うものです。

定義だけ聞くとわかりにくいのですがこちら記事で説明されている例がわかりやすいです。

例えば、あなたがあるテストを受けたとします。テスト結果が返ってきて、あなたの点数は85パーセンタイルと判定されたら、あなたの成績は上位15%である（あなたの下に85%存在する）ということです。 Pパーセンタイルの位置は、データの数をnとすると、(n+1)P/100で与えられます。

つまり、P1(1パーセンタイル)は上位99%(= 下位1%)の値、P50(50パーセンタイル)は中央値、P99(99パーセンタイル)は上位1%の値を示しています。

STDDEV(Standard Deviation、標準偏差)は、ばらつき度合いを示す指標です。

つまり、標準偏差の値が少なければ少ないほど、レスポスにばらつきが少ないことを示します。

alpの便利なオプションについて

alpには便利なオプションがたくさんあります。

詳しくはalpのリポジトリのREADMEを参考にしてください。

ここではいくつかサンプルコマンドと、サンプルの実行結果を載せます。

結果とコマンドを見比べて実際にアクセスログの内容が変わっていることを確認してみてください。

昇順でソートする場合は-rオプションを利用します。

alpではデフォルトでMAXの値をもとに表示をしているため、サンプルの結果はMAXの昇順になっています。

$ alp -r -f /var/log/nginx/access.log
+-------+-------+-------+--------+-------+-------+-------+-------+--------+------------+------------+-------------+------------+--------+-----------------------------------------------------+
| COUNT |  MIN  |  MAX  |  SUM   |  AVG  |  P1   |  P50  |  P99  | STDDEV | MIN(BODY)  | MAX(BODY)  |  SUM(BODY)  | AVG(BODY)  | METHOD |                         URI                         |
+-------+-------+-------+--------+-------+-------+-------+-------+--------+------------+------------+-------------+------------+--------+-----------------------------------------------------+
|     4 | 2.510 | 3.758 | 13.183 | 3.296 | 2.510 | 3.175 | 3.740 |  0.511 |      0.000 |      0.000 |       0.000 |      0.000 | GET    | /icons/cc70e74a366a09da57f028a4317043d40e48afcc.png |
|     1 | 3.758 | 3.758 |  3.758 | 3.758 | 3.758 | 3.758 | 3.758 |  0.000 |      0.000 |      0.000 |       0.000 |      0.000 | GET    | /icons/2917ace8d8d4e5e1df4e4ce8f6bf03c1fb9ab162.png |
|     8 | 1.502 | 3.758 | 22.552 | 2.819 | 1.502 | 2.941 | 3.572 |  0.764 |      0.000 |      0.000 |       0.000 |      0.000 | GET    | /icons/aa8c2a9a793eb1414c45fd2f46f08096d5f7cb69.png |
|     5 | 1.450 | 3.758 | 14.346 | 2.869 | 1.450 | 2.858 | 3.408 |  0.787 |      0.000 |  91551.000 |   91551.000 |  18310.200 | GET    | /icons/1d76784a308ce4cabc26ee143e6be5ac64eaa494.png |
|    29 | 0.003 | 3.750 | 72.956 | 2.516 | 0.003 | 2.589 | 3.667 |  0.860 |      0.000 |   3009.000 |   21261.000 |    733.138 | GET    | /fetch                                              |
|     7 | 1.615 | 3.745 | 17.434 | 2.491 | 1.615 | 1.741 | 3.096 |  0.774 |      0.000 | 105173.000 |  105173.000 |  15024.714 | GET    | /icons/e58ed7194ed4a99d9d6ada9e3383983edcbd1edc.png |
|     7 | 1.543 | 3.738 | 21.034 | 3.005 | 1.543 | 3.007 | 3.526 |  0.699 |      0.000 | 672881.000 |  672881.000 |  96125.857 | GET    | /icons/f0a6a8334e2b9b3f49c39ce35a19a2d20e648aab.png |
...
...
(以下略)

合計値でソートする場合は--sumオプションを利用します。

-rと組み合わせることで合計値の昇順でソートされます。

$ alp --sum -r -f /var/log/nginx/access.log
+-------+--------+--------+---------+--------+--------+--------+--------+--------+------------+------------+-------------+------------+--------+-----------------------------------------------------+
| COUNT |  MIN   |  MAX   |   SUM   |  AVG   |   P1   |  P50   |  P99   | STDDEV | MIN(BODY)  | MAX(BODY)  |  SUM(BODY)  | AVG(BODY)  | METHOD |                         URI                         |
+-------+--------+--------+---------+--------+--------+--------+--------+--------+------------+------------+-------------+------------+--------+-----------------------------------------------------+
|    30 |  0.010 | 10.253 | 227.594 |  7.586 |  0.010 | 10.005 | 10.016 |  3.781 |      0.000 |   3009.000 |   27273.000 |    909.100 | GET    | /fetch                                              |
|    15 |  8.689 | 10.323 | 146.364 |  9.758 |  8.689 |  9.945 | 10.014 |  0.415 |      0.000 | 329742.000 |  329742.000 |  21982.800 | GET    | /icons/4222f36590fbd90f9b7179efaa582ae51c777c52.jpg |
|    14 |  2.086 | 10.322 | 131.262 |  9.376 |  2.086 | 10.001 | 10.289 |  2.043 |      0.000 |      0.000 |       0.000 |      0.000 | GET    | /icons/ec48374ca1b2693ca643041659fb8372c72d1ddd.png |
|    14 |  5.256 | 10.244 | 130.185 |  9.299 |  5.256 | 10.000 | 10.117 |  1.367 |      0.000 | 430334.000 |  430334.000 |  30738.143 | GET    | /icons/d9efb5732e0ee53618bd10d2ddc5a6b33edc4751.png |
|    14 |  3.377 | 10.007 | 124.925 |  8.923 |  3.377 |  9.635 | 10.007 |  1.950 |      0.000 | 103094.000 |  103094.000 |   7363.857 | GET    | /icons/c434098fec37fd0d2c1e646d104220f6ffabbea7.png |
|    13 |  4.026 | 10.007 | 119.399 |  9.185 |  4.026 |  9.404 | 10.006 |  1.538 |      0.000 | 478119.000 |  478119.000 |  36778.385 | GET    | /icons/8e4c19ddf58b761c97bbfcf7e6279f0c793c4156.png |
|    12 |  9.241 | 10.006 | 118.095 |  9.841 |  9.241 | 10.000 | 10.005 |  0.270 |      0.000 |      0.000 |       0.000 |      0.000 | GET    | /icons/2917ace8d8d4e5e1df4e4ce8f6bf03c1fb9ab162.png |
...
...
(以下略)

--aggregatesオプションを利用すれば正規表現でアクセスログを集計できます。

合計値の昇順でソートし、/icons/.*に関するレスポンスをまとめたい場合は以下のようにします。

$ alp --sum -r -f /var/log/nginx/access.log --aggregates='/icons/.＊'
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+-------------+------------+--------+-------------------------------------------+
| COUNT |  MIN  |  MAX  |   SUM   |  AVG  |  P1   |  P50  |  P99  | STDDEV | MIN(BODY)  | MAX(BODY)  |  SUM(BODY)  | AVG(BODY)  | METHOD |                    URI                    |
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+-------------+------------+--------+-------------------------------------------+
|   248 | 1.450 | 3.758 | 685.615 | 2.765 | 1.468 | 2.927 | 3.758 |  0.732 |      0.000 | 687385.000 | 8670602.000 |  34962.105 | GET    | /icons/.*                                 |
|    29 | 0.003 | 3.750 |  72.956 | 2.516 | 0.003 | 2.589 | 3.667 |  0.860 |      0.000 |   3009.000 |   21261.000 |    733.138 | GET    | /fetch                                    |
|    48 | 0.005 | 2.547 |  54.411 | 1.134 | 0.005 | 1.116 | 2.374 |  0.656 |      3.000 |  88664.000 | 3876907.000 |  80768.896 | GET    | /message                                  |
|   179 | 0.003 | 3.001 |  48.423 | 0.271 | 0.003 | 0.009 | 2.215 |  0.584 |      0.000 |    212.000 |   36581.000 |    204.363 | POST   | /login                                    |
|    10 | 1.712 | 2.940 |  24.805 | 2.481 | 1.712 | 2.785 | 2.897 |  0.483 |      0.000 |      0.000 |       0.000 |      0.000 | GET    | /channel/373                              |
|    11 | 0.623 | 3.223 |  23.778 | 2.162 | 0.623 | 1.806 | 3.054 |  0.752 |      0.000 |   3020.000 |    3020.000 |    274.545 | GET    | /channel/439                              |
|     7 | 0.008 | 3.696 |  14.891 | 2.127 | 0.008 | 1.077 | 3.582 |  1.407 |      0.000 |    209.000 |     836.000 |    119.429 | GET    | /logout                                   |
|    20 | 0.303 | 0.774 |  10.536 | 0.527 | 0.303 | 0.542 | 0.682 |  0.107 |   3021.000 |   3038.000 |   60531.000 |   3026.550 | GET    | /channel/10                               |
...
...
(以下略)

まとめ

以上でalpの手順とalpを利用したNginxのアクセスログ解析の方法について説明を終わります。

プロファイリングツールのインストールはISUCON当日必ずやることなので、事前に手順書を用意しておくとよいでしょう。

この記事がいいなと思いましたらツイッター(@nishina555)のフォローもよろしくお願いします！

タグ: ISUCON , nginx , パフォーマンスチューニング