やり方

とりあえず、現状自分たちが考えることができる理想的な方法で、過去問を解いてみる。

参考資料

https://speakerdeck.com/fujiwara3/isucon-summer-school-1 https://speakerdeck.com/fujiwara3/isucon-summer-school-2

環境を作る

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

# 1時間以上かかるので、暇な時にやっておくと良い
➜  isucon git clone git@github.com:matsuu/vagrant-isucon.git
➜  vagrant-isucon git:(master) cd ./vagrant-isucon/isucon6-qualifier-standalone
➜  isucon6-qualifier-standalone git:(master) vagrant up

ベンチマークを取ってみる

➜  isucon6-qualifier-standalone git:(master) vagrant ssh
ubuntu@ubuntu-xenial:~$ sudo -i -u isucon
isucon@ubuntu-xenial:~$ cd isucon6q
isucon@ubuntu-xenial:~/isucon6q$ ./isucon6q-bench -target http://127.0.0.1
2017/10/09 11:35:16 start pre-checking
2017/10/09 11:35:22 pre-check finished and start main benchmarking
2017/10/09 11:36:16 benchmarking finished

nginxのプロファイリング

# alpのinstall
root@ubuntu-xenial:~# wget https://github.com/tkuchiki/alp/releases/download/v0.3.1/alp_linux_amd64.zip
root@ubuntu-xenial:~# apt install unzip
root@ubuntu-xenial:~# unzip alp_linux_amd64.zip
root@ubuntu-xenial:~# install ./alp /usr/local/bin/

#ベンチマーク実行
isucon@ubuntu-xenial:~/isucon6q$ cd isucon6q/
isucon@ubuntu-xenial:~/isucon6q$ ./isucon6q-bench -target http://127.0.0.1

#alp実行
root@ubuntu-xenial:~# alp --sum -r -f /var/log/nginx/access_log --aggregates='/keywords/.*'
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+--------------------------------------------------------+
| COUNT |  MIN  |  MAX  |   SUM   |  AVG  |  P1   |  P50  |  P99  | STDDEV | MIN(BODY)  | MAX(BODY)  |  SUM(BODY)   | AVG(BODY)  | METHOD |                          URI                           |
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+--------------------------------------------------------+
|    68 | 1.147 | 7.731 | 323.394 | 4.756 | 1.147 | 4.726 | 7.696 |  1.423 |   7894.000 | 108819.000 |  4688744.000 |  68952.118 | GET    | /                                                      |
|   270 | 0.001 | 4.718 | 274.573 | 1.017 | 0.001 | 0.882 | 4.559 |  0.943 | 106015.000 | 106015.000 | 28624050.000 | 106015.000 | GET    | /css/bootstrap.min.css                                 |
|   135 | 0.001 | 4.710 | 137.316 | 1.017 | 0.001 | 0.856 | 4.154 |  0.942 |  28631.000 |  28631.000 |  3865185.000 |  28631.000 | GET    | /js/bootstrap.min.js                                   |
|   135 | 0.001 | 4.711 | 137.077 | 1.015 | 0.000 | 0.868 | 4.152 |  0.942 |  16849.000 |  16849.000 |  2274615.000 |  16849.000 | GET    | /css/bootstrap-responsive.min.css                      |
|   135 | 0.001 | 4.710 | 136.959 | 1.015 | 0.001 | 0.859 | 4.153 |  0.942 |  86351.000 |  86351.000 | 11657385.000 |  86351.000 | GET    | /js/jquery.min.js                                      |
|   135 | 0.001 | 4.709 | 136.811 | 1.013 | 0.000 | 0.872 | 4.150 |  0.943 |   1092.000 |   1092.000 |   147420.000 |   1092.000 | GET    | /favicon.ico                                           |
|   135 | 0.001 | 4.709 | 136.020 | 1.008 | 0.000 | 0.852 | 4.148 |  0.941 |     93.000 |     93.000 |    12555.000 |     93.000 | GET    | /img/star.gif                                          |
|    57 | 0.003 | 3.001 |  63.052 | 1.106 | 0.003 | 1.046 | 3.000 |  0.802 |     25.000 |    335.000 |     2615.000 |     45.877 | POST   | /stars                                                 |
|    67 | 0.001 | 3.006 |  59.732 | 0.892 | 0.001 | 0.714 | 3.001 |  0.779 |      5.000 |    335.000 |     3615.000 |     53.955 | POST   | /login                                                 |
|    41 | 0.032 | 3.002 |  49.207 | 1.200 | 0.032 | 0.969 | 3.001 |  0.886 |      5.000 |    331.000 |     6374.000 |    155.463 | POST   | /keyword

