fujiwara/reguration.md Secret

## reguration.md

      
    Raw
  

              reguration.md
            
          
    ISUCON夏期講習2017 実習レギュレーション

このレギュレーションは https://github.com/isucon/isucon6-qualify/blob/master/Regulation.md を元に @fujiwara が夏期講習用に改変したものです。
ISUCON6 予選レギュレーションも併せてご確認ください。
http://isucon.net/archives/48396740.html
初期スコアについて

幾つかの初期実装は、ベンチマークはpassするものの、初期スコアが0になっています。これは不具合ではありません。
Getting Started

以下の順序で作業を開始してください。
1. インスタンスにログイン

各自に渡したIPアドレスとパスワードを入力し、インスタンスにsshでログインしてください。ユーザは ubuntu です。
ssh -l ubuntu [IPアドレス]
2. アプリケーションの動作確認

インスタンスのIPアドレスにブラウザからアクセスするとログイン画面が表示されます。
ユーザはidとパスワードでログインしますが、データベースにデフォルトで登録されているユーザは全て、パスワードはアカウント名と同じです。例えば、以下のペアが使えます。

id: motemen
パスワード: motemen

3. 負荷走行

ベンチマーク走行はインスタンス上で実行します。
cd /home/isucon/isucon6q
sudo ./isucon6q-bench
2017/08/24 17:58:01 start pre-checking
2017/08/24 17:58:19 pre-check finished and start main benchmarking
2017/08/24 17:59:01 benchmarking finished
{"pass":true,"score":0,"success":386,"fail":39,"messages":["リクエストがタイムアウトしました (GET /)","リクエストがタイムアウトしました (POST /keyword)","リクエストがタイムアウトしました (POST /login)","リクエストがタイムアウトしました (POST /stars)"]}
なおベンチマークは以下のように実施されます。

初期化処理の実行 /initialize (5秒以内)
アプリケーション互換性チェックの走行 (適宜: 数秒〜数十秒、固定リクエスト数)
負荷走行 (60秒 - 2.の互換性チェックにかかった時間)

各ステップで失敗が見付かった場合にはその時点で停止します。ただし、互換性チェック中にタイムアウトした分に関しては、失敗とみなさず、それ以外の失敗がない場合には負荷走行ステップに移行します。
参考実装の切り替え方法

各言語実装は systemd で管理されています。基本的には systemctl stop/start ならびに systemctl enable/disable で制御します。
PHPの場合

systemd での切り替えのほか、nginxの設定変更が必要です。/etc/nginx/nginx.php.conf が置いてあるのでそれを使用してください。
ルール詳細

指定されたサーバー上のアプリケーションのチューニングをおこない、それに対するベンチマークのスコアで競技をおこないます。そのサーバー1台のみでアプリケーションの動作が可能であればどのような変更を加えても構いません。
ベンチマーカーとブラウザの挙動に差異がある場合、ベンチマーカーの挙動を正とします。また初期実装毎に若干の挙動の違いはありますが、ベンチマーカーに影響のない挙動に関しては仕様とします。
スコア計算

スコアは以下のルールで算出されます。
静的ファイル配信成功数x1 + 成功GETリクエスト数x5 + 成功POSTリクエスト数x10 - (サーバエラー(error)レスポンス数x50 + リクエスト失敗(exception)数x100 + 遅延POSTレスポンス数x200)
ベンチマーカーは一定秒数でタイムアウトします。特にPOSTリクエストは、3000ミリ秒(3秒)以内にレスポンスを返す必要があり、遅れたリクエストについては大きく減点されますのでご注意ください。
以下を満たした場合リクエストが成功したと判定し、得点が加算されます。

タイムアウトせずにレスポンスを返却する
HTTPステータスコードが想定と一致する
コンテンツの内容チェックを通過する

制約事項

以下の事項に抵触すると失格(fail)となり、点数が無効として扱われます。

GET /initialize へのレスポンスが5秒以内に戻らない場合
スコアが0点
アプリケーション互換性チェックに失敗した場合
他、ベンチマークツールのチェッカが失敗を検出したケース

