先週末にisucon11-prior(事前講習のハンズオン課題)をやったのでメモ
- 結果
- コンテキスト
- 事前にやったこと:AMI作成
- 8時間の素振りでやったこと一覧
- AMI起動してベンチ即実行
- NewRelicやSentryを仕込む
- APとDBとbenchを分離
- pumaの設定調整
- NewRelicの設定がうまく反映されていなかったので修正
- get_reservationsのN+1を修正
- POST /api/reservationsのループを修正
- POST /api/reservationsでINSERT後にSELECTしてるのが無駄だったのでINSERT時にcreated_atを入れるようにした
- current_userのメモ化
- GET /api/schedules のN+1修正(不完全)
- sinatraでindex.htmlを返さないようにした
- generate_idでSELECTするのをやめた
- POST /api/signupでINSERT後にSELECTするのをやめた
- netdataをDBサーバに流す
- 前の方にやった「GET /api/schedules のN+1修正(不完全)」をrevert
- GET /api/schedules のN+1修正(完全版)
- reservationsにindexつけた
- POST /api/schedules でINSERT後にSELECTしないようにした
- 2台目のAP追加
- DBとnginxを同居
- netdataを3台に増やした
- parallelismを40にした
- 設定調整祭
- parallelismを20に戻した
- 終了直前対応(その1)
- puma設定修正
- 終了直前対応(その2)
- 感想戦
- 感想
結果
最終的なサーバ構成
スペックはいずれもc5.large
コンテキスト
- 1人チーム
事前にやったこと:AMI作成
AMIの作り方は https://github.com/matsuu/vagrant-isucon11-prior がむっちゃ参考になりました。
作成手順
- ubuntu-focalでEC2インスタンスを作る
- sshでログイン
ssh -i /path/to/ec2_key_pair.pem ubuntu@PUBLIC_IP
- EC2インスタンス内で https://github.com/matsuu/vagrant-isucon11-prior/blob/655df852ee1539e763b1fb82c0251a43d333c33a/Vagrantfile#L78-L91 を1行ずつ実行
- エラーになったらsudoをつけて再実行
- ログアウトしてAMIを作成開始
- AMIの作成後にEC2インスタンスを止めるか削除する
AMIから起動したEC2インスタンスへisuconユーザでログインする方法
ubuntuユーザでログイン後にauthorized_keysをコピーするのが楽
- ubuntuユーザでログイン
ssh -i /path/to/ec2_key_pair.pem ubuntu@PUBLIC_IP
- EC2インスタンス内で下記を実行
sudo cp /home/ubuntu/.ssh/authorized_keys /home/isucon/.ssh/authorized_keys
- isuconユーザでログイン
ssh -i /path/to/ec2_key_pair.pem isucon@PUBLIC_IP
8時間の素振りでやったこと一覧
- 時系列順
- 本番を想定して10〜18時で素振りをしてます
AMI起動してベンチ即実行
この時点ではbenchとAPが同一
10:12:14.150419 ERR: validation: invalid: overbooking at 01FCM7DTTC8C6Y3B4PVR073T4C 10:12:14.447652 score: 1765(1815 - 50) : pass 10:12:14.447664 deduction: 50 / timeout: 0
NewRelicやSentryを仕込む
11:28:15.032062 SCORE: create-schedule: 18 11:28:15.032074 SCORE: create-reservation: 1239 11:28:15.032086 SCORE: login: 235 11:28:15.032094 SCORE: signup: 234 11:28:15.032164 score: 1554(1654 - 100) : pass 11:28:15.032171 deduction: 100 / timeout: 0
APとDBとbenchを分離
この時点のAPサーバのAMIを作って、そのAMIからDBサーバを作成
11:46:06.535986 SCORE: login: 242 11:46:06.536002 SCORE: signup: 241 11:46:06.536005 SCORE: create-schedule: 19 11:46:06.536007 SCORE: create-reservation: 1298 11:46:06.536010 score: 1730(1730 - 0) : pass 11:46:06.536012 deduction: 0 / timeout: 0
pumaの設定調整
root = File.expand_path('..', __dir__) # workers 1 directory root rackup File.join(root, 'config.ru') bind 'tcp://0.0.0.0:9292' environment ENV.fetch('RACK_ENV') { 'development' } pidfile File.join(root, 'tmp', 'puma.pid') threads 0, 32 workers 32 preload_app! log_requests false # for puma 5+ # Recommended 0.001~0.010(default 0.005) wait_for_less_busy_worker 0.005 nakayoshi_fork true
wait_for_less_busy_worker
と nakayoshi_fork
は下記参照
11:51:03.549932 SCORE: create-reservation: 1581 11:51:03.549946 SCORE: login: 292 11:51:03.549952 SCORE: signup: 291 11:51:03.549962 SCORE: create-schedule: 22 11:51:03.550041 score: 2092(2093 - 1) : pass 11:51:03.550050 deduction: 1 / timeout: 2
NewRelicの設定がうまく反映されていなかったので修正
12:03:43.493894 deduction: 0 / timeout: 1 12:03:55.091536 SCORE: login: 220 12:03:55.091551 SCORE: signup: 219 12:03:55.091554 SCORE: create-schedule: 17 12:03:55.091557 SCORE: create-reservation: 1157 12:03:55.091591 score: 1547(1547 - 0) : pass 12:03:55.091598 deduction: 0 / timeout: 1
get_reservationsのN+1を修正
https://github.com/isucon/isucon11-prior/blob/aea2af2bdfdeab5905f60bdb79292b0ef44dd354/webapp/ruby/app.rb#L46-L50 がN+1だったので下記のようにして1クエリでとれるように修正
def get_reservations(schedule) sql = <<~SQL SELECT r.id AS reservation_id, r.schedule_id AS reservation_schedule_id, r.user_id AS reservation_user_id, r.created_at AS reservation_created_at, u.id AS user_id, u.email AS user_email, u.nickname AS user_nickname, u.staff AS user_staff, u.created_at AS user_created_at FROM `reservations` AS r INNER JOIN users u ON u.id = r.user_id WHERE r.schedule_id = ? SQL rows = db.xquery(sql, schedule[:id]) reservations = rows.each_with_object([]) do |row, reservations| reservation = { id: row[:reservation_id], schedule_id: row[:reservation_schedule_id], user_id: row[:reservation_user_id], created_at: row[:reservation_created_at], } reservation[:user] = { id: row[:user_id], email: row[:user_email], nickname: row[:user_nickname], staff: row[:user_staff], created_at: row[:user_created_at], } reservation[:user][:email] = '' if !current_user || !current_user[:staff] reservations << reservation end
12:18:30.912796 SCORE: create-schedule: 18 12:18:30.912813 SCORE: create-reservation: 1294 12:18:30.912825 SCORE: login: 250 12:18:30.912832 SCORE: signup: 249 12:18:30.912839 score: 1724(1724 - 0) : pass 12:18:30.912846 deduction: 0 / timeout: 0
POST /api/reservationsのループを修正
https://github.com/isucon/isucon11-prior/blob/aea2af2bdfdeab5905f60bdb79292b0ef44dd354/webapp/ruby/app.rb#L149-L152 のループが無駄だったので下記のようにSQLでcountとるようにした
reserved = tx.xquery('SELECT COUNT(*) as cnt FROM `reservations` WHERE `schedule_id` = ?', schedule_id).first[:cnt].to_i
12:40:14.739025 SCORE: login: 272 12:40:14.739040 SCORE: signup: 271 12:40:14.739233 SCORE: create-schedule: 22 12:40:14.739238 SCORE: create-reservation: 1437 12:40:14.739271 score: 1929(1929 - 0) : pass 12:40:14.739277 deduction: 0 / timeout: 2
POST /api/reservationsでINSERT後にSELECTしてるのが無駄だったのでINSERT時にcreated_atを入れるようにした
created_at = Time.now tx.xquery('INSERT INTO `reservations` (`id`, `schedule_id`, `user_id`, `created_at`) VALUES (?, ?, ?, ?)', id, schedule_id, user_id, created_at)
のようにした
12:43:37.171543 SCORE: login: 242 12:43:37.171557 SCORE: create-schedule: 14 12:43:37.171567 SCORE: signup: 241 12:43:37.171570 SCORE: create-reservation: 1280 12:43:37.171576 score: 1662(1662 - 0) : pass 12:43:37.171585 deduction: 0 / timeout: 0
current_userのメモ化
NewRelic見てたらむっちゃusersへのSELECTが多くて気になって調べたら current_user
で毎回SELECTしてたのでメモ化した
def current_user @current_user ||= db.xquery('SELECT * FROM `users` WHERE `id` = ? LIMIT 1', session[:user_id]).first end
のようにするだけでスコアが倍になって大爆笑した記憶
12:48:49.106668 SCORE: create-schedule: 38 12:48:49.106677 SCORE: signup: 492 12:48:49.106728 SCORE: create-reservation: 2604 12:48:49.106767 SCORE: login: 493 12:48:49.106930 score: 3326(3477 - 151) : pass 12:48:49.106938 deduction: 151 / timeout: 0
GET /api/schedules のN+1修正(不完全)
https://github.com/isucon/isucon11-prior/blob/aea2af2bdfdeab5905f60bdb79292b0ef44dd354/webapp/ruby/app.rb#L164-L167 のN+1を下記のように修正
sql = <<~SQL SELECT s.id AS id, s.title AS title, s.capacity AS capacity, s.created_at AS created_at, r.reserved AS reserved FROM `schedules` AS s INNER JOIN ( SELECT schedule_id, COUNT(*) AS reserved FROM reservations GROUP BY schedule_id ) r ON s.id = r.schedule_id ORDER BY s.id DESC SQL schedules = db.xquery(sql)
スコアは増えてるんだけど同時にベンチマーカーでpanic出すようになって謎だった。この時点ではよくわからんのでそのまま進めた
13:00:14.156606 deduction: 0 / timeout: 4 13:00:17.157713 SCORE: create-schedule: 710 13:00:17.157731 SCORE: login: 7 13:00:17.157735 SCORE: signup: 6 13:00:17.157986 score: 7107(7107 - 0) : pass 13:00:17.157995 deduction: 0 / timeout: 4 panic: runtime error: index out of range [-1] goroutine 75533 [running]: main.(*Scenario).Validation.func1(0x7d08e8, 0xc0008d4420, 0xffffffffffffffff) /home/isuadmin/src/isucon11-prior/benchmarker/scenario.go:304 +0xeec github.com/isucon/isucandar/worker.(*Worker).processInfinity.func1(0x7d08e8, 0xc0008d4420) /home/isuadmin/go/pkg/mod/github.com/isucon/isucandar@v0.0.0-20210609100057-baa52484de01/worker/worker.go:72 +0x46 github.com/isucon/isucandar/parallel.(*Parallel).Do.func1(0xc000a58d80, 0xc000312a80, 0x0) /home/isuadmin/go/pkg/mod/github.com/isucon/isucandar@v0.0.0-20210609100057-baa52484de01/parallel/parallel.go:68 +0x73 created by github.com/isucon/isucandar/parallel.(*Parallel).Do /home/isuadmin/go/pkg/mod/github.com/isucon/isucandar@v0.0.0-20210609100057-baa52484de01/parallel/parallel.go:66 +0xa6
sinatraでindex.htmlを返さないようにした
https://github.com/isucon/isucon11-prior/blob/aea2af2bdfdeab5905f60bdb79292b0ef44dd354/webapp/ruby/app.rb#L182-L184 でsinatraで静的ファイルを読み込んで返しているのが無駄だったので、下記のようにnginxで返すようにした
location /initialize { try_files $uri @webapp; } location /api/ { try_files $uri @webapp; } location ^~ / { }
13:16:12.892609 SCORE: signup: 6 13:16:12.892626 SCORE: login: 7 13:16:12.892631 SCORE: create-schedule: 855 13:16:12.893000 score: 8557(8557 - 0) : pass 13:16:12.893008 deduction: 0 / timeout: 5 panic: runtime error: index out of range [-1] goroutine 185836 [running]: main.(*Scenario).Validation.func1(0x7d08e8, 0xc0004a7440, 0xffffffffffffffff) /home/isuadmin/src/isucon11-prior/benchmarker/scenario.go:304 +0xeec github.com/isucon/isucandar/worker.(*Worker).processInfinity.func1(0x7d08e8, 0xc0004a7440) /home/isuadmin/go/pkg/mod/github.com/isucon/isucandar@v0.0.0-20210609100057-baa52484de01/worker/worker.go:72 +0x46 github.com/isucon/isucandar/parallel.(*Parallel).Do.func1(0xc000bb8140, 0xc000c2a090, 0x0) /home/isuadmin/go/pkg/mod/github.com/isucon/isucandar@v0.0.0-20210609100057-baa52484de01/parallel/parallel.go:68 +0x73 created by github.com/isucon/isucandar/parallel.(*Parallel).Do /home/isuadmin/go/pkg/mod/github.com/isucon/isucandar@v0.0.0-20210609100057-baa52484de01/parallel/parallel.go:66 +0xa6
generate_idでSELECTするのをやめた
マニュアル には
各エンドポイントの URI の変更は認められませんが、以下の点については明確に許可されます。
・ID 発行形式の変更
って書いてあったので https://github.com/isucon/isucon11-prior/blob/aea2af2bdfdeab5905f60bdb79292b0ef44dd354/webapp/ruby/app.rb#L26-L32 でSELECTするのをやめて
def generate_id(table, tx) SecureRandom.uuid end
のように修正。(呼び出し元を変更するのが面倒だったので引数はそのまま)
ULIDからUUIDに変えた理由はよく覚えてない。
13:26:43.131061 SCORE: login: 7 13:26:43.131078 SCORE: signup: 6 13:26:43.131083 SCORE: create-schedule: 851 13:26:43.131215 score: 8517(8517 - 0) : pass 13:26:43.131220 deduction: 0 / timeout: 5 panic: runtime error: index out of range [-1] goroutine 184194 [running]: main.(*Scenario).Validation.func1(0x7d08e8, 0xc0004d1da0, 0xffffffffffffffff) /home/isuadmin/src/isucon11-prior/benchmarker/scenario.go:304 +0xeec github.com/isucon/isucandar/worker.(*Worker).processInfinity.func1(0x7d08e8, 0xc0004d1da0) /home/isuadmin/go/pkg/mod/github.com/isucon/isucandar@v0.0.0-20210609100057-baa52484de01/worker/worker.go:72 +0x46 github.com/isucon/isucandar/parallel.(*Parallel).Do.func1(0xc0006135c0, 0xc000a23660, 0x0) /home/isuadmin/go/pkg/mod/github.com/isucon/isucandar@v0.0.0-20210609100057-baa52484de01/parallel/parallel.go:68 +0x73 created by github.com/isucon/isucandar/parallel.(*Parallel).Do /home/isuadmin/go/pkg/mod/github.com/isucon/isucandar@v0.0.0-20210609100057-baa52484de01/parallel/parallel.go:66 +0xa6
POST /api/signupでINSERT後にSELECTするのをやめた
https://github.com/isucon/isucon11-prior/blob/aea2af2bdfdeab5905f60bdb79292b0ef44dd354/webapp/ruby/app.rb#L98-L99 にも POST /api/reservations
と同じ問題があったので
created_at = Time.now tx.xquery('INSERT INTO `users` (`id`, `email`, `nickname`, `created_at`) VALUES (?, ?, ?, ?)', id, email, nickname, created_at)
のように修正
13:30:30.845231 SCORE: login: 7 13:30:30.845248 SCORE: signup: 6 13:30:30.845253 SCORE: create-schedule: 874 13:30:30.846415 score: 8735(8747 - 12) : pass 13:30:30.846424 deduction: 0 / timeout: 127 panic: runtime error: index out of range [-1] goroutine 185720 [running]: main.(*Scenario).Validation.func1(0x7d08e8, 0xc000181c80, 0xffffffffffffffff) /home/isuadmin/src/isucon11-prior/benchmarker/scenario.go:304 +0xeec github.com/isucon/isucandar/worker.(*Worker).processInfinity.func1(0x7d08e8, 0xc000181c80) /home/isuadmin/go/pkg/mod/github.com/isucon/isucandar@v0.0.0-20210609100057-baa52484de01/worker/worker.go:72 +0x46 github.com/isucon/isucandar/parallel.(*Parallel).Do.func1(0xc000a2cd00, 0xc0009e7950, 0x0) /home/isuadmin/go/pkg/mod/github.com/isucon/isucandar@v0.0.0-20210609100057-baa52484de01/parallel/parallel.go:68 +0x73 created by github.com/isucon/isucandar/parallel.(*Parallel).Do /home/isuadmin/go/pkg/mod/github.com/isucon/isucandar@v0.0.0-20210609100057-baa52484de01/parallel/parallel.go:66 +0xa6
netdataをDBサーバに流す
netdata が重いかもと思って、そんなに負荷の高くなかったDBサーバに流すようにしたけどそんなにスコア変わらなかった
13:39:49.441780 SCORE: create-schedule: 871 13:39:49.441799 SCORE: login: 7 13:39:49.441802 SCORE: signup: 6 13:39:49.442042 score: 8717(8717 - 0) : pass 13:39:49.442068 deduction: 0 / timeout: 4 panic: runtime error: index out of range [-1] goroutine 185720 [running]: main.(*Scenario).Validation.func1(0x7d08e8, 0xc000181c80, 0xffffffffffffffff) /home/isuadmin/src/isucon11-prior/benchmarker/scenario.go:304 +0xeec github.com/isucon/isucandar/worker.(*Worker).processInfinity.func1(0x7d08e8, 0xc000181c80) /home/isuadmin/go/pkg/mod/github.com/isucon/isucandar@v0.0.0-20210609100057-baa52484de01/worker/worker.go:72 +0x46 github.com/isucon/isucandar/parallel.(*Parallel).Do.func1(0xc000a2cd00, 0xc0009e7950, 0x0) /home/isuadmin/go/pkg/mod/github.com/isucon/isucandar@v0.0.0-20210609100057-baa52484de01/parallel/parallel.go:68 +0x73 created by github.com/isucon/isucandar/parallel.(*Parallel).Do /home/isuadmin/go/pkg/mod/github.com/isucon/isucandar@v0.0.0-20210609100057-baa52484de01/parallel/parallel.go:66 +0xa6
前の方にやった「GET /api/schedules のN+1修正(不完全)」をrevert
ずっとpanic出てるのもアレだったので本格的になおすためにいったんrevertした
13:48:51.002083 SCORE: create-schedule: 41 13:48:51.002098 SCORE: signup: 521 13:48:51.002111 SCORE: create-reservation: 2878 13:48:51.002120 SCORE: login: 522 13:48:51.002146 score: 3810(3810 - 0) : pass 13:48:51.002154 deduction: 0 / timeout: 1
GET /api/schedules のN+1修正(完全版)
最終的にこれでなおった。( INNER JOIN
を LEFT JOIN
に変えた)
sql = <<~SQL SELECT s.id AS id, s.title AS title, s.capacity AS capacity, s.created_at AS created_at, IFNULL(r.reserved, 0) AS reserved FROM `schedules` AS s LEFT JOIN ( SELECT schedule_id, COUNT(*) AS reserved FROM reservations GROUP BY schedule_id ) r ON s.id = r.schedule_id ORDER BY s.id DESC SQL schedules = db.xquery(sql)
panicしてた時ほどスコアは増えなかったのでスコア8000はバグだったのか...
13:56:18.541470 SCORE: create-schedule: 40 13:56:18.541484 SCORE: create-reservation: 3265 13:56:18.541494 SCORE: login: 600 13:56:18.541497 SCORE: signup: 599 13:56:18.541607 score: 4262(4265 - 3) : pass 13:56:18.541614 deduction: 3 / timeout: 2
reservationsにindexつけた
ALTER TABLE reservations ADD INDEX schedule_id (`schedule_id`); ALTER TABLE reservations ADD INDEX user_id (`user_id`);
14:09:07.199826 SCORE: create-reservation: 3352 14:09:07.199843 SCORE: login: 612 14:09:07.199847 SCORE: signup: 611 14:09:07.199853 SCORE: create-schedule: 45 14:09:07.199858 score: 4414(4414 - 0) : pass 14:09:07.199863 deduction: 0 / timeout: 0
ブログ書きながら気づいたんだけど https://github.com/isucon/isucon11-prior/blob/aea2af2bdfdeab5905f60bdb79292b0ef44dd354/webapp/ruby/app.rb#L146 があったので schedule_id
と user_id
の複合indexでもよかったかも
POST /api/schedules でINSERT後にSELECTしないようにした
他エンドポイントで修正済のやつを見逃してたので https://github.com/isucon/isucon11-prior/blob/aea2af2bdfdeab5905f60bdb79292b0ef44dd354/webapp/ruby/app.rb#L129-L130 を
created_at = Time.now tx.xquery('INSERT INTO `schedules` (`id`, `title`, `capacity`, `created_at`) VALUES (?, ?, ?, ?)', id, title, capacity, created_at)
のようになおした
14:16:39.149303 SCORE: create-reservation: 3460 14:16:39.149331 SCORE: login: 626 14:16:39.149337 SCORE: signup: 625 14:16:39.149347 SCORE: create-schedule: 47 14:16:39.149420 score: 4555(4556 - 1) : pass 14:16:39.149428 deduction: 1 / timeout: 1
2台目のAP追加
14:27:18.376503 SCORE: login: 747 14:27:18.376518 SCORE: signup: 746 14:27:18.376523 SCORE: create-schedule: 55 14:27:18.376526 SCORE: create-reservation: 4102 14:27:18.376530 score: 5399(5399 - 0) : pass 14:27:18.376533 deduction: 0 / timeout: 0
このあとpumaのworkersとかthreadsを色々いじったがそんなに改善しなかった
DBとnginxを同居
この時点では
- front + AP
- AP
- DB
だったと思うんだけど(うろ覚え)、冒頭にも書いた通りDBの負荷がそんなに高くなかったのでfrontとDBを同居させて
- front + DB
- AP
- AP
のような構成にした
14:51:04.770444 SCORE: login: 619 14:51:04.770470 SCORE: signup: 618 14:51:04.770475 SCORE: create-schedule: 47 14:51:04.770480 SCORE: create-reservation: 3445 14:51:04.770488 score: 4534(4534 - 0) : pass 14:51:04.770491 deduction: 0 / timeout: 0
netdataを3台に増やした
14:59:57.771297 SCORE: login: 723 14:59:57.771312 SCORE: signup: 722 14:59:57.771323 SCORE: create-schedule: 53 14:59:57.771326 SCORE: create-reservation: 3903 14:59:57.771329 score: 5156(5156 - 0) : pass 14:59:57.771334 deduction: 0 / timeout: 0
parallelismを40にした
この時点で各サーバともCPU使用率50%前後止まりでスコアが伸び悩んでいたのでダメ元で -parallelism
(ベンチマーカーのパラメータ)を増やしたらスコアが増えた(が、timeoutも増えた...)
15:19:27.198058 SCORE: login: 462 15:19:27.198083 SCORE: signup: 461 15:19:27.198093 SCORE: create-schedule: 84 15:19:27.198100 SCORE: create-reservation: 4875 15:19:27.206160 score: 6059(6177 - 118) : pass 15:19:27.206173 deduction: 3 / timeout: 1154
設定調整祭
この辺でひたすらpumaやnginxの設定を調整しまくってた
parallelismを20に戻した
timeoutが多くてスコアが伸び悩んでそうだったのでダメ元でparallelismを20に戻したらスコアが改善した。どうして...(現場猫顔)
17:45:53.615559 SCORE: signup: 679 17:45:53.615574 SCORE: create-schedule: 98 17:45:53.615576 SCORE: create-reservation: 6925 17:45:53.615579 SCORE: login: 680 17:45:53.616384 score: 8550(8585 - 35) : pass 17:45:53.616392 deduction: 34 / timeout: 18
終了直前対応(その1)
nginxとmysqlのログを止めて、SentryとNewRelic(APMとinfra agentの両方)を無効化
17:51:08.566625 SCORE: login: 1093 17:51:08.566640 SCORE: signup: 1092 17:51:08.566650 SCORE: create-schedule: 138 17:51:08.566665 SCORE: create-reservation: 10580 17:51:08.566901 score: 13051(13053 - 2) : pass 17:51:08.566910 deduction: 1 / timeout: 16
puma設定修正
「NewRelic止めたからpumaのworker数増やせるのでは?」と思って増やしたらスコアが減った...
17:56:47.793917 SCORE: create-reservation: 10370 17:56:47.794019 SCORE: login: 1240 17:56:47.794073 SCORE: signup: 1239 17:56:47.794124 SCORE: create-schedule: 138 17:56:47.796378 score: 12725(12990 - 265) : pass 17:56:47.796530 deduction: 250 / timeout: 152
終了直前対応(その2)
pumaのworker数増やす設定をrevertして終了時間ギリギリでデプロイ
17:59:03.124528 SCORE: login: 1259 17:59:03.124632 SCORE: signup: 1258 17:59:03.124642 SCORE: create-schedule: 143 17:59:03.124651 SCORE: create-reservation: 10539 17:59:03.125527 score: 13226(13228 - 2) : pass 17:59:03.125539 deduction: 0 / timeout: 21
感想戦
メトリクス見れるようにするために終了直前対応をrevertしてスコア計測
21:14:05.874582 SCORE: login: 952 21:14:05.874616 SCORE: signup: 951 21:14:05.874624 SCORE: create-schedule: 104 21:14:05.874630 SCORE: create-reservation: 6597 21:14:05.874955 score: 8585(8589 - 4) : pass 21:14:05.874963 deduction: 3 / timeout: 19
usersにemail index追加
https://github.com/isucon/isucon11-prior/blob/aea2af2bdfdeab5905f60bdb79292b0ef44dd354/webapp/ruby/app.rb#L110 で email
使ってるのにindex無いやんけって気づいてindex追加
ALTER TABLE users ADD INDEX email (`email`);
21:36:18.462310 SCORE: login: 848 21:36:18.462325 SCORE: signup: 847 21:36:18.462329 SCORE: create-schedule: 93 21:36:18.462332 SCORE: create-reservation: 7049 21:36:18.462454 score: 8826(8827 - 1) : pass 21:36:18.462465 deduction: 0 / timeout: 10
json_encoderをActiveSupport::JSONからojに変更
ActiveSupport::JSON
が重そうだったので https://github.com/isucon/isucon11-prior/blob/aea2af2bdfdeab5905f60bdb79292b0ef44dd354/webapp/ruby/app.rb#L15 をojに変更
json_encoderをojに差し替える方法は下記を参考にした
21:57:01.325176 SCORE: login: 1044 21:57:01.325190 SCORE: signup: 1043 21:57:01.325201 SCORE: create-schedule: 119 21:57:01.325203 SCORE: create-reservation: 8102 21:57:01.325620 score: 10325(10336 - 11) : pass 21:57:01.325628 deduction: 10 / timeout: 18
再度終了直前対応
22:08:45.723600 SCORE: create-reservation: 12100 22:08:45.723613 SCORE: login: 1290 22:08:45.723615 SCORE: signup: 1289 22:08:45.723618 SCORE: create-schedule: 151 22:08:45.723879 score: 14899(14900 - 1) : pass 22:08:45.723887 deduction: 1 / timeout: 3
sinatraのログを無効化
https://github.com/isucon/isucon11-prior/blob/aea2af2bdfdeab5905f60bdb79292b0ef44dd354/webapp/ruby/app.rb#L9 を見てて「sinatraのログ出力(出力先はsystemd)」も重そうだなあと思ってdisableにした
22:27:05.030386 SCORE: login: 1267 22:27:05.030401 SCORE: signup: 1266 22:27:05.030407 SCORE: create-schedule: 167 22:27:05.030412 SCORE: create-reservation: 12165 22:27:05.030627 score: 15101(15102 - 1) : pass 22:27:05.030632 deduction: 1 / timeout: 9
感想
1人チームなのでstakprofやalpみたいな手元で解析するツールは諦めて解析は全部NewRelicに任せてたんだけど、限界が出てきたのでそろそろstackprofくらいは使えるようにならないとなあという気持ちになってる