mysqlのプロファイリング

root@ubuntu-xenial:~# vim /etc/mysql/my.cnf
[mysqld]
slow_query_log  = 1
slow_query_log_file = /var/log/mysql/slow.log
long_query_time = 0

root@ubuntu-xenial:~# systemctl restart mysql
root@ubuntu-xenial:~# systemctl restart isuda.ruby
root@ubuntu-xenial:~# systemctl restart isutar.ruby

root@ubuntu-xenial:~# head -20 /var/log/mysql/slow.log
/usr/sbin/mysqld, Version: 5.7.19-0ubuntu0.16.04.1-log ((Ubuntu)). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument
# Time: 2017-10-09T05:02:00.742015Z
# User@Host: isucon[isucon] @ localhost []  Id:     4
# Query_time: 0.000143  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
use isuda;
SET timestamp=1507525320;
SET SESSION sql_mode='TRADITIONAL,NO_AUTO_VALUE_ON_ZERO,ONLY_FULL_GROUP_BY';
# Time: 2017-10-09T05:02:00.746467Z
# User@Host: isucon[isucon] @ localhost []  Id:     4
# Query_time: 0.004247  Lock_time: 0.003866 Rows_sent: 2  Rows_examined: 4
SET timestamp=1507525320;
SELECT * FROM entry
        ORDER BY updated_at DESC
        LIMIT 10
        OFFSET 0;
# Time: 2017-10-09T05:02:00.747545Z
# User@Host: isucon[isucon] @ localhost []  Id:     4
# Query_time: 0.000388  Lock_time: 0.000143 Rows_sent: 2  Rows_examined: 4

root@ubuntu-xenial:~# wget https://www.percona.com/downloads/percona-toolkit/3.0.4/binary/debian/xenial/x86_64/percona-toolkit_3.0.4-1.xenial_amd64.deb
root@ubuntu-xenial:~# apt install libdbd-mysql-perl libdbi-perl libio-socket-ssl-perl libnet-ssleay-perl libterm-readkey-perl

# Profile
# Rank Query ID           Response time Calls R/Call V/M   Item
# ==== ================== ============= ===== ====== ===== ===============
#    1 0x6C987DBB94BEC091 43.9842 96.9%   414 0.1062  0.13 SELECT entry
#    2 0x51C26B78ABE63960  0.6851  1.5%    28 0.0245  0.00 INSERT SELECT UPDATE entry
#    3 0x0C85264D3C24C18B  0.3384  0.7%    44 0.0077  0.09 SELECT entry
#    4 0x782FEBA311BC59ED  0.1392  0.3%   414 0.0003  0.00 SELECT star
#    5 0xF32185B56AEF3A1D  0.0631  0.1%    44 0.0014  0.00 SELECT entry
#    6 0x7E7900C7AF4DD0A4  0.0440  0.1%    23 0.0019  0.00 INSERT star
#    7 0x6FF06CCB4B4E1FAC  0.0261  0.1%    17 0.0015  0.00 INSERT UPDATE entry
#    8 0x41883793B68D128E  0.0235  0.1%    82 0.0003  0.00 SELECT user
#    9 0x16F15936BC5B2382  0.0224  0.0%    70 0.0003  0.00 SELECT entry
#   10 0x87B0C6DEA95CEF2E  0.0201  0.0%    84 0.0002  0.00 SELECT user
# MISC 0xMISC              0.0312  0.1%    59 0.0005   0.0 <32 ITEMS>

上から順番に遅いやつ。