最初に呼ばれる初期化処理 /initialize は用意された環境内で、チェッカツールが要求する範囲の整合性を担保します。サーバサイドで処理の変更・データ構造の変更などを行う場合、この処理が行っている内容を漏れなく提供してください。またこの処理が5秒以上レスポンスを返さない場合、失格とします。
アプリケーションは全て、保存データを永続化する必要があります。つまり処理実施後に再起動が行われた場合、再起動前に行われた処理内容が再起動後に保存されている必要があります。
また、アプリケーションは、ブラウザ上での表示を初期状態と同様に保つ必要があります。

  
## slide.md

      
    Raw
  

              slide.md
            
          
    ISUCON 夏期講習 2017

実践編

2017.08.25

@fujiwara


 @fujiwara

##[fit]  @mackee_w (ISUCON2,3本選出場)
 技術部


これからの実習

ISUCON 6 予選問題(一部改変版) を体験していただきます
昨年の予選との相違点

マシンが 2コア → 3コア
ベンチがリモートではなくローカル
Go 版を一部改変
(スコアは予選と比較できないので注意)

ISUCON 7 予選について

さくらのクラウドで開催
運営がサーバーを用意する(自分で起動しない)
過去の予選は全て自分でインスタンスを起動していた
つまり今日と同じ雰囲気のはず¹

今日のレギュレーション

https://goo.gl/8SSGJy
このスライド原稿も含まれているのでコピペにご利用ください

レギュレーションを熟読する

レギュレーションは毎回異なる
事前告知される内容＋当日公開される詳細
スコアの計算方法・Success/Fail の判定条件
許可されること・されないこと
過去には
「ブラウザで表示した際の見た目を変更しない」
という項目も

まずサーバに ssh ログイン

ssh -l ubuntu [各自のサーバのIPアドレス]
パスワードと公開鍵は自由に変更してください
その後の操作は基本的に isucon ユーザーで行います
$ sudo su - isucon

サーバで pstree や ps auxwf 等を実行して
動いているプロセスを確認する
何の daemon やミドルウェアで構成されてるかを把握

どんなWebアプリなのか確認

ブラウザで http://[各自のサーバのIPアドレス]/ にアクセス
アプリケーションを把握

サーバをいじる前に

確実に戻れるようにしておく
過去の予選ではサーバを初期状態で起動し直せたが…
今回の予選と過去の本選ではサーバを壊したら__そこで終了__
レギュレーションを熟読すること(大事なことなので二回)
ISUCON 3 本選ではサーバ上の画像ファイルを失うとそこで全てが終わりました

Git 等で管理しよう

アプリケーションが配置されている /home/isucon/webapp
→ 共同作業の場合、GitHub や BitBucket のプライベートrepoにpushするのがお勧め²
OS、ミドルウェアの設定ファイルがある /etc も(rootで)
$ git init
$ git add .
$ git commit -m "first commit"


ベンチを掛けてみよう

初期実装は Perl
$ cd /home/isucon/isucon6q
$ sudo ./isucon6q-bench
2017/08/24 17:58:01 start pre-checking
2017/08/24 17:58:19 pre-check finished and start main benchmarking
2017/08/24 17:59:01 benchmarking finished
{"pass":true,"score":0,"success":386,"fail":39,"messages":[
"リクエストがタイムアウトしました (GET /)",
"リクエストがタイムアウトしました (POST /keyword)",
"リクエストがタイムアウトしました (POST /login)",
"リクエストがタイムアウトしました (POST /stars)"]}


自分の使う言語の実装に切り替えてベンチしてみよう

$ sudo -s
# systemctl stop isuda.perl
# systemctl stop isutar.perl

# systemctl start isuda.XXX
# systemctl start isutar.XXX
# journalctl -f

XXX は go js perl php python ruby scala のいずれか

ベンチを掛けながらサーバの様子を見よう

top
htop
dstat -t -a
glances

netdata - https://my-netdata.io

