くりにっき

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

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が動いてるアプリケーションサーバ

至極の難問AWS & GCPクイズ

社内勉強会で発表したら好評だったので公開

注意

  • 全問解けても仕事の役にはたちません
  • ググるのは禁止

問題1

Q: 正しい組み合わせはどれか?

  1. AWS: CloudShell / GCP CloudShell
  2. AWS: Cloud Shell / GCP CloudShell
  3. AWS: CloudShell / GCP Cloud Shell
  4. AWS: Cloud Shell / GCP Cloud Shell

回答

正解: 3 (AWS: CloudShell / GCP Cloud Shell)

  • AWSがCloudShell(空白が入らない)で、GCPがCloud Shell(空白が入る)です
  • AWSは単語と単語の間に空白を入れない印象がある

問題2

Q: 正しい組み合わせはどれか?

  1. Amazon Workspace / Google Workspace
  2. Amazon Workspaces / Google Workspace
  3. Amazon Workspace / Google Workspaces
  4. Amazon Workspaces / Google Workspaces

回答 正解: 2 (Amazon Workspaces / Google Workspace)

  • Amazon Workspacesのみ複数形です
  • 名前は似ていますが両者は全く違うサービスです

問題3

Q: AWS KMSとGCP KMSの正式名称で正しい組み合わせはどれか?

  1. AWS Key Management Service / Google Cloud Key Management Service
  2. AWS Key Management System / Google Cloud Key Management Service
  3. AWS Key Management Service / Google Cloud Key Management System
  4. AWS Key Management System / Google Cloud Key Management System

回答 正解: 1 (AWS Key Management Service / Google Cloud Key Management Service)

  • KMSとは両方とも機微情報の管理に使うマネージドサービスです
  • KMSは両方とも「Key Management Service」が正式名称でした(引っ掛け問題)

問題4

Q: 正しい組み合わせはどれか?

  1. AWS: Secret Manager / GCP: Secret Manager
  2. AWS: Secrets Manager / GCP: Secret Manager
  3. AWS: Secret Manager / GCP: Secrets Manager
  4. AWS: Secrets Manager / GCP: Secrets Manager

回答 正解: 2 (AWS: Secrets Manager / GCP: Secret Manager)

  • 問題2と同様にAWSのみ複数形です
  • 両方とも機微情報管理のマネージドサービスです

問題5

Q: 下記の中で2021年5月末時点でGA(General Availability)済のサービスはどれか?

  1. Amazon EC2 Anywhere
  2. Amazon ECS Anywhere
  3. Amazon EKS Anywhere
  4. 1〜3全部

回答

正解: 2 (Amazon ECS Anywhere)

  • EC2 Anywhereは2021年5月末時点で名前は一切出ていない
  • ECS Anywhereはオンプレミスのサーバ上でECSを動かすためのサービス。2021年5月27日GA済
  • EKS Anywhereはオンプレミスのサーバ上でEKSを動かすためのサービス。2021年リリース予定だが2021年5月末時点ではまだGAされてない

おまけ:発表中の社内の反応

  • これは仕事の役に立たないwwwwwwwwwwwwww
  • えぐいやつだった
  • 選択肢の違いがわからない????
  • 何もわからない

余談

1年前の僕

2ヶ月前の僕

関連クイズ

sue445.hatenablog.com

GitHub-native DependabotでもAuto mergeをやりたかった

tl;dr;

いくつかやり方はあるんだけどどれも一長一短で決定打はなかった

前置き

Dependabot Previewの終了がアナウンスされました。

github.blog

Auto-merge: We always recommend verifying your dependencies before merging them; therefore, auto-merge will not be supported for the foreseeable future. For those of you who have vetted your dependencies, or are only using internal dependencies, we recommend adding third-party auto-merge apps, or setting up GitHub Actions to merge.

と書いてるようにGitHub-native Dependabot(新しい方)ではAuto mergeがサポートされないようです。

Dependabot Preview(古い方)では automerged_updates を使ってたので本腰入れて調べてみました。

ちなみに自動マージをやりたいモチベーションは個人的な理由なので大抵の人には当てはまらないと思います。(20個以上の個人アプリでdependabotを入れてると大量にPRきた時にマージするだけでも大変だし一気にマージするとデプロイのqueueが詰まる(CircleCIのjobの同時実行数はアカウント単位)ので、開発系のライブラリや本番系のライブラリでもパッチバージョンのバージョンアップ時は自動マージを許したい)

GitHub Actionsでやる方法

https://github.com/marketplace?type=actions&query=dependabot+merge で調べてStar数の多いものや定期的に更新されてるものをピックアップしました

