来年の isucon で泣かずに予選を終える為のメモ（1）

• tl;dr
• isucon6予選の反省点
• 過去問や解析ツールのメモ
  — Apache / Nginx アクセスログの解析
  — MySQL スローログの解析
  — アプリケーションの解析
  — 過去問 matsuu さんに感謝
  — isucon5 の予選で利用された問題を展開する例
• ボクがログインしたらやれそうなこと…
  — これだったら出来そう
  — Nginx ログの解析
  — MySQL SlowLog 取得の設定
  — アプリケーション解析の設定
• ひとまず

tl;dr

isucon6 予選は何も出来ずに涙を飲んだので、来年は少しでも手を動かせるように過去問を触りながら isucon の雰囲気に慣れていきたい。

isucon6 予選の反省点

• どの言語でとか等のチーム方針が明確では無かった
• チーム方針が明確では無かったので当然役割分担も不明瞭だった
• 過去問に触れずに挑んだ為、何をすれば良いのか全く解らなかった
• 各種解析ツールの存在、使い方に慣れていなかった（そもそも使ったことが無かった）
• データベースに関する知識、経験がほぼ 0 だった為、データベースのチューニングには全く手を付けることが出来なかった

ということで、今回は過去問を起動するところから、解析ツールを仕込むところまでやってみる。

過去問や解析ツールのメモ

Apache / Nginx アクセスログの解析

• https://github.com/matsuu/kataribe
• https://github.com/tkuchiki/alp

MySQL スローログの解析

• https://www.percona.com/doc/percona-toolkit/2.2/pt-query-digest.html

アプリケーションの解析

• Ruby（Rack アプリケーション）
• https://github.com/kainosnoema/rack-lineprof
• Python(WSGI アプリケーション)
• http://werkzeug.pocoo.org/docs/0.11/contrib/profiler/

過去問 matsuu さんに感謝

• https://github.com/matsuu/vagrant-isucon

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 = <
上記のように行ごとに処理に要した時間が出力される。

ひとまず
解析する為の仕込みは出来た。ただ、これらから何を読み取って、どこを改善していくか…ここからが本当の isucon なんだと思う。
元記事はこちら
「来年の isucon で泣かずに予選を終える為のメモ（1）」