あらすじ
というわけで自習開始
最初の一歩: アクセス解析
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
$ 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 | +-------+-------+-------+---------+-------+------------+------------+------------+------------+--------+------------------------------------+
という事でどのリクエストで問題が起きているかが分かりやすくなると思います。