Dependabot Auto Merge

github.com

pull_requestイベントかpull_request_targetイベントで実行される。執筆時点での最新版は2.4.0

メリット

  • Dependabot Previewautomerged_updates 相当の設定がある
  • APIから @dependabot merge みたいなコメントをして実現してるのでGitHub-native Dependabotと100%の互換性がある

デメリット

  • 前述の仕様のためPersonal Access Token(PAT)が必要
    • publicリポジトリだけなら public_repo スコープだけでいいのでギリギリ許容できなくはないが、トークン漏洩時のリスクを考えるとなるべくスコープを狭くしたい
    • ためしにApp Tokenを使ってみたらコメント自体は成功したけどDependabot側でエラーになったので、おそらくPATのユーザにリポジトリのWrite権限があるかをチェックしてるように見える

f:id:sue445:20210504181545p:plain

備考

GitHub-native Dependabotの仕様としてpublicリポジトリのpull_requestイベントだとsecretsが取れないのでPATの受け渡しができずにエラーになるのでpull_request_targetイベントを使う必要があるのですが、pull_request_targetイベントだと今度はセキュリティリスクがあるので注意する必要があります。

github.com

https://github.com/ahmadnassri/action-dependabot-auto-merge/issues/60#issuecomment-806170152 みたいに github.actor でチェックするしかなさそう。

Merge me!

github.com

workflow_runイベントによって別のジョブの終了時に実行される。執筆時点での最新版は1.2.62

メリット

  • secrets.GITHUB_TOKEN が使える

デメリット

  • presetで DEPENDABOT_MINORDEPENDABOT_PATCH はあるものの現時点ではDependabot Previewほどの柔軟さはない
  • workflow_runの仕様上リポジトリ上はGitHub Actionsで統一していないと使えない
    • CircleCIのジョブ終了時にGitHub Actionsを発火させるのはできなくはないが大変そう

Dependabot Pull Request Action

github.com

scheduleイベントで定期実行する。執筆時点での最新版は1.0.0

メリット

  • secrets.GITHUB_TOKEN が使える

デメリット

  • 設定は豊富だが現時点ではDependabot Previewautomerged_updates を完全に置き換えるのは難しそう
  • dependabotを実行する時間にあわせてscheduleの時間も調整する必要がある
    • 寝てる間にいい感じにマージされていればいいのであれば雑に30分後とか1時間後にセットすればいいけど、そのラグが許容できないとストレスかも

番外編

Renovateを使う

github.com

Renovateであればauto merge対応してるのでDependabotから移行するのも1つの手なのだが、DependabotはGitHub公式という強みがあるので移行するかどうかはかなり悩ましい

docs.renovatebot.com

近況

手持ちのリポジトリ全部移行する前にDependabot Auto MergeとMerge me!を1リポジトリずつ入れて試験運用してみた結果、下記の理由でDependabot Auto Mergeを採用しました

  • PATを各リポジトリにコピペしてまわる手間はあるものの automerged_updates 対応してるのは強い
  • 手持ちのリポジトリだとCircleCIも使っているのでMerge me!が使えない

gitpanda v0.9.5をリリースした

github.com

https://github.com/sue445/gitpanda/blob/master/CHANGELOG.md#v095

gitpanda的にはこれといって新機能は無いのですが GitHub Container Registryが secrets.GITHUB_TOKEN に対応した ためDockerイメージをGitHub Container Registryにホスティングするようにしてみました。

https://github.com/users/sue445/packages/container/package/gitpanda

ビルド済のDockerイメージがあるのでCloud Run辺りで動かしやすいかもしれません。

Go 1.16以降はGitHub版Dependabotを使った方がよさそう

前提

一言でDependabotと言っても実は2種類あります

3rd party版Dependabot

dependabot.com *1

GitHub版Dependabot

docs.github.com

github.blog

どうしてGo.1.16以降はGitHub版Dependabotを使った方がいいのか?

Go 1.16で No automatic changes to go.mod and go.sum が入った関係でmoduleのバージョンアップ時にエラーになることがあるためです。

blog.golang.org

実際に3rd party版DependabotでmoduleのバージョンアップPRを作った場合、下記のようにGo 1.16のみエラーになります

f:id:sue445:20210320073935p:plain

+ make test
go test -count=1 $***TEST_ARGS***
Error: kmsenv.go:8:2: missing go.sum entry for module providing package golang.org/x/oauth2/google (imported by github.com/sue445/gcp-kmsenv); to add:
    go get github.com/sue445/gcp-kmsenv
