あいつの日誌β

あいつの日誌です。

ISCON5 予選の振り返り(1): アクセスログ

あらすじ

というわけで自習開始

最初の一歩: アクセス解析

isucon で最初にするのはベンチマークツールが何をしようとしているかを測定する事だと思います(違っていたらすいません)

という事で nginx のアクセスログを ltsv 形式に変更し、alp というツールを使ってみたいと思います

設定ファイルを確認

初期設定を一応確認しておく

$ nginx -V
nginx version: nginx/1.6.2 (Ubuntu)
TLS SNI support enabled
configure arguments: --with-cc-opt='-g -O2 -fPIE -fstack-protector-strong -Wformat -Werror=format-security -D_FORTIFY_SOURCE=2' --with-ld-opt='-Wl,-Bsymbolic-functions -fPIE -pie -Wl,-z,relro -Wl,-z,now' --prefix=/usr/share/nginx --conf-path=/etc/nginx/nginx.conf --http-log-path=/var/log/nginx/access.log --error-log-path=/var/log/nginx/error.log --lock-path=/var/lock/nginx.lock --pid-path=/run/nginx.pid --http-client-body-temp-path=/var/lib/nginx/body --http-fastcgi-temp-path=/var/lib/nginx/fastcgi --http-proxy-temp-path=/var/lib/nginx/proxy --http-scgi-temp-path=/var/lib/nginx/scgi --http-uwsgi-temp-path=/var/lib/nginx/uwsgi --with-debug --with-pcre-jit --with-ipv6 --with-http_ssl_module --with-http_stub_status_module --with-http_realip_module --with-http_auth_request_module --with-http_addition_module --with-http_dav_module --with-http_geoip_module --with-http_gzip_static_module --with-http_image_filter_module --with-http_spdy_module --with-http_sub_module --with-http_xslt_module --with-mail --with-mail_ssl_module

一応バックアップを取得しておく

$ sudo cp /etc/nginx/nginx.conf /etc/nginx/nginx.conf.bak

edit: /etc/nginx/conf.d/log_format.conf

worker_processes  1;  

events {
  worker_connections  1024;
}

