くりにっき

フルスタックキュアエンジニアです

ISUCONの素振りでisucon11-priorをやった

先週末にisucon11-prior(事前講習のハンズオン課題)をやったのでメモ

github.com

isucon.net

結果

  • 使用言語:Ruby
  • 初期スコア:1765
  • 最終スコア:13226(8時間で出せたスコア)
  • 感想戦後:15101

最終的なサーバ構成

スペックはいずれもc5.large

  • front *1 兼DB x 1 *2
  • AP*3 x 2
  • bench x 1

コンテキスト

  • 1人チーム

事前にやったこと:AMI作成

AMIの作り方は https://github.com/matsuu/vagrant-isucon11-prior がむっちゃ参考になりました。

github.com

作成手順

  1. ubuntu-focalでEC2インスタンスを作る
    • マニュアル によれば演習時のインスタンスタイプは c5.large を想定してるらしいが、AMI作成時は関係ないのでスペック上げておけば時間短縮できる
      • 参考:c5.large だと3のコマンド実行で15分くらいかかる
    • ボリュームサイズはデフォルトの8GiBでOK
      • ボリュームサイズを増やしすぎるとそのAMIから作るEC2インスタンスもそれに引きづられるのでむしろダメ
      • 例:50GiBでAMIを作るとEC2インスタンスは50GiB以上じゃないと作れなくなる
    • セキュリティグループで最低限22番ポートだけは開放する
  2. sshでログイン
    • ssh -i /path/to/ec2_key_pair.pem ubuntu@PUBLIC_IP
  3. EC2インスタンス内で https://github.com/matsuu/vagrant-isucon11-prior/blob/655df852ee1539e763b1fb82c0251a43d333c33a/Vagrantfile#L78-L91 を1行ずつ実行
    • エラーになったらsudoをつけて再実行
  4. ログアウトしてAMIを作成開始
  5. AMIの作成後にEC2インスタンスを止めるか削除する

AMIから起動したEC2インスタンスへisuconユーザでログインする方法

ubuntuユーザでログイン後にauthorized_keysをコピーするのが楽

  1. ubuntuユーザでログイン
    • ssh -i /path/to/ec2_key_pair.pem ubuntu@PUBLIC_IP
  2. EC2インスタンス内で下記を実行
    • sudo cp /home/ubuntu/.ssh/authorized_keys /home/isucon/.ssh/authorized_keys
  3. 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の設定調整

https://github.com/isucon/isucon11-prior/blob/aea2af2bdfdeab5905f60bdb79292b0ef44dd354/webapp/ruby/config/puma.rb を下記のように修正

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_workernakayoshi_fork は下記参照

isucon.net

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を入れるようにした

https://github.com/isucon/isucon11-prior/blob/aea2af2bdfdeab5905f60bdb79292b0ef44dd354/webapp/ruby/app.rb#L156-L157

      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してたのでメモ化した

https://github.com/isucon/isucon11-prior/blob/aea2af2bdfdeab5905f60bdb79292b0ef44dd354/webapp/ruby/app.rb#L42-L44

    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-L184sinatraで静的ファイルを読み込んで返しているのが無駄だったので、下記のように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 JOINLEFT 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_iduser_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#L110email 使ってるのに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に差し替える方法は下記を参考にした

qiita.com

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くらいは使えるようにならないとなあという気持ちになってる

*1:ベンチマーカーのリクエストを受けるnginxがいるサーバ

*2:色々改善した結果DBの負荷がそんなに高くなかったのでnginxと同居させた

*3:pumaが動いてるアプリケーションサーバ