Error: ../../../go/pkg/mod/google.golang.org/grpc@v1.36.0/internal/channelz/types_linux.go:26:2: missing go.sum entry for module providing package golang.org/x/sys/unix (imported by google.golang.org/grpc/internal/channelz); to add:
    go get google.golang.org/grpc/internal/channelz@v1.36.0
Error: ../../../go/pkg/mod/cloud.google.com/go@v0.79.0/kms/apiv1/key_management_client.go:28:2: missing go.sum entry for module providing package google.golang.org/api/iterator (imported by cloud.google.com/go/kms/apiv1); to add:
    go get cloud.google.com/go/kms/apiv1@v0.79.0
Error: ../../../go/pkg/mod/cloud.google.com/go@v0.79.0/kms/apiv1/doc.go:43:2: missing go.sum entry for module providing package google.golang.org/api/option (imported by github.com/sue445/gcp-kmsenv); to add:
    go get github.com/sue445/gcp-kmsenv
Error: ../../../go/pkg/mod/cloud.google.com/go@v0.79.0/kms/apiv1/key_management_client.go:30:2: missing go.sum entry for module providing package google.golang.org/api/option/internaloption (imported by cloud.google.com/go/kms/apiv1); to add:
    go get cloud.google.com/go/kms/apiv1@v0.79.0
Error: ../../../go/pkg/mod/cloud.google.com/go@v0.79.0/kms/apiv1/key_management_client.go:31:2: missing go.sum entry for module providing package google.golang.org/api/transport/grpc (imported by cloud.google.com/go/kms/apiv1); to add:
    go get cloud.google.com/go/kms/apiv1@v0.79.0
Error: ../../../go/pkg/mod/cloud.google.com/go@v0.79.0/kms/apiv1/iam.go:19:2: missing go.sum entry for module providing package google.golang.org/genproto/googleapis/cloud/kms/v1 (imported by github.com/sue445/gcp-kmsenv); to add:
    go get github.com/sue445/gcp-kmsenv
Error: ../../../go/pkg/mod/cloud.google.com/go@v0.79.0/iam/iam.go:30:2: missing go.sum entry for module providing package google.golang.org/genproto/googleapis/iam/v1 (imported by cloud.google.com/go/iam); to add:
    go get cloud.google.com/go/iam@v0.79.0
Error: ../../../go/pkg/mod/google.golang.org/grpc@v1.36.0/status/status.go:34:2: missing go.sum entry for module providing package google.golang.org/genproto/googleapis/rpc/status (imported by google.golang.org/grpc/status); to add:
    go get google.golang.org/grpc/status@v1.36.0
Error: make: *** [Makefile:10: test] Error 1
Error: Process completed with exit code 2.

https://github.com/sue445/gcp-kmsenv/pull/53/checks?check_run_id=2152006087

対応するためにはmoduleのバージョンアップ時に go getgo mod tidy も一緒にする必要があるのですが、GitHub版DependabotだとPR作成時に自動で go mod tidy を行うためこの問題を回避できます。

github.blog

3rd party版の方は下記issueがクローズされてるのでおそらく実装の見込みは薄いと思います。

github.com

まぁ3rd party版とGitHub版があるならGitHub版を使った方がいいよね...

3rd party版 vs GitHub

GitHub版には automerged_updates が無いのを除けば今の所不満は無いです。(3rd party版の automerged_updates *4 をずっと使ってきたのでこれまで移行するモチベーションがあまりなかった)

*1:区別するために僕が勝手に3rd party版って言ってるので適切な言い方があったら知りたい

*2:https://github.com/sue445/gitpanda/pull/575

*3:https://github.com/sue445/gitpanda/pull/584

*4:https://dependabot.com/docs/config-file/#automerged_updates

Cloud FunctionsにRubyのスクリプトをデプロイする時の裏側

前置き

個人ツールをCloud Functionsで動かしてるのですがある日突然デプロイできなくなりました。

事象は下記のStack Overflowに書いて解決済みです。

stackoverflow.com

英語読みたくない人用に簡単に説明書くと、Cloud Functionsのデプロイで使われているDockerイメージにインストールされてるbundlerがバグってるバージョンにいきなり上がった *1 せいでデプロイできなかった感じです。

調べたけど gcloud functions deploy からだとデプロイ時に使うbundlerのバージョンをどうやっても変えられませんでした。

で、その調査の過程でCloud Functionsのデプロイの裏側を調べたのでメモ。

注意点

このエントリに書いてる内容は実際の処理やログを参考に調べた結果をまとめてるだけなので注意してください。公式ドキュメントのどこにも載っていなかったので公式ドキュメントへのリンクも書いてません。