http {
  upstream app {
    server 127.0.0.1:8080;
  }

  server {
    location / {
      proxy_set_header Host $host;
      proxy_pass http://app;
    }
  }

  log_format ltsv 'time:$time_local\t'
                  'status:$status\t'
                  'request_time:$request_time\t'
                  'upstream_addr:$upstream_addr\t'
                  'upstream_response_time:$upstream_response_time\t'
                  'upstream_cache_status:$upstream_cache_status\t'
                  'body_bytes_sent:$body_bytes_sent\t'
                  'remote_addr:$remote_addr\t'
                  'host:$host\t'
                  'request_method:$request_method\t'
                  'request_uri:$request_uri\t'
                  'protocol:$server_protocol\t'
                  'http_referer:$http_referer\t'
                  'http_user_agent:$http_user_agent\t'
                  'connection:$connection\t'
                  'connection_requests:$connection_requests';

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

check syntax

$ sudo nginx -t

restart nginx

$ sudo service nginx restart

アクセスログを確認し、ltsv 形式のログになっている事を確認したら 一旦 access log を削除します。その後 nginx を再起動する

$ cat /var/log/nginx/access.log
$ sudo rm /var/log/nginx/access.log
$ sudo service nginx restart

isucon で最初にするのはベンチマークツールが何をしようとしているかを測定する事だと思います(違っていたらすいません)

という事で alp というツールを使ってみたいと思います

install apl for ubunt

gcpインスタンス上で以下を操作します

$ sudo su
$ cd /usr/local/src
$ curl -sLO https://github.com/tkuchiki/alp/releases/download/v0.0.5/alp_linux_amd64.zip
$ unzip alp_linux_amd64.zip
$ mv alp_linux_amd64 /usr/local/bin/alp

アクセスログを解析。レスポンスタイムの合計値が大きい順番を調べます。

% alp --sum -rf /var/log/nginx/access.log 
+-------+-------+-------+---------+-------+------------+------------+------------+------------+--------+------------------------------------+
| COUNT |  MIN  |  MAX  |   SUM   |  AVG  | MAX(BODY)  | MIN(BODY)  | SUM(BODY)  | AVG(BODY)  | METHOD |                URI                 |
+-------+-------+-------+---------+-------+------------+------------+------------+------------+--------+------------------------------------+
| 70    | 0.001 | 5.836 | 119.756 | 1.711 |  16336.000 |  16901.000 | 904996.000 |  12928.514 | GET    | /                                  |
| 22    | 0.192 | 3.225 |  22.992 | 1.045 |  11357.000 |  14893.000 | 288459.000 |  13111.773 | GET    | /friends                           |
| 29    | 0.001 | 1.989 |  11.805 | 0.407 |      0.000 |      0.000 |      0.000 |      0.000 | POST   | /login                             |
| 13    | 0.167 | 1.741 |  11.160 | 0.858 |   6754.000 |   6860.000 |  88368.000 |   6797.538 | GET    | /footprints                        |
| 29    | 0.001 | 2.906 |   9.201 | 0.317 |   1021.000 |   1021.000 |  29609.000 |   1021.000 | GET    | /login                             |
| 11    | 0.004 | 1.455 |   8.393 | 0.763 |      0.000 |      0.000 |      0.000 |      0.000 | POST   | /diary/entry                       |
| 4     | 0.940 | 3.604 |   7.382 | 1.845 |   3335.000 |   5888.000 |  18446.000 |   4611.500 | GET    | /profile/alanis416                 |
| 2     | 0.003 | 5.835 |   5.838 | 2.919 |   3267.000 |   5869.000 |   9136.000 |   4568.000 | GET    | /profile/dusty3747                 |
| 3     | 0.233 | 2.875 |   4.714 | 1.571 |   3396.000 |   5973.000 |  15342.000 |   5114.000 | GET    | /profile/abigayle2663              |
| 2     | 0.002 | 4.650 |   4.652 | 2.326 |   3287.000 |   5881.000 |   9168.000 |   4584.000 | GET    | /profile/kim1558                   |
| 3     | 0.445 | 3.371 |   4.412 | 1.471 |   3638.000 |   3910.000 |  11458.000 |   3819.333 | GET    | /diary/entry/499435                |
| 1     | 3.631 | 3.631 |   3.631 | 3.631 |   3295.000 |   3295.000 |   3295.000 |   3295.000 | GET    | /profile/braulio_stamm4405         |
| 6     | 0.005 | 1.436 |   3.373 | 0.562 |   3641.000 |   4174.000 |  23722.000 |   3953.667 | GET    | /diary/entry/498756                |
| 2     | 1.547 | 1.640 |   3.187 | 1.593 |      0.000 |      0.000 |      0.000 |      0.000 | POST   | /diary/comment/498756              |
| 6     | 0.008 | 1.982 |   3.121 | 0.520 |  57177.000 |  62017.000 | 358598.000 |  59766.333 | GET    | /diary/entries/stacey4230          |
| 4     | 0.176 | 1.846 |   3.065 | 0.766 |   3268.000 |   5874.000 |  18284.000 |   4571.000 | GET    | /profile/stacey4230                |
| 3     | 0.002 | 2.992 |   3.035 | 1.012 |   3295.000 |   5891.000 |  12496.000 |   4165.333 | GET    | /profile/johnathan_kunze4838       |
| 1     | 2.954 | 2.954 |   2.954 | 2.954 |      0.000 |      0.000 |      0.000 |      0.000 | POST   | /friends/edyth1934                 |
| 12    | 0.001 | 2.005 |   2.714 | 0.226 |      0.000 |      0.000 |      0.000 |      0.000 | GET    | /logout                            |
| 6     | 0.002 | 1.268 |   2.690 | 0.448 |  57449.000 |  62864.000 | 299949.000 |  49991.500 | GET    | /diary/entries/alanis416           |
| 1     | 2.506 | 2.506 |   2.506 | 2.506 |      0.000 |      0.000 |      0.000 |      0.000 | POST   | /diary/comment/492049              |
| 3     | 0.177 | 1.967 |   2.491 | 0.830 |   3299.000 |   5903.000 |  12501.000 |   4167.000 | GET    | /profile/lucious4978               |
| 3     | 0.009 | 1.642 |   2.465 | 0.822 |  59507.000 |  62164.000 | 183144.000 |  61048.000 | GET    | /diary/entries/johnathan_kunze4838 |
| 3     | 0.020 | 1.441 |   2.431 | 0.810 |  58490.000 |  61152.000 | 180241.000 |  60080.333 | GET    | /diary/entries/kim1558             |
| 3     | 0.026 | 1.149 |   2.104 | 0.701 |  59911.000 |  62561.000 | 184239.000 |  61413.000 | GET    | /diary/entries/dusty3747           |
| 1     | 1.949 | 1.949 |   1.949 | 1.949 |   3473.000 |   3473.000 |   3473.000 |   3473.000 | GET    | /diary/entry/492049                |
| 3     | 0.135 | 1.536 |   1.947 | 0.649 |  59720.000 |  62376.000 | 183959.000 |  61319.667 | GET    | /diary/entries/julien1813          |
| 1     | 1.913 | 1.913 |   1.913 | 1.913 |   3259.000 |   3259.000 |   3259.000 |   3259.000 | GET    | /profile/ona336                    |
| 3     | 0.166 | 1.445 |   1.845 | 0.615 |    971.000 |   1232.000 |   3435.000 |   1145.000 | GET    | /diary/entry/500068                |
| 3     | 0.165 | 1.093 |   1.782 | 0.594 |   3638.000 |   3898.000 |  11434.000 |   3811.333 | GET    | /diary/entry/498837                |
| 2     | 0.591 | 1.190 |   1.781 | 0.890 |   3263.000 |   3263.000 |   6526.000 |   3263.000 | GET    | /profile/adonis4890                |
| 3     | 0.005 | 1.384 |   1.566 | 0.522 |   3956.000 |   4217.000 |  12390.000 |   4130.000 | GET    | /diary/entry/491192                |
| 1     | 1.548 | 1.548 |   1.548 | 1.548 |      0.000 |      0.000 |      0.000 |      0.000 | POST   | /diary/comment/498837              |
| 1     | 1.482 | 1.482 |   1.482 | 1.482 |   3578.000 |   3578.000 |   3578.000 |   3578.000 | GET    | /diary/entry/499380                |
| 2     | 0.414 | 1.064 |   1.478 | 0.739 |  60475.000 |  61144.000 | 121619.000 |  60809.500 | GET    | /diary/entries/doug_kemmer3496     |
| 2     | 0.009 | 1.403 |   1.412 | 0.706 |  60183.000 |  61023.000 | 121206.000 |  60603.000 | GET    | /diary/entries/ona336              |
| 1     | 1.399 | 1.399 |   1.399 | 1.399 |      0.000 |      0.000 |      0.000 |      0.000 | POST   | /friends/michael1263               |
| 2     | 0.654 | 0.667 |   1.321 | 0.661 |   3260.000 |   3260.000 |   6520.000 |   3260.000 | GET    | /profile/elena3579                 |
| 1     | 1.268 | 1.268 |   1.268 | 1.268 |      0.000 |      0.000 |      0.000 |      0.000 | POST   | /diary/comment/491192              |
| 3     | 0.065 | 0.800 |   1.209 | 0.403 |  59320.000 |  61927.000 | 182483.000 |  60827.667 | GET    | /diary/entries/abigayle2663        |
| 3     | 0.010 | 0.966 |   1.164 | 0.388 |   4230.000 |   4493.000 |  13216.000 |   4405.333 | GET    | /diary/entry/497935                |
| 3     | 0.052 | 0.388 |   0.804 | 0.268 |   3271.000 |   5874.000 |  12416.000 |   4138.667 | GET    | /profile/julien1813                |
| 1     | 0.721 | 0.721 |   0.721 | 0.721 |   3430.000 |   3430.000 |   3430.000 |   3430.000 | GET    | /profile/joaquin_cremin3108        |
| 3     | 0.013 | 0.557 |   0.616 | 0.205 |   3635.000 |   3897.000 |  11429.000 |   3809.667 | GET    | /diary/entry/499740                |
| 1     | 0.537 | 0.537 |   0.537 | 0.537 |   3357.000 |   3357.000 |   3357.000 |   3357.000 | GET    | /profile/doug_kemmer3496           |
| 1     | 0.467 | 0.467 |   0.467 | 0.467 |      0.000 |      0.000 |      0.000 |      0.000 | POST   | /diary/comment/499435              |
| 3     | 0.008 | 0.369 |   0.386 | 0.129 |  59909.000 |  62560.000 | 183515.000 |  61171.667 | GET    | /diary/entries/lucious4978         |
| 3     | 0.012 | 0.342 |   0.382 | 0.127 |  58993.000 |  61639.000 | 179625.000 |  59875.000 | GET    | /diary/entries/bertram_walsh763    |
| 3     | 0.015 | 0.321 |   0.378 | 0.126 |   3638.000 |   3905.000 |  11448.000 |   3816.000 | GET    | /diary/entry/498636                |
| 1     | 0.175 | 0.175 |   0.175 | 0.175 |      0.000 |      0.000 |      0.000 |      0.000 | POST   | /friends/joana794                  |
| 1     | 0.171 | 0.171 |   0.171 | 0.171 |      0.000 |      0.000 |      0.000 |      0.000 | POST   | /friends/victor_jones326           |
| 1     | 0.171 | 0.171 |   0.171 | 0.171 |      0.000 |      0.000 |      0.000 |      0.000 | POST   | /diary/comment/499380              |
| 2     | 0.005 | 0.033 |   0.038 | 0.019 |   3324.000 |   3354.000 |   6678.000 |   3339.000 | GET    | /profile/bertram_walsh763          |
| 3     | 0.002 | 0.006 |   0.013 | 0.004 |    490.000 |   1077.000 |   2644.000 |    881.333 | GET    | /diary/entry/500063                |
| 1     | 0.013 | 0.013 |   0.013 | 0.013 |      0.000 |      0.000 |      0.000 |      0.000 | GET    | /initialize                        |
| 1     | 0.008 | 0.008 |   0.008 | 0.008 |      0.000 |      0.000 |      0.000 |      0.000 | POST   | /diary/comment/498636              |
| 1     | 0.007 | 0.007 |   0.007 | 0.007 |      0.000 |      0.000 |      0.000 |      0.000 | POST   | /diary/comment/499740              |
| 1     | 0.005 | 0.005 |   0.005 | 0.005 |      0.000 |      0.000 |      0.000 |      0.000 | POST   | /friends/glen4851                  |
| 1     | 0.005 | 0.005 |   0.005 | 0.005 |      0.000 |      0.000 |      0.000 |      0.000 | POST   | /diary/comment/4810                |
| 1     | 0.004 | 0.004 |   0.004 | 0.004 |      0.000 |      0.000 |      0.000 |      0.000 | POST   | /diary/comment/497935              |
| 1     | 0.004 | 0.004 |   0.004 | 0.004 |      0.000 |      0.000 |      0.000 |      0.000 | POST   | /profile/bertram_walsh763          |
| 1     | 0.004 | 0.004 |   0.004 | 0.004 |      0.000 |      0.000 |      0.000 |      0.000 | POST   | /diary/comment/500068              |
| 1     | 0.002 | 0.002 |   0.002 | 0.002 | 122540.000 | 122540.000 | 122540.000 | 122540.000 | GET    | /css/bootstrap.min.css             |
+-------+-------+-------+---------+-------+------------+------------+------------+------------+--------+------------------------------------+

という事でどのリクエストで問題が起きているかが分かりやすくなると思います。