# Query 1: 0.70 QPS, 0.07x concurrency, ID 0x6C987DBB94BEC091 at byte 28601055
# Scores: V/M = 0.13
# Time range: 2017-10-09T05:24:22 to 2017-10-09T05:34:12
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         32     414
# Exec time     96     44s   129us      1s   106ms   266ms   117ms    75ms
# Lock time     39    64ms    40us     5ms   153us   224us   361us    93us
# Rows sent     99   2.70M       1   6.94k   6.67k   6.63k   1.28k   6.63k
# Rows examine  91   5.40M       2  13.89k  13.34k  13.78k   2.66k  13.78k
# Query size     0  23.85k      59      59      59      59       0      59
# String:
# Databases    isuda
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us  ###
#   1ms
#  10ms  ################################################################
# 100ms  ###########################
#    1s  #
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isuda` LIKE 'entry'\G
#    SHOW CREATE TABLE `isuda`.`entry`\G
# EXPLAIN /*!50100 PARTITIONS*/
select * from entry order by character_length(keyword) desc\G

改善作業に入る

step1 不要なカラムを読み込まないようにする

# before
keywords = db.xquery(%| select * from entry order by character_length(keyword) desc |)

# after
keywords = db.xquery(%| select keyword from entry order by character_length(keyword) desc |)

# Query 1: 17.68 QPS, 0.14x concurrency, ID 0x8AC9E716A43D8A44 at byte 610435
# Scores: V/M = 0.00
# Time range: 2017-10-09T05:57:41 to 2017-10-09T05:58:44
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         37    1114
# Exec time     89      9s     5ms   103ms     8ms    16ms     6ms     6ms
# Lock time     34   111ms    45us     4ms    99us   144us   138us    80us
# Rows sent     99   7.55M   6.93k   6.95k   6.94k   6.63k       0   6.63k
# Rows examine  92  15.11M  13.87k  13.90k  13.89k  13.78k       0  13.78k
# Query size    21  70.71k      65      65      65      65       0      65
# String:
# Databases    isuda
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms  ###############
# 100ms  #
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isuda` LIKE 'entry'\G
#    SHOW CREATE TABLE `isuda`.`entry`\G
# EXPLAIN /*!50100 PARTITIONS*/
select keyword from entry order by character_length(keyword) desc\G

isucon@ubuntu-xenial:~/isucon6q$ ./isucon6q-bench -target http://127.0.0.1
2017/10/09 14:57:41 start pre-checking
2017/10/09 14:57:45 pre-check finished and start main benchmarking
2017/10/09 14:58:41 benchmarking finished
{"pass":true,"score":4719,"success":1918,"fail":1,"messages":["リクエストがタイムアウトしました (POST /stars)"]}

step2 何度も実行されないようにする

#before
      entries.each do |entry|
        entry[:html] = htmlify(entry[:description])
        entry[:stars] = load_stars(entry[:keyword])
      end

#after
    keywords = 
    entries.each do |entry|
      entry[:html] = htmlify(keywords, entry[:description])
      entry[:stars] = load_stars(entry[:keyword])
    end

