tl;dr
isucon6 予選は何も出来ずに涙を飲んだので、来年は少しでも手を動かせるように過去問を触りながら isucon の雰囲気に慣れていきたい。
isucon6 予選の反省点
- どの言語でとか等のチーム方針が明確では無かった
- チーム方針が明確では無かったので当然役割分担も不明瞭だった
- 過去問に触れずに挑んだ為、何をすれば良いのか全く解らなかった
- 各種解析ツールの存在、使い方に慣れていなかった（そもそも使ったことが無かった）
- データベースに関する知識、経験がほぼ 0 だった為、データベースのチューニングには全く手を付けることが出来なかった
ということで、今回は過去問を起動するところから、解析ツールを仕込むところまでやってみる。
過去問や解析ツールのメモ
Apache / Nginx アクセスログの解析
MySQL スローログの解析
アプリケーションの解析
- Ruby（Rack アプリケーション）
- https://github.com/kainosnoema/rack-lineprof
- Python(WSGI アプリケーション)
- http://werkzeug.pocoo.org/docs/0.11/contrib/profiler/
過去問 matsuu さんに感謝
isucon2 から isucon5 まで用意されており、各過去問が vagrant 一発で起動させることが出来る。
isucon5 の予選で利用された問題を展開する例
$ git clone https://github.com/matsuu/vagrant-isucon.git
$ cd isucon5-qualifier-standalone
vagrant up
ブラウザでアクセスしたい場合には Vagrantfile を以下のように修正する。
$ diff -u Vagrantfile.original Vagrantfile --- Vagrantfile.original 2016-09-25 11:35:04.349082426 +0900 +++ Vagrantfile 2016-09-24 21:27:00.276552570 +0900 @@ -28,7 +28,7 @@ # Create a private network, which allows host-only access to the machine # using a specific IP. - # config.vm.network "private_network", ip: "192.168.33.10" + config.vm.network "private_network", ip: "192.168.33.10" # Create a public network, which generally matched to bridged network. # Bridged networks make the machine appear as another physical device on
ボクがログインしたらやれそうなこと...
これだったら出来そう
- Nginx ログの解析
- MySQL SlowLog 取得の設定
- アプリケーション解析の設定
Nginx ログの解析
- alp を使う場合に Nginx のアクセスログフォーマットを ltsv 形式に設定する
http { log_format ltsv "time:$time_local" "\thost:$remote_addr" "\tforwardedfor:$http_x_forwarded_for" "\treq:$request" "\tstatus:$status" "\tmethod:$request_method" "\turi:$request_uri" "\tsize:$body_bytes_sent" "\treferer:$http_referer" "\tua:$http_user_agent" "\treqtime:$request_time" "\tcache:$upstream_http_x_cache" "\truntime:$upstream_http_x_runtime" "\tapptime:$upstream_response_time" "\tvhost:$host"; access_log /var/log/nginx/access.log ltsv; upstream app { server 127.0.0.1:8080; } server { location / { proxy_set_header Host $host; proxy_pass http://app; } } }
- alp でログ解析
$ sudo cat /var/log/nginx/access.log | ./alp -r | less +-------+-------+-------+---------+-------+-------+-------+-------+--------+-----------+------------+-------------+-----------+--------+------------------------------------+ | COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI | +-------+-------+-------+---------+-------+-------+-------+-------+--------+-----------+------------+-------------+-----------+--------+------------------------------------+ | 207 | 0.001 | 2.669 | 225.738 | 1.091 | 0.001 | 1.012 | 2.548 | 0.612 | 16285.000 | 16791.000 | 2966944.000 | 14333.063 | GET | / | | 3 | 0.654 | 2.499 | 3.875 | 1.292 | 0.654 | 0.654 | 0.722 | 0.854 | 3476.000 | 3747.000 | 10970.000 | 3656.667 | GET | /diary/entry/489651 | | 9 | 0.013 | 2.292 | 3.258 | 0.362 | 0.013 | 0.025 | 0.588 | 0.704 | 53984.000 | 61469.000 | 530916.000 | 58990.667 | GET | /diary/entries/verlie_crooks151 (snip)
MySQL SlowLog 取得の設定
- my.cnf に設定を追加
[mysqld] (snip) slow_query_log = 1 slow_query_log_file = /var/log/mysql/mysqld-slow.log long_query_time = 0 log-queries-not-using-indexes =
- pt-query-digest で解析
$ sudo pt-query-digest /var/log/mysql/mysqld-slow.log # 1.3s user time, 0 system time, 28.45M rss, 85.27M vsz # Current date: Sun Sep 25 11:54:50 2016 # Hostname: vagrant # Files: /var/log/mysql/mysqld-slow.log # Overall: 7.45k total, 27 unique, 2.45 QPS, 0.00x concurrency ___________ # Time range: 2016-09-25 08:22:49 to 09:13:31 # Attribute total min max avg 95% stddev median # ============ ======= ======= ======= ======= ======= ======= ======= # Exec time 3s 3us 204ms 432us 247us 6ms 113us # Lock time 238ms 0 2ms 31us 44us 38us 27us # Rows sent 21.36k 0 1000 2.94 0.99 40.61 0.99 # Rows examine 5.71M 0 488.50k 804.05 0.99 19.01k 0 # Query size 817.88k 11 226 112.42 112.70 19.13 112.70 # Profile # Rank Query ID Response time Calls R/Call V/M Item # ==== ================== ============= ===== ====== ===== =============== # 1 0xDE6DD0309F9386F8 1.0643 33.1% 6 0.1774 0.00 SELECT relations # 2 0xD44150558D8295E1 0.9162 28.5% 6942 0.0001 0.00 SELECT relations # 3 0x492C7CAB538DE80D 0.8483 26.3% 6 0.1414 0.00 SELECT footprints # 4 0x064A5B2042FC8316 0.2127 6.6% 7 0.0304 0.01 SELECT entries # 5 0xCE3E456E0D0EFD1C 0.0584 1.8% 6 0.0097 0.01 SELECT comments entries # MISC 0xMISC 0.1200 3.7% 483 0.0002 0.0 <22 ITEMS> # Query 1: 0.00 QPS, 0.00x concurrency, ID 0xDE6DD0309F9386F8 at byte 317533 # Scores: V/M = 0.00 # Time range: 2016-09-25 08:23:03 to 09:13:31 # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count 0 6 # Exec time 33 1s 168ms 204ms 177ms 198ms 13ms 163ms # Lock time 0 176us 28us 32us 29us 31us 1us 28us # Rows sent 5 1.24k 212 212 212 212 0 212 # Rows examine 49 2.83M 483.53k 483.53k 483.53k 483.53k 0 483.53k # Query size 0 522 87 87 87 87 0 87 # String: # Databases isucon5q # Hosts localhost # Users root # Query_time distribution # 1us # 10us # 100us # 1ms # 10ms # 100ms ################################################################ # 1s # 10s+ # Tables # SHOW TABLE STATUS FROM `isucon5q` LIKE 'relations'\G # SHOW CREATE TABLE `isucon5q`.`relations`\G # EXPLAIN /*!50100 PARTITIONS*/ SELECT * FROM relations WHERE one = '3657' OR another = '3657' ORDER BY created_at DESC\G (snip)
アプリケーション解析の設定
- rack-lineprof を仕込む（事前に bundle install しておく）
$ diff -u app.rb.original app.rb --- app.rb.original 2016-09-25 11:59:24.195894782 +0900 +++ app.rb 2016-09-25 12:00:10.071619573 +0900 @@ -4,6 +4,7 @@ require 'tilt/erubis' require 'erubis' require 'rack-lineprof' +require 'profiler' module Isucon5 class AuthenticationError < StandardError; end @@ -18,6 +19,7 @@ end class Isucon5::WebApp < Sinatra::Base + use Rack::Lineprof use Rack::Session::Cookie set :erb, escape_html: true set :public_folder, File.expand_path('../../static', __FILE__)
- アプリケーションにアクセス
ブラウザで 192.168.33.10/?lineprof=app.rb にアクセスする。
$ sudo journalctl -f (snip) 9月 25 12:04:18 vagrant bundle[5117]: ....... 9月 25 12:04:18 vagrant bundle[5117]: | 189 entry[:title] = entry[:body].split(/\n/).first 9月 25 12:04:18 vagrant bundle[5117]: | 190 entries_of_friends << entry 9月 25 12:04:18 vagrant bundle[5117]: 2.9ms 3 | 191 break if entries_of_friends.size >= 10 9月 25 12:04:18 vagrant bundle[5117]: | 192 end 9月 25 12:04:18 vagrant bundle[5117]: | 193 9月 25 12:04:18 vagrant bundle[5117]: 151.4ms 1587 | 194 comments_of_friends = [] 9月 25 12:04:18 vagrant bundle[5117]: 114.7ms 528 | 195 db.query('SELECT * FROM comments ORDER BY created_at DESC LIMIT 1000').each do |comment| 9月 25 12:04:18 vagrant bundle[5117]: 0.4ms 20 | 196 next unless is_friend?(comment[:user_id]) 9月 25 12:04:18 vagrant bundle[5117]: | 197 entry = db.xquery('SELECT * FROM entries WHERE id = ?', comment[:entry_id]).first 9月 25 12:04:18 vagrant bundle[5117]: | 198 entry[:is_private] = (entry[:private] == 1) 9月 25 12:04:18 vagrant bundle[5117]: ....... 9月 25 12:04:18 vagrant bundle[5117]: | 200 comments_of_friends << comment 9月 25 12:04:18 vagrant bundle[5117]: | 201 break if comments_of_friends.size >= 10 9月 25 12:04:18 vagrant bundle[5117]: 151.8ms 1884 | 202 end 9月 25 12:04:18 vagrant bundle[5117]: 128.2ms 627 | 203 9月 25 12:04:18 vagrant bundle[5117]: 2.4ms 84 | 204 friends_query = 'SELECT * FROM relations WHERE one = ? OR another = ? ORDER BY created_at DESC' 9月 25 12:04:18 vagrant bundle[5117]: | 205 friends_map = {} 9月 25 12:04:18 vagrant bundle[5117]: 0.4ms 2 | 206 db.xquery(friends_query, current_user[:id], current_user[:id]).each do |rel| 9月 25 12:04:18 vagrant bundle[5117]: | 207 key = (rel[:one] == current_user[:id] ? :another : :one) 9月 25 12:04:18 vagrant bundle[5117]: | 208 friends_map[rel[key]] ||= rel[:created_at] 9月 25 12:04:18 vagrant bundle[5117]: ....... 9月 25 12:04:18 vagrant bundle[5117]: | 211 9月 25 12:04:18 vagrant bundle[5117]: | 212 query = <<SQL 9月 25 12:04:18 vagrant bundle[5117]: 170.6ms 641 | 213 SELECT user_id, owner_id, DATE(created_at) AS date, MAX(created_at) AS updated 9月 25 12:04:18 vagrant bundle[5117]: | 214 FROM footprints 9月 25 12:04:18 vagrant bundle[5117]: | 215 WHERE user_id = ? 9月 25 12:04:18 vagrant bundle[5117]: ....... (snip)
上記のように行ごとに処理に要した時間が出力される。
ひとまず
解析する為の仕込みは出来た。ただ、これらから何を読み取って、どこを改善していくか...ここからが本当の isucon なんだと思う。