Cloud Functionsのデプロイ方法

下記のように gcloud functions deploy を実行するだけで bundle install やら諸々実行されます。

gcloud functions deploy my_func --region=us-central1 --memory=128MB --runtime=ruby27

cloud.google.com

デプロイ時のログの場所

デプロイ時のログにCloud Loggingへのリンクが表示され、Cloud Loggingで詳細なログが見れます。

f:id:sue445:20210312220834p:plain

Cloud Functionsのデプロイで使われるビルド環境

f:id:sue445:20210312221239p:plain

ここで注目してほしいのはフォーカスしている箇所です。

Cloud Functionsデプロイ時のビルド環境はDockerコンテナのようです。

実際のDockerイメージは下記にあります。

実際に docker run --rm -it us.gcr.io/fn-img/buildpacks/ruby27/builder:latest bash のようにすることでCloud Functionsのビルド環境に入ることができますが、イメージ1つ2.5GBあるのでpullする時の帯域と空きストレージには注意してください。

$ docker images | grep us.gcr.io/fn-img/buildpacks
us.gcr.io/fn-img/buildpacks/ruby26/builder                          ruby26_20210228_2_6_6_RC00   3546787b4c87        41 years ago        2.48GB
us.gcr.io/fn-img/buildpacks/ruby27/builder                          ruby27_20210308_2_7_2_RC00   4eb6206a7245        41 years ago        2.44GB

Cloud Functionsのデプロイ時の処理

色々ググッた結果、デプロイ時の処理は下記にあるのを見つけました。

https://github.com/GoogleCloudPlatform/buildpacks/blob/54f3b59da3ac1fc7f9f1236bb0a6c8b1fb055e00/cmd/ruby/bundle/main.go

これを見れば gcloud functions deploy 実行時に実際にGCP側でどんな処理が実行されるのか分かると思います。

*1:Rubyのdefault gemで入ってるbundlerを使ってない

プリパラのライブにおける緊急対応事例 #ノンシュガー

起きたこと

3/6(土)の NonSugar スペシャルイベント「約束のてへペロピタですわ!」byプリパラ の昼夜公演に現地勢として参加してたのですが、昼公演の楽曲中に演者の1人の山下七海さんが 歌ってる最中にダッシュでステージ裏にはけた。

現地で見てた側としてはまさにこういう心境でした。

dic.pixiv.net

昼公演終了の段階では「ペッパー *1 だしそういう演出の可能性もあるかもしれないな」という感想だった。

ちなみに夜公演だと途中退場はなかったのでガチなトラブルだったらしい。

真相

これらしい。

家に帰って配信アーカイブを見返してたんだけど、確かに山下さんのブーツの紐が片方解けてステージ上で自分で外そうとした様子が映っていた。(ステージ降りた後の再入場時にはブーツの紐っぽいのがなくなってた)

配信アーカイブを見返しての感想

昼公演の様子がむっちゃ気になったので家に帰ってから配信チケットを買ってアーカイブを見た。

山下さんが歌いながらブーツを外そうとして苦労してるのは確認。

だけど山下さんがダッシュで抜けた様子は全くカメラに映ってなくて、NonSugarが一時的に2人でライブしてる間はカメラをむっちゃズームにしてステージ全体が映らないようになってた。完全に推測だけどステージ全体が映ると3人ユニットのNonSugarが2人しかいないことに配信側が気づくので現場の一瞬の判断のカメラワークだと思う。

山下さんが抜けてる最中に山下さんのコールのパートがあったのだけど残り2人が一緒にコールしてた。その直後に山下さんが再入場して歌唱再開したのですがその時にはブーツの紐っぽいのが両足ともなくなっていた。

2曲終わってMCタイムになった時に山下さんが再度ステージから抜けて戻ってきた時にはブーツの紐っぽいのが両足ともついてたので、楽曲やってる数分間でスタッフがブーツの緊急対応をやったのだと思う。

結果としてNonSugarは歌唱中にトラブルが起きて一瞬2人になったけども楽曲を止めることなく歌いきった。

時間にしたらほんの数分間の出来事なんだけどかなり情報量が多かった。

軒並みですが演者だけでなく関係者一同対応乙という感想しかないです。

サービス継続不可能になりそうな障害時にも周囲が一瞬の判断で協力して緊急対応してダウンタイムやユーザ影響を最小にしてサービスを継続するのは日々の業務に通じるものがあると思いました。

ちなみにアーカイブ配信は3/7までで円盤にも夜公演しか収録されないのでこの緊急対応内容はお蔵入りになりそう。

*1:プリパラ内で山下七海さんが演じる野生児キャラ