# Query 1: 4.67 QPS, 0.04x concurrency, ID 0x8AC9E716A43D8A44 at byte 687529
# Scores: V/M = 0.00
# Time range: 2017-10-09T06:04:42 to 2017-10-09T06:05:54
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         13     336
# Exec time     69      3s     5ms    54ms     9ms    17ms     5ms     6ms
# Lock time      9    28ms    32us   287us    83us   144us    33us    73us
# Rows sent     99   2.28M   6.93k   6.95k   6.94k   6.63k       0   6.63k
# Rows examine  73   4.56M  13.87k  13.90k  13.89k  13.78k    0.00  13.78k
# Query size     7  21.33k      65      65      65      65       0      65
# String:
# Databases    isuda
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms  ############################
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isuda` LIKE 'entry'\G
#    SHOW CREATE TABLE `isuda`.`entry`\G
# EXPLAIN /*!50100 PARTITIONS*/
select keyword from entry order by character_length(keyword) desc\G

isucon@ubuntu-xenial:~/isucon6q$ ./isucon6q-bench -target http://127.0.0.1
2017/10/09 15:04:42 start pre-checking
2017/10/09 15:04:47 pre-check finished and start main benchmarking
2017/10/09 15:05:42 benchmarking finished
{"pass":true,"score":5051,"success":2093,"fail":1,"messages":["リクエストがタイムアウトしました (POST /keyword)"]}

step3 assetsをnginxで返す

root@ubuntu-xenial:~# alp --sum -r -f /var/log/nginx/access.log --aggregates='/keywords/.*'
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+---------------------------------------------+
| COUNT |  MIN  |  MAX  |   SUM   |  AVG  |  P1   |  P50  |  P99  | STDDEV | MIN(BODY)  | MAX(BODY)  |  SUM(BODY)   | AVG(BODY)  | METHOD |                     URI                     |
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+---------------------------------------------+
|   114 | 0.645 | 6.417 | 314.101 | 2.755 | 0.645 | 2.723 | 4.654 |  0.862 |   7960.000 |  93210.000 |  4816125.000 |  42246.711 | GET    | /                                           |
|   456 | 0.001 | 3.043 | 278.135 | 0.610 | 0.002 | 0.503 | 2.131 |  0.497 | 106015.000 | 106015.000 | 48342840.000 | 106015.000 | GET    | /css/bootstrap.min.css                      |
|   228 | 0.001 | 3.038 | 140.322 | 0.615 | 0.001 | 0.511 | 2.059 |  0.496 |  28631.000 |  28631.000 |  6527868.000 |  28631.000 | GET    | /js/bootstrap.min.js                        |
|   228 | 0.001 | 3.039 | 140.048 | 0.614 | 0.002 | 0.513 | 2.060 |  0.496 |  86351.000 |  86351.000 | 19688028.000 |  86351.000 | GET    | /js/jquery.min.js                           |
|   228 | 0.002 | 3.044 | 139.345 | 0.611 | 0.002 | 0.505 | 2.062 |  0.497 |  16849.000 |  16849.000 |  3841572.000 |  16849.000 | GET    | /css/bootstrap-responsive.min.css           |
|   228 | 0.001 | 3.038 | 138.529 | 0.608 | 0.001 | 0.509 | 2.058 |  0.497 |   1092.000 |   1092.000 |   248976.000 |   1092.000 | GET    | /favicon.ico                                |
|   228 | 0.001 | 3.027 | 137.308 | 0.602 | 0.001 | 0.498 | 2.057 |  0.495 |     93.000 |     93.000 |    21204.000 |     93.000 | GET    | /img/star.gif

やっぱり / 重いけれども、まずはすぐにできそうな assetsまわりからやってみる。

        location ~ ^/(img|css|js|favicon.ico){
            root /home/isucon/webapp/public;
        }

isucon@ubuntu-xenial:~/isucon6q$ ./isucon6q-bench -target http://127.0.0.1
2017/10/09 15:15:16 start pre-checking
2017/10/09 15:15:20 pre-check finished and start main benchmarking
2017/10/09 15:16:16 benchmarking finished
{"pass":true,"score":5258,"success":2380,"fail":2,"messages":["リクエストがタイムアウトしました (POST /stars)"]}

200 score早くなった。

step4 失敗しているリクエストをなくす

isucon@ubuntu-xenial:~/isucon6q$ ./isucon6q-bench -target http://127.0.0.1
{"pass":true,"score":3779,"success":1851,"fail":4,"messages":["starがついていません (GET /)","リクエストがタイムアウトしました (POST /stars)","讃岐典侍日記 に 1109年 へのリンクがありません (GET /)"]}

これを見ると POST /stars でtimeoutしている。

    post '/stars' do
      keyword = params[:keyword]
      isuda_keyword_url = URI(settings.isuda_origin)
      isuda_keyword_url.path = '/keyword/%s' % [Rack::Utils.escape_path(keyword)]
      res = Net::HTTP.get_response(isuda_keyword_url)
      halt(404) unless Net::HTTPSuccess === res

POST /stars では GET /keyword/:keyword を実行している。 GET /keyword/:keyword の検索がなかなか遅いので、こいつをなんとかしなければならない。

root@ubuntu-xenial:~# alp --sum -r -f /var/log/nginx/access.log --aggregates='/keywords/.*'
|     8 | 1.287 | 3.497 |   19.388 | 2.423 | 1.287 | 2.553 | 2.927 |  0.671 |  11924.000 |  11928.000 |     95408.000 |  11926.000 | GET    | /keyword/巨大基数

なぜ遅いのか見てみる。

mysql> desc star;
+------------+---------------------+------+-----+---------+----------------+
| Field      | Type                | Null | Key | Default | Extra          |
+------------+---------------------+------+-----+---------+----------------+
| id         | bigint(20) unsigned | NO   | PRI | NULL    | auto_increment |
| keyword    | varchar(191)        | NO   |     | NULL    |                |
| user_name  | varchar(191)        | NO   |     | NULL    |                |
| created_at | datetime            | YES  |     | NULL    |                |
+------------+---------------------+------+-----+---------+----------------+

keywordにindexが貼られていない。keywordにindexを貼っておく。

isucon@ubuntu-xenial:~/isucon6q$ ./isucon6q-bench -target http://127.0.0.1
2017/10/09 16:01:56 start pre-checking
2017/10/09 16:01:59 pre-check finished and start main benchmarking
2017/10/09 16:02:56 benchmarking finished
{"pass":true,"score":5671,"success":2476,"fail":0,"messages":[]}

300 scoreあがった。

5step `get /`をなんとかする。

root@ubuntu-xenial:~# alp --sum -r -f /var/log/nginx/access.log --aggregates='/keywords/.*'
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+-------------------------------------------------------+
| COUNT |  MIN  |  MAX  |   SUM   |  AVG  |  P1   |  P50  |  P99  | STDDEV | MIN(BODY)  | MAX(BODY)  |  SUM(BODY)   | AVG(BODY)  | METHOD |                          URI                          |
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+-------------------------------------------------------+
|   101 | 0.709 | 7.417 | 345.768 | 3.423 | 0.709 | 3.317 | 6.436 |  1.414 |   7960.000 | 162448.000 |  5027564.000 |  49777.861 | GET    | /                                                     |

      keywords = db.xquery(%| select keyword from entry order by character_length(keyword) desc |)
      entries.each do |entry|
        entry[:html] = htmlify(keywords, entry[:description])
        entry[:stars] = load_stars(entry[:keyword])
      end

ここを、下記のようにできるのは無いか。

      keywords = db.xquery(%| select keyword from entry order by character_length(keyword) desc |)
      stars = load_stars(keywords)
      
      entries.each do |entry|
        entry[:html] = htmlify(keywords, entry[:description])
        entry[:stars] = stars[entry[:keyword]]
      end

今日は一旦ここまで

その他

再起動用script

#!/bin/sh

set -e

now=`date +%Y%m%d-%H%M%S`
mv /var/log/nginx/access.log /var/log/nginx/access.log.$now
systemctl restart nginx

mv /var/log/mysql/slow.log /var/log/mysql/slow.log.$now
mysqladmin -uisucon -pisucon flush-logs

systemctl restart isuda.ruby
systemctl restart isutar.ruby

過去問の作業ログ

当日の作業の流れ

環境確認

githubでコード管理
アプリケーションの動作確認: ブラウザでさわってみる、どんなプロセス動いてるとか
運営側から提供されているベンチマークを実行
マシンスペックの確認(core数とか重要そう)

計測

alpでアクセスログが出せるように設定
MySQLのログ設定
ベンチマーク実行
各種ログ確認：nginxのログとか、MySQLのslow logとか
ボトルネックの洗い出し

selmertsxの素振り日記

ひたすら日々の素振り内容を書き続けるだけの日記

isucon6の過去問を解く

やり方

参考資料

環境を作る

ベンチマークを取ってみる

nginxのプロファイリング

mysqlのプロファイリング

改善作業に入る

step1 不要なカラムを読み込まないようにする

step2 何度も実行されないようにする

step3 assetsをnginxで返す

step4 失敗しているリクエストをなくす

5step `get /`をなんとかする。

その他

再起動用script

過去問の作業ログ

当日の作業の流れ

環境確認

計測

やり方

参考資料

環境を作る

ベンチマークを取ってみる

nginxのプロファイリング

mysqlのプロファイリング

改善作業に入る

step1 不要なカラムを読み込まないようにする

step2 何度も実行されないようにする

step3 assetsをnginxで返す

step4 失敗しているリクエストをなくす

5step get /をなんとかする。

その他

再起動用script

過去問の作業ログ

当日の作業の流れ

環境確認

計測

5step `get /`をなんとかする。