# bash <(curl -Ss https://my-netdata.io/kickstart-static64.sh)

ブラウザで http://サーバのアドレス:19999/ にアクセス


ボトルネックを見つける


#[fit]「推測するな計測せよ」

どこがボトルネックなのかをはっきりさせるまでは、推測を行ったり、スピードハックをしてはならない。


計測すべし。計測するまでは速度のための調整をしてはならない。³

Robert C. Pike

alpでアクセスログを解析してみよう


github.com/tkuchiki/alp Access Log Profiler
releases から alp_linux_amd64.zip をダウンロードして展開
wget https://github.com/tkuchiki/alp/releases/download/v0.3.1/alp_linux_amd64.zip
unzip alp_linux_amd64.zip
sudo install ./alp /usr/local/bin


nginx.conf に alp 用の出力を設定

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;

# rm /var/log/nginx/access.log && systemctl reload nginx

ベンチをまわしたあとに alp で解析

$ alp --sum -r -f /var/log/nginx/access.log --aggregates='/keyword/.*'

+-------+-------+--------+---------+--------+-------+--------+--------+--------+------------+------------+-------------+------------+--------+-----------------------------------+
| COUNT |  MIN  |  MAX   |   SUM   |  AVG   |  P1   |  P50   |  P99   | STDDEV | MIN(BODY)  | MAX(BODY)  |  SUM(BODY)  | AVG(BODY)  | METHOD |                URI                |
+-------+-------+--------+---------+--------+-------+--------+--------+--------+------------+------------+-------------+------------+--------+-----------------------------------+
|    31 | 1.113 | 15.001 | 323.588 | 10.438 | 1.113 | 11.023 | 15.001 |  3.934 |      0.000 |  87485.000 |  972130.000 |  31359.032 | GET    | /                                 |
|    84 | 0.001 | 10.408 | 182.531 |  2.173 | 0.001 |  1.241 | 10.406 |  2.825 | 106015.000 | 106015.000 | 8905260.000 | 106015.000 | GET    | /css/bootstrap.min.css            |
|    53 | 0.012 |  3.009 | 109.075 |  2.058 | 0.012 |  2.999 |  3.009 |  1.270 |      0.000 |    335.000 |     775.000 |     14.623 | POST   | /login                            |
|    26 | 1.036 | 10.929 |  98.640 |  3.794 | 1.036 |  3.674 |  9.501 |  2.392 |   2247.000 |  49197.000 |  172511.000 |   6635.038 | GET    | /keyword/.*                       |
|    42 | 0.001 | 10.399 |  91.376 |  2.176 | 0.001 |  1.250 | 10.188 |  2.823 |  86351.000 |  86351.000 | 3626742.000 |  86351.000 | GET    | /js/jquery.min.js                 |
|    42 | 0.000 | 10.400 |  91.264 |  2.173 | 0.000 |  1.248 | 10.189 |  2.823 |  16849.000 |  16849.000 |  707658.000 |  16849.000 | GET    | /css/bootstrap-responsive.min.css |
|    42 | 0.001 | 10.409 |  91.132 |  2.170 | 0.001 |  1.223 | 10.210 |  2.828 |   1092.000 |   1092.000 |   45864.000 |   1092.000 | GET    | /favicon.ico                      |
|    42 | 0.001 | 10.399 |  90.840 |  2.163 | 0.001 |  1.137 | 10.184 |  2.825 |  28631.000 |  28631.000 | 1202502.000 |  28631.000 | GET    | /js/bootstrap.min.js              |
|    42 | 0.001 | 10.398 |  90.706 |  2.160 | 0.001 |  1.132 | 10.180 |  2.826 |     93.000 |     93.000 |    3906.000 |     93.000 | GET    | /img/star.gif                     |
|    14 | 0.176 |  3.001 |  24.694 |  1.764 | 0.176 |  1.545 |  3.001 |  1.061 |      0.000 |    331.000 |    1023.000 |     73.071 | POST   | /keyword                          |
|    13 | 0.004 |  3.001 |  12.114 |  0.932 | 0.004 |  0.461 |  3.001 |  1.017 |      0.000 |    335.000 |     585.000 |     45.000 | POST   | /stars                            |
|     2 | 0.004 |  6.611 |   6.615 |  3.307 | 0.004 |  0.004 |  0.004 |  3.304 |      5.000 |      5.000 |      10.000 |      5.000 | GET    | /logout                           |
|     2 | 0.027 |  0.044 |   0.071 |  0.035 | 0.027 |  0.027 |  0.027 |  0.008 |     25.000 |     25.000 |      50.000 |     25.000 | GET    | /initialize                       |
+-------+-------+--------+---------+--------+-------+--------+--------+--------+------------+------------+-------------+------------+--------+-----------------------------------+


