ISUCON11 素振り
流石に練習しとかないとヤバいな…という気持ちになったので練習する
素振り環境の構築
以前解いたことのあるISUCON10の予選問題を元に素振り環境を作っていく。
インスタンスタイプ: t2.small
CPU: 1 Core
メモリ: 2GB
ストレージ: 16GB
IP: 18.183.153.63
インスタンス が立ち上がったことを確認
キーペア使ってインスタンスにログイン。
code:console
$ ssh -i isucon10-qualify-keypair.pem ubuntu@18.183.153.63
インスタンスの状態を確認する。
code:console
$ sudo apt install dstat
$ dstat
You did not select any stats, using -cdngy by default.
--total-cpu-usage-- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai stl| read writ| recv send| in out | int csw
8 2 83 5 1| 667k 1710k| 0 0 | 0 0 | 86 363
0 0 100 0 0| 0 0 | 52B 1066B| 0 0 | 25 70
0 0 100 0 0| 0 0 | 104B 436B| 0 0 | 19 49
0 0 100 0 0| 0 0 | 52B 436B| 0 0 | 19 51
0 0 100 0 0| 0 0 | 104B 436B| 0 0 | 16 45
0 0 100 0 0| 0 0 | 104B 436B| 0 0 | 18 47
$ htop
HTTPでブラウザからもアクセスしてみる。
https://gyazo.com/10414f34b98ca9b526e90ae1b5568bdc
OKOK.
ベンチマークを走らせてみる
インスタンスタイプ: t2.large
CPU: 2 Core
メモリ: 16GB
ストレージ: 16GB
IP: 172.31.0.20
ベンチマーク用インスタンスにsshして、以下のコマンドを実行。
code:console
$ sudo su isucon
2021/07/24 10:43:58 bench.go:78: === initialize ===
2021/07/24 10:44:00 bench.go:90: === verify ===
2021/07/24 10:44:01 bench.go:100: === validation ===
2021/07/24 10:44:39 load.go:181: 負荷レベルが上昇しました。
...
2021/07/24 10:45:01 bench.go:102: 最終的な負荷レベル: 1
nazotte 失敗しているけどスコア出ているので大丈夫そう。
スコアを mackerel に送信するようにしておく
スコアの変遷が分かったほうが盛り上がるのでサクッとやる。
まず mackerel のダッシュボードから Service を作成する
名前はisucon10-qualifyにした
mackerel の API キーを発行
こちらも名前はisucon10-qualifyで
ベンチマーク用インスタンスにログインして、所々のセットアップをしつつベンチマークを実行する
code:console
$ sudo apt-get install mkr
$ export MACKEREL_APIKEY=...
$ echo "score.mizdra $(./bench --target-url http://18.183.153.63 | jq '.score') $(date +%s)" | mkr throw --service isucon10-qualify https://gyazo.com/5b838a7164beb6b94251d02023af3343
OKOK
ssh_config書いておく
適当に以下のようにしておく
code:console
Host isu01
HostName 18.183.153.63
User ubuntu
IdentityFile ~/src/github.com/mizdra/isucon10-qualify/isucon10-qualify-keypair.pem
Host bench
HostName 18.181.81.211
User ubuntu
IdentityFile ~/src/github.com/mizdra/isucon10-qualify/isucon10-qualify-keypair.pem
構成を確認する
準備も終わったのでどういう構成になっているのか見ていく。
80 portをlistenするプロセスを確認
code:console
$ sudo lsof -i:80
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
nginx 17825 root 6u IPv4 21174 0t0 TCP *:http (LISTEN)
nginx 17825 root 7u IPv6 21267 0t0 TCP *:http (LISTEN)
nginx 17828 www-data 6u IPv4 21174 0t0 TCP *:http (LISTEN)
nginx 17828 www-data 7u IPv6 21267 0t0 TCP *:http (LISTEN)
nginxだった
service一覧確認 (注: 主要なもの以外は省略)
code:console
$ systemctl list-unit-files --type=service | grep enabled
...
isuumo.go.service enabled
...
mysql.service enabled
...
nginx.service enabled
...
ssh.service enabled
sshd.service enabled
初期状態で動いているのはGo実装
mysqlとnginxが裏で動いている模様
まあ分かってきた
コードを引っこ抜いてくる
いつもどおりコードを引っこ抜いてくる。
まず引っこ抜いたコードの置き場を作っておく
色々コピーしてくる
code:console
$ cd ~/src/github.com/mizdra/isucon10-qualify
$ rsync -av isu1:/home/isucon/isuumo/webapp/go .
$ rsync -av isu1:/etc/nginx/sites-available nginx/
$ rsync -av isu1:/etc/nginx/nginx.conf nginx/
$ rsync -av isu1:/home/isucon/env.sh .
$ rsync -av isu1:/etc/mysql/conf.d mysql/
$ rsync -av isu1:/etc/mysql/mysql.conf.d mysql/
rsync便利〜
ついでにデプロイスクリプトも書く
rsync便利〜
計測していく
本当はレギュレーション見たり、アプリケーション触ったりする時間必要だけど、以前解いたことあるのでスキップして、早速計測していく。
何からやろうかな〜
スローログ、alpあたり?
アクセスログを計測・分析する
mizdra.icon nginx -s reloadハマった...
アクセスログ分析には alp を使う (なぜならこれしか知らないから…)
ローカルでインストールする
code:console
$ brew install alp
ベンチ走らせて...
code:console
$ ./bench.sh
log/ にログが fetch されるので、これをalpで見ていく
適当に-mでグルーピングしつつ、-r --sort=sumでsumで降順にする
code:text
$ cat log/access.log | alp ltsv -r --sort=sum -m "/api/estate/req_doc/\d+,/api/recommended_estate/\d+,/api/estate/\d+,/api/chair/\d+,/api/chair/buy/\d+"
https://gyazo.com/f160787f3c9519abcac3754e79bf4aef
気になるところ
いくつか 4XX がある
上位5件が支配的
/api/estate/searchと/api/chair/searchが特に支配的
/api/estate/nazotteは上位2件に劣るが、リクエストが少ない割に極端に遅い
/api/estate/nazotteのreqtimeの標準偏差がデカい
あんま気にしなくても良い気はする
スローログを計測・分析する
mizdra.icon sudo mysqladmin flush-logsハマった…
mizdra.icon ついでにベンチマークを envchain mackerel ./benchで走らせるようにした
スローログ分析にはpt-query-digestを使う (なぜならこれしか知らないから…)
ローカル側で以下を実行
code:console
$ brew install percona-toolkit
$ pt-query-digest log/mysql-slow.log
# 710ms user time, 40ms system time, 32.71M rss, 4.15G vsz
# Current date: Sun Jul 25 02:26:42 2021
# Hostname: yukari.local
# Files: log/mysql-slow.log
# Overall: 4.61k total, 64 unique, 75.52 QPS, 6.70x concurrency __________
# Time range: 2021-07-24T17:18:29 to 2021-07-24T17:19:30
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 409s 19ms 280ms 89ms 141ms 27ms 82ms
# Lock time 233ms 15us 9ms 50us 38us 298us 23us
# Rows sent 77.36k 0 1.31k 17.19 24.84 44.20 19.46
# Rows examine 131.92M 28.81k 30.61k 29.32k 28.66k 48.31 28.66k
# Query size 441.65k 46 341 98.17 329.68 63.03 76.28
# Profile
# Rank Query ID Response time Calls R/Call V/M
# ==== =================================== ============= ===== ====== ====
# 1 0x3D7F9AD8D0B5ECFA387A1968AED87BF9 34.0790 8.3% 258 0.1321 0.01 SELECT estate
# 2 0x1592B6A6C5962A79A3BBB20FFD7BCE7C 33.8324 8.3% 369 0.0917 0.00 SELECT chair
# 3 0xF8D9C0871992B1AF9C572B62B2210476 30.4821 7.5% 369 0.0826 0.01 SELECT estate
# 4 0x07E5ED76C7A93E48E37BD5D8F0FF2FDE 30.1879 7.4% 326 0.0926 0.01 SELECT estate
# 5 0x7239C60E5785569730222108492FF4F7 25.7644 6.3% 326 0.0790 0.01 SELECT estate
# 6 0xDAF418A1CBFF50D9A9A4F380692DE1C8 19.7056 4.8% 207 0.0952 0.01 SELECT chair
# 7 0x4E8EAE12D58B73C2F3EFAD4903F0402F 15.6442 3.8% 207 0.0756 0.01 SELECT chair
# 8 0x644E34B4F9AC414D9810769325CA5A5E 12.4593 3.0% 144 0.0865 0.01 SELECT estate
# 9 0x5DE2A94FD483D5087F578E6167724DBF 12.3404 3.0% 149 0.0828 0.01 SELECT estate
# 10 0x747A5415F890FCD0F418F8958C3A84C3 10.9075 2.7% 114 0.0957 0.01 SELECT estate
# 11 0xBF1444BD9A8EAD17F291508A52D09114 10.4871 2.6% 149 0.0704 0.01 SELECT estate
# 12 0x4CD8BC51141C351DC73BFA73427CD78F 10.4402 2.6% 144 0.0725 0.00 SELECT estate
# 13 0x55402B93A43729A085DF0F23BB694539 9.8489 2.4% 77 0.1279 0.00 SELECT estate
# 14 0x929E86BFE887C4E10B23D92EDD8D61BC 9.3345 2.3% 114 0.0819 0.01 SELECT estate
# 15 0x2F6A8881D435EE788EED46376BCF2AE3 8.8825 2.2% 90 0.0987 0.01 SELECT estate
# 16 0xE5EB3FC758DE6E117FEEE42B5C7412D2 8.4652 2.1% 84 0.1008 0.01 SELECT chair
# 17 0x4A8E12431038633B5ADF2C461C6F48FE 8.2783 2.0% 73 0.1134 0.01 SELECT chair
# 18 0xED731470FE91D25E31E27AD9C15C891F 7.6682 1.9% 90 0.0852 0.01 SELECT estate
# 19 0x85EDDA9F02FE0A0E65DBB57A0B593F83 6.8963 1.7% 84 0.0821 0.01 SELECT chair
# 20 0x3D16910D1C54800461F4988BE0D150F8 6.8867 1.7% 69 0.0998 0.01 SELECT chair
# MISC 0xMISC 96.2208 23.5% 1164 0.0827 0.0 <44 ITEMS>
...
mizdra.icon 見方が全く分からない!
思ったこと
特に見どころなさそう
どうせ index 貼ったら大きく傾向変わるので、また後で見に来れば良い
スキーマを取り出す
そういえばスキーマまだ取り出していないこと思い出したので、取り出す。
isu01 で以下を実行
code:console
$ mysqldump -uisucon -pisucon --no-data isuumo
出力をリポジトリにコピペ
マイグレーションスクリプトも用意しておく
テーブルサイズも見ておく
以下を mysql console で実行
code:sql
SELECT
TABLE_NAME
, ENGINE
, TABLE_ROWS -- レコード数
, AVG_ROW_LENGTH -- 平均レコード容量
, FLOOR((DATA_LENGTH + INDEX_LENGTH) / 1024 / 1024) AS "SIZE(MB)" -- 合計容量
, FLOOR((DATA_LENGTH) / 1024 / 1024) AS "DATA_SIZE(MB)" -- データ容量
, FLOOR((INDEX_LENGTH) / 1024 / 1024) AS "INDEX_SIZE(MB)" -- インデックス容量
FROM
INFORMATION_SCHEMA.TABLES
WHERE
TABLE_SCHEMA = DATABASE()
ORDER BY
(DATA_LENGTH + INDEX_LENGTH) DESC
;
実行結果:
code:text
+------------+--------+------------+----------------+----------+---------------+----------------+
| TABLE_NAME | ENGINE | TABLE_ROWS | AVG_ROW_LENGTH | SIZE(MB) | DATA_SIZE(MB) | INDEX_SIZE(MB) |
+------------+--------+------------+----------------+----------+---------------+----------------+
| estate | InnoDB | 29137 | 522 | 14 | 14 | 0 |
| chair | InnoDB | 29163 | 485 | 13 | 13 | 0 |
+------------+--------+------------+----------------+----------+---------------+----------------+
2 rows in set (0.00 sec)
気づいたこと
テーブルはたったの2つ
index が無
あとはアプリケーションからどういう使われ方しているか見ないとなんとも
ベンチマーク実行中のパフォーマンスを計測する
どうせ後で傾向変わるけど、どこから改善するかの取っ掛かりを掴むのに重要なので、計測しておく
ベンチマーク実行前に isu01 で各種計測ツールを立ち上げておく
code:console
$ dstat
$ htop
動画撮ろう
シークバー弄りながら見返せて便利
https://youtu.be/lAz3mol7x1A
読み方
思ったこと
CPUが常に100%に張り付いている
mysqlが支配的
メモリは余裕ある
見た感じでは mysql の CPU 使用率下げないことにはどうにも、という感じがする
次何やるか決める
各種測定終わったので改善していく
まず mysql の CPU 使用率下げたい
試しに index 貼ったり、パラメータ見直したりしてみる
index 貼っていく
とりあえず index 貼っていこう
index 貼るべきところを洗い出す
=> 全部 1 よりかなり大きい値だった…
まあ rank の上のほうから index 貼っていけば良いかな
index の仕組みについて読んでおく
分かりやすい
index の貼り方
これは最高の記事だった
where 句と order by 句を併用している SQL に対する index の貼り方の話
上から順に貼っていく
SELECT * FROM estate WHERE (door_width >= 102 AND door_height >= 78) OR (door_width >= 102 AND door_height >= 61) OR (door_width >= 78 AND door_height >= 102) OR (door_width >= 78 AND door_height >= 61) OR (door_width >= 61 AND door_height >= 102) OR (door_width >= 61 AND door_height >= 78) ORDER BY popularity DESC, id ASC LIMIT 20
door_widthとdoor_heightの2つのindexを貼りたいけど、比較演算子使っているので無駄
多分 index 貼るよりデータ構造とか見直したほうが良い
というかそもそも WHERE で index 使えないので全スキャンになる気がする
mizdra.icon一旦後回しで
SELECT * FROM chair WHERE stock > 0 ORDER BY price ASC, id ASC LIMIT 20\G
(stock)かな
SELECT * FROM estate ORDER BY rent ASC, id ASC LIMIT 20\G
(rent, id)かな
SELECT * FROM estate WHERE rent >= 50000 AND rent < 100000 ORDER BY popularity DESC, id ASC LIMIT 25 OFFSET 0\G
(rent)かな
SELECT COUNT(*) FROM estate WHERE rent >= 50000 AND rent < 100000\G
(rent)かな
SELECT * FROM chair WHERE price >= 9000 AND price < 12000 AND stock > 0 ORDER BY popularity DESC, id ASC LIMIT 25 OFFSET 25\G
(price) / (stock)かな
SELECT COUNT(*) FROM chair WHERE price >= 9000 AND price < 12000 AND stock > 0\G
(price) / (stock)かな
SELECT * FROM estate WHERE rent < 50000 ORDER BY popularity DESC, id ASC LIMIT 25 OFFSET 0\G
(rent)かな
とりあえずこれくらいにして、index貼って様子見てみる
スコア: 459 => 556
ちょっと上がった!
試しに余分に index 貼ってみたら、503 になった
やはり効果なさそう
ストレージが足りていないという可能性はある
次何やろう
index は貼り終わったので、発行される SQL の見直しとかかなー
発行される SQL の改善
alp.log 見ながら、遅いエンドポイントで発行されている SQL を順に倒していく
556 => 872
nazotte 改善
nazotte が明らかに遅い (タイムアウトもしている) ので、改善する
872 => 973
nazotte のタイムアウトもなくなった
が、代わりに他のAPIでレスポンスエラーになりはじめた
恐らく負荷が上がって色々なリクエストが届くようになったためだろう
次何やろう
htop 見てみる
mysql: 65%
go: 20〜25%
nginx: 10%
nginx 仕事してない
backendからnginxに負荷を寄せていく
そもそもbackendに届くリクエストが多すぎるので、
振り返り
素振り環境用のインスタンスのスペック、ちょっと強すぎたかも
ログの clear でハマりがちだった
index 貼るのに時間掛けすぎた
最小限で最大効率の index 貼ろうとしていた
別に最小限である必要はあまりないので、適当に貼ればよかったかも