静的ファイルが重そうなので nginx で配ってみる?

location / { の前に下記をいれて
location ~ ^/(img|css|js|favicon.ico) {
    root /home/isucon/webapp/public;
}

# rm /var/log/nginx/access.log && systemctl reload nginx ⁴
もう一回ベンチして alp で解析

どうなりましたか?


静的ファイルは速くなったけど…

+-------+-------+--------+---------+--------+-------+--------+--------+--------+------------+------------+-------------+------------+--------+-----------------------------------+
| COUNT |  MIN  |  MAX   |   SUM   |  AVG   |  P1   |  P50   |  P99   | STDDEV | MIN(BODY)  | MAX(BODY)  |  SUM(BODY)  | AVG(BODY)  | METHOD |                URI                |
+-------+-------+--------+---------+--------+-------+--------+--------+--------+------------+------------+-------------+------------+--------+-----------------------------------+
|    29 | 1.632 | 15.001 | 310.129 | 10.694 | 1.632 | 11.513 | 15.000 |  4.038 |      0.000 |  54728.000 |  939499.000 |  32396.517 | GET    | /                                 |
|    36 | 0.586 | 12.471 | 197.041 |  5.473 | 0.586 |  3.888 | 12.417 |  4.025 |   2130.000 |  83098.000 |  315071.000 |   8751.972 | GET    | /keyword/.*                       |
|    63 | 0.002 |  3.000 | 132.119 |  2.097 | 0.002 |  2.418 |  3.000 |  1.157 |      5.000 |    335.000 |    1160.000 |     18.413 | POST   | /login                            |
|    22 | 0.216 |  3.001 |  48.918 |  2.224 | 0.216 |  2.629 |  3.001 |  0.951 |      0.000 |    331.000 |    1038.000 |     47.182 | POST   | /keyword                          |
|    21 | 0.004 |  3.001 |  24.217 |  1.153 | 0.004 |  0.582 |  3.001 |  1.020 |      0.000 |    335.000 |     735.000 |     35.000 | POST   | /stars                            |
|     3 | 0.001 |  1.962 |   1.970 |  0.657 | 0.001 |  0.001 |  0.007 |  0.923 |      5.000 |      5.000 |      15.000 |      5.000 | GET    | /logout                           |
|     1 | 0.130 |  0.130 |   0.130 |  0.130 | 0.130 |  0.130 |  0.130 |  0.000 |     25.000 |     25.000 |      25.000 |     25.000 | GET    | /initialize                       |
|    43 | 0.000 |  0.000 |   0.000 |  0.000 | 0.000 |  0.000 |  0.000 |  0.000 |  28631.000 |  28631.000 | 1231133.000 |  28631.000 | GET    | /js/bootstrap.min.js              |
|    43 | 0.000 |  0.000 |   0.000 |  0.000 | 0.000 |  0.000 |  0.000 |  0.000 |  16849.000 |  16849.000 |  724507.000 |  16849.000 | GET    | /css/bootstrap-responsive.min.css |
|    43 | 0.000 |  0.000 |   0.000 |  0.000 | 0.000 |  0.000 |  0.000 |  0.000 |  86351.000 |  86351.000 | 3713093.000 |  86351.000 | GET    | /js/jquery.min.js                 |
|    43 | 0.000 |  0.000 |   0.000 |  0.000 | 0.000 |  0.000 |  0.000 |  0.000 |   1092.000 |   1092.000 |   46956.000 |   1092.000 | GET    | /favicon.ico                      |
|    43 | 0.000 |  0.000 |   0.000 |  0.000 | 0.000 |  0.000 |  0.000 |  0.000 |     93.000 |     93.000 |    3999.000 |     93.000 | GET    | /img/star.gif                     |
|    86 | 0.000 |  0.000 |   0.000 |  0.000 | 0.000 |  0.000 |  0.000 |  0.000 | 106015.000 | 106015.000 | 9117290.000 | 106015.000 | GET    | /css/bootstrap.min.css            |
+-------+-------+--------+---------+--------+-------+--------+--------+--------+------------+------------+-------------+------------+--------+-----------------------------------+

スコアは大差ないはず
つまり静的ファイルはボトルネックではなかった(現時点では)

MySQLのクエリを解析しよう

/etc/mysql/my.cnf
[mysqld]
slow_query_log = 1
slow_query_log_file = /var/log/mysql/slow.log
long_query_time = 0 # 全てのクエリを出力

# systemctl restart mysql
# systemctl restart isuda.XXX
# systemctl restart isutar.XXX

アプリも再起動しないとDB接続が切れてエラーの原因に

そろそろ再起動が面倒になってきましたね

一発でできる shell script や Makefile を用意しましょう
#!/bin/sh
set -e

now=`date +%Y%m%d-%H%M%S`
mv /var/log/nginx/access.log /var/log/nginx/access.log.$now # nginxのログをローテート
systemctl reload nginx

mv /var/log/mysql/slow.log /var/log/mysql/slow.log.$now # mysqlのslowlogをローテート
mysqladmin -uisucon -pisucon flush-logs

# アプリケーションの再起動
systemctl restart isuda.XXX
systemctl restart isutar.XXX

# エラーが出てないかログを見る
journalctl -f

MySQL の slow log

# Time: 2017-08-24T10:18:22.683713Z
# User@Host: isucon[isucon] @ localhost []  Id:     4
# Query_time: 0.160908  Lock_time: 0.000241 Rows_sent: 7110  Rows_examined: 14220
SET timestamp=1503569902;
/* /home/isucon/webapp/perl/lib/Isuda/Web.pm line 235 */
SELECT * FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC;

Query_time: クエリ実行に掛かった時間
Rows_sent: クライアント(アプリ)に送信した行数
Rows_examined: 実行するために内部で読み取った行数

MySQL の slow log を解析

# mysqldumpslow /var/log/mysql/slow.log

Reading mysql slow query log from /var/log/mysql/slow.log
Count: 11  Time=0.12s (1s)  Lock=0.00s (0s)  Rows=7110.0 (78210), isucon[isucon]@localhost
  /* /home/isucon/webapp/perl/lib/Isuda/Web.pm line N */        SELECT * FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC

Count: 2  Time=0.02s (0s)  Lock=0.00s (0s)  Rows=10.0 (20), isucon[isucon]@localhost
  /* /home/isucon/webapp/perl/lib/Isuda/Web.pm line N */        SELECT * FROM entry
  ORDER BY updated_at DESC
  LIMIT N
  OFFSET N

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (1), isucon[isucon]@localhost
  /* /home/isucon/webapp/perl/lib/Isuda/Web.pm line N */        SELECT COUNT(*) FROM entry


pt-query-digest で解析

Percona Toolkit
www.percona.com/software/database-tools/percona-toolkit
# 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
# apt install libdbd-mysql-perl libdbi-perl libio-socket-ssl-perl libnet-ssleay-perl
# dpkg -i percona-toolkit_3.0.4-1.xenial_amd64.deb

pt-query-digest --limit 10 /var/log/mysql/slow.log

圧倒的に時間を食っているクエリ

# Profile
# Rank Query ID           Response time Calls R/Call V/M   Item
# ==== ================== ============= ===== ====== ===== ===============
#    1 0x6C987DBB94BEC091 36.1491 96.3%   202 0.1790  0.04 SELECT entry
#    2 0x28FC5B5D583E2DA6  0.3160  0.8%   186 0.0017  0.00 SHOW GLOBAL STATUS
#    3 0x0C85264D3C24C18B  0.3030  0.8%    19 0.0159  0.00 SELECT entry
#    4 0x6FF06CCB4B4E1FAC  0.2020  0.5%    10 0.0202  0.01 INSERT UPDATE entry
#    5 0x813031B8BBC3B329  0.1380  0.4%   372 0.0004  0.00 COMMIT
(略)
# Query 1: 2.27 QPS, 0.41x concurrency, ID 0x6C987DBB94BEC091 at byte 54680

SELECT * FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC

問題のクエリがどこから発行されてるか

ソースコードで確認しましょう
ちなみに Perl だとクエリコメントが埋まっているので一撃
/* /home/isucon/webapp/perl/lib/Isuda/Web.pm line 235 */
SELECT * FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC;

DBIx::Sunny by kazeburo 

htmlify()

エントリ内容を画面に表示するためのHTMLを生成する関数
この中で例のクエリが呼ばれている
さらにトップページではループ内で呼ばれている！
処理を読むと、実はこのクエリは SELECT * ではなく
SELECT keyword で十分

無駄なカラムをSELECTすると遅い

約20倍
# Query_time: 0.018891  Lock_time: 0.000156 Rows_sent: 7108  Rows_examined: 14216
SELECT keyword FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC;

# Query_time: 0.373342  Lock_time: 0.000047 Rows_sent: 7108  Rows_examined: 14216
SELECT * FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC;

EXPLAIN してみる

mysql> EXPLAIN SELECT keyword FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC;
+----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-----------------------------+
| id | select_type | table | partitions | type  | possible_keys | key     | key_len | ref  | rows | filtered | Extra                       |
+----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-----------------------------+
|  1 | SIMPLE      | entry | NULL       | index | NULL          | keyword | 767     | NULL | 5022 |   100.00 | Using index; Using filesort |
+----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-----------------------------+
1 row in set, 1 warning (0.00 sec)

mysql> EXPLAIN SELECT * FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC;
+----+-------------+-------+------------+------+---------------+------+---------+------+------+----------+----------------+
| id | select_type | table | partitions | type | possible_keys | key  | key_len | ref  | rows | filtered | Extra          |
+----+-------------+-------+------------+------+---------------+------+---------+------+------+----------+----------------+
|  1 | SIMPLE      | entry | NULL       | ALL  | NULL          | NULL | NULL    | NULL | 5022 |   100.00 | Using filesort |
+----+-------------+-------+------------+------+---------------+------+---------+------+------+----------+----------------+
1 row in set, 1 warning (0.00 sec)

SELECT keyword は Using Index
つまり Index を検索するだけでクエリが完了するので速い

クエリを変えてベンチしてみよう

SELECT * を SELECT keyword に変更するだけ ⁵
アプリの再起動を忘れずに

どうなりましたか？

...score 0 の人は score ではなく success の値を比較してください

やっていきましょう 🍻


(おまけ) ISUCON の傾向と対策

ISUCON は過去と同じパターンの問題は出しづらい
(出題者の心理)
現在の技術トレンドを取り込む傾向がある
ISUCON 5 予選: systemd
ISUCON 5 本選: Microservices, https
ISUCON 6 予選: Microservices
ISUCON 6 本選: React SSR, Docker, https
ISUCON 7 ???
Footnotes


ただしベンチマークはおそらくリモートだと思われます ↩


実際の予選、本選では競技中にrepoを公開してしまうと失格になるので注意 ↩


https://ja.wikipedia.org/wiki/UNIX%E5%93%B2%E5%AD%A6 ↩


ログを消したくなければ mv で保存 ↩


Go, Scala の人はコードも少し調整が必要です ↩