matsuu / aws-isucon

ISUCON過去問環境をAWSで再現するための一式まとめ

このファイルはREADME.adocです

aws-isucon's Issues

isucon11-qualifyで参照実装をRubyとPythonに切り替えるとベンチマーカーが正常に動かない

こんにちは。isucon11-qualifyのAMI（ami-01730fadc0a1d1e1c）で参照実装をGoから他の言語に切り替えるとコードを一切変更してないにも関わらずベンチマーカーがprepareでエラーになるため報告させていただきます。

問題のある言語

• Ruby
• Python

全ての参照実装で確認しましたが他の言語では問題ありませんでした。

動作確認方法

$ sudo -i -u isucon
$ cd /home/isucon/bench

$ sudo systemctl stop isucondition.go.service
$ sudo systemctl start isucondition.ruby.service
$ ./bench -all-addresses 127.0.0.1 -target 127.0.0.1:443 -tls -jia-service-url http://127.0.0.1:4999

エラー内容

詳細

11:57:30.134790 ISUCON11 benchmarker
11:57:30.135045 ===> PREPARE
11:57:30.135060 start: load initial data
11:57:30.138205 finish: load initial data
11:57:35.169530 ERR: prepare: mismatch: 2番目の椅子 (JIA_ISU_UUID=15063e10-26fc-4dac-ae3a-1f195e0c6c4a) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.169554 ERR: prepare: mismatch: 1番目の椅子 (JIA_ISU_UUID=8fb74e6e-4f8d-4a33-9862-dbcdc0712c7e) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.169577 ERR: prepare: mismatch: 4番目の椅子 (JIA_ISU_UUID=b82dcff4-8fae-4773-9956-22ab354adb7e) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.169590 ERR: prepare: mismatch: 3番目の椅子 (JIA_ISU_UUID=8469e6f6-0d29-4052-87cf-dd9bfde45014) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.169629 ERR: prepare: mismatch: 5番目の椅子 (JIA_ISU_UUID=eb104b95-3532-4828-8550-89da717b9667) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196298 ERR: prepare: mismatch: 2番目の椅子 (JIA_ISU_UUID=0b675a72-c8fd-4c21-b87b-eefc1d5df5e4) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196326 ERR: prepare: mismatch: 1番目の椅子 (JIA_ISU_UUID=6d69647a-b816-4540-9e60-1d43c774df94) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196355 ERR: prepare: mismatch: 4番目の椅子 (JIA_ISU_UUID=5112418b-549f-4da1-baee-30265193657c) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196376 ERR: prepare: mismatch: 3番目の椅子 (JIA_ISU_UUID=08985a64-c425-48d2-ac33-25ac61d5a931) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196415 ERR: prepare: mismatch: 6番目の椅子 (JIA_ISU_UUID=99c606e8-c041-4a13-b073-c29015cbbdb1) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196452 ERR: prepare: mismatch: 5番目の椅子 (JIA_ISU_UUID=0634a999-5f5b-4e8b-bee6-f95d622954a4) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196485 ERR: prepare: mismatch: 8番目の椅子 (JIA_ISU_UUID=c39e23ec-1681-4251-bd08-d082b882a74b) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196516 ERR: prepare: mismatch: 7番目の椅子 (JIA_ISU_UUID=9dfdc081-a305-4c1f-8ea2-fc29b46f1f7d) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196582 ERR: prepare: mismatch: 10番目の椅子 (JIA_ISU_UUID=7d195770-8d14-4c79-946e-d7a313d3cabd) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196596 ERR: prepare: mismatch: 9番目の椅子 (JIA_ISU_UUID=b14b8bad-6b89-4997-95de-27e85ed058f8) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196641 ERR: prepare: mismatch: 12番目の椅子 (JIA_ISU_UUID=023c8e56-4410-484d-b7fa-702d48188d3c) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196654 ERR: prepare: mismatch: 11番目の椅子 (JIA_ISU_UUID=96263833-a65e-4607-8403-a0c49e2c7112) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196689 ERR: prepare: mismatch: 14番目の椅子 (JIA_ISU_UUID=5a5ab5c8-85ad-4b12-8663-ca400e895307) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196694 ERR: prepare: mismatch: 13番目の椅子 (JIA_ISU_UUID=ea78c8f4-3b61-4f59-a5e3-2be4d5cc9d00) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196725 ERR: prepare: mismatch: 16番目の椅子 (JIA_ISU_UUID=c9add5fc-28ca-4eea-9b77-6cb90852508a) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196739 ERR: prepare: mismatch: 15番目の椅子 (JIA_ISU_UUID=d5226f7b-3c7b-477e-ba8b-3cc7a4012e9d) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196764 ERR: prepare: mismatch: 18番目の椅子 (JIA_ISU_UUID=2fbbb42f-287a-40f7-8432-ea1d8dd9afd6) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196785 ERR: prepare: mismatch: 17番目の椅子 (JIA_ISU_UUID=f46ad522-d196-487e-b666-c9b000c3d458) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196809 ERR: prepare: mismatch: 20番目の椅子 (JIA_ISU_UUID=c0a0b8b0-23da-4394-ac77-64685821ca38) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.196832 ERR: prepare: mismatch: 19番目の椅子 (JIA_ISU_UUID=6278f71d-a338-4c5d-8fd9-12ece77add5b) の情報が異なります: latest_isu_conditionの内容が不正です: 200 (GET: /api/isu)
11:57:35.232593 ERR: prepare: mismatch: POSTに成功していない時刻のデータが返されました: 200 (GET: /api/trend)
11:57:35.232718 ERR: prepare: critical: アプリケーション互換性チェックに失敗しました
11:57:35.232742 SCORE: 00.StartBenchmark       : 0
11:57:35.232748 SCORE: 01.GraphGood            : 0
11:57:35.232750 SCORE: 02.GraphNormal          : 0
11:57:35.232753 SCORE: 03.GraphBad             : 0
11:57:35.232755 SCORE: 04.GraphWorst           : 0
11:57:35.232758 SCORE: 05.TodayGraphGood       : 0
11:57:35.232760 SCORE: 06.TodayGraphNormal     : 0
11:57:35.232762 SCORE: 07.TodayGraphBad        : 0
11:57:35.232765 SCORE: 08.TodayGraphWorst      : 0
11:57:35.232769 SCORE: 09.ReadInfoCondition    : 0
11:57:35.232772 SCORE: 10.ReadWarningCondition : 0
11:57:35.232775 SCORE: 11.ReadCriticalCondition: 0
11:57:35.232779 SCORE: _1.IsuInitialize        : 0
11:57:35.232781 SCORE: _2.NormalUserInitialize : 0
11:57:35.232783 SCORE: _3.ViewerInitialize     : 0
11:57:35.232785 SCORE: _5.ViewerDropout        : 0
11:57:35.232787 SCORE: _6.RepairIsu            : 0
11:57:35.232790 SCORE: _7.PostInfoCondition    : 0
11:57:35.232792 SCORE: _8.PostWarningCondition : 0
11:57:35.232794 SCORE: _9.PostCriticalCondition: 0
11:57:35.232796 SCORE: 00.StartBenchmark       : 0
11:57:35.232798 SCORE: 01.GraphGood            : 0
11:57:35.232799 SCORE: 02.GraphNormal          : 0
11:57:35.232801 SCORE: 03.GraphBad             : 0
11:57:35.232803 SCORE: 04.GraphWorst           : 0
11:57:35.232804 SCORE: 05.TodayGraphGood       : 0
11:57:35.232806 SCORE: 06.TodayGraphNormal     : 0
11:57:35.232807 SCORE: 07.TodayGraphBad        : 0
11:57:35.232809 SCORE: 08.TodayGraphWorst      : 0
11:57:35.232811 SCORE: 09.ReadInfoCondition    : 0
11:57:35.232812 SCORE: 10.ReadWarningCondition : 0
11:57:35.232814 SCORE: 11.ReadCriticalCondition: 0
11:57:35.233048 Critical error because: prepare:
    github.com/isucon/isucandar.(*BenchmarkStep).AddError
        /home/isucon/go/pkg/mod/github.com/isucon/[email protected]/benchmark_step.go:30
    github.com/isucon/isucandar.(*Benchmark).Start
        /home/isucon/go/pkg/mod/github.com/isucon/[email protected]/benchmark.go:104
    main.main
        /home/isucon/bench/main.go:438
    runtime.main
        /home/isucon/local/go/src/runtime/proc.go:225
  - critical:
    github.com/isucon/isucon11-qualify/bench/scenario.(*Scenario).prepareCheck
        /home/isucon/bench/scenario/prepare.go:117
    github.com/isucon/isucon11-qualify/bench/scenario.(*Scenario).Prepare
        /home/isucon/bench/scenario/prepare.go:82
    github.com/isucon/isucandar.(*Benchmark).Start.func2
        /home/isucon/go/pkg/mod/github.com/isucon/[email protected]/benchmark.go:98
    github.com/isucon/isucandar.panicWrapper
        /home/isucon/go/pkg/mod/github.com/isucon/[email protected]/benchmark.go:204
    github.com/isucon/isucandar.(*Benchmark).Start
        /home/isucon/go/pkg/mod/github.com/isucon/[email protected]/benchmark.go:98
  - アプリケーション互換性チェックに失敗しました
11:57:35.233061 score: 0(0 - 0) : Critical error
11:57:35.233063 deduction: 0 / timeout: 0
11:57:35.233068 <=== sendResult finish

原因

https://github.com/isucon/isucon11-qualify/blob/a443b242596003515c3037540dd3e48abfa87382/bench/scenario/verify.go#L1017-L1026 に https://github.com/isucon/isucon11-qualify/blob/a443b242596003515c3037540dd3e48abfa87382/bench/scenario/verify.go#L177-L184 をコピペしてデバッグログを仕込んだベンチマーカーを実行したところ、下記のようなログが得られました。

12:31:51.481372 expected: { JIAIsuUUID: 8fb74e6e-4f8d-4a33-9862-dbcdc0712c7e, Name: 金属製Mk-Ⅱ, IsSitting: true,ConditionString: is_dirty=false,is_overweight=false,is_broken=false, ConditionLevel: 1, Message: いい感じです〜, Timestamp: 1622959149 }actual: { JAIsuUUID: 8fb74e6e-4f8d-4a33-9862-dbcdc0712c7e, Name: 金属製Mk-Ⅱ, IsSitting: true,ConditionString: is_dirty=false,is_overweight=false,is_broken=false, ConditionLevel: info, Message: いい感じです〜, Timestamp: 1622991549 }
12:31:51.481416 expected: { JIAIsuUUID: 15063e10-26fc-4dac-ae3a-1f195e0c6c4a, Name: カウンターカウチ, IsSitting: true,ConditionString: is_dirty=false,is_overweight=false,is_broken=true, ConditionLevel: 2, Message: 直していただけますか？, Timestamp: 1622959149 }actual: { JAIsuUUID: 15063e10-26fc-4dac-ae3a-1f195e0c6c4a, Name: カウンターカウチ, IsSitting: true,ConditionString: is_dirty=false,is_overweight=false,is_broken=true, ConditionLevel: warning, Message: 直していただけますか？, Timestamp: 1622991549 }
12:31:51.481434 expected: { JIAIsuUUID: 8469e6f6-0d29-4052-87cf-dd9bfde45014, Name: リビングサイコー, IsSitting: true,ConditionString: is_dirty=true,is_overweight=false,is_broken=true, ConditionLevel: 2, Message: 汚れた壊れたまま...捨てられちゃうの...?, Timestamp: 1622959149 }actual: { JAIsuUUID: 8469e6f6-0d29-4052-87cf-dd9bfde45014, Name: リビングサイコー, IsSitting: true,ConditionString: is_dirty=true,is_overweight=false,is_broken=true, ConditionLevel: warning, Message: 汚れた壊れたまま...捨てられちゃうの...?, Timestamp: 1622991549 }
12:31:51.481450 expected: { JIAIsuUUID: b82dcff4-8fae-4773-9956-22ab354adb7e, Name: ミラクル1号, IsSitting: false,ConditionString: is_dirty=true,is_overweight=false,is_broken=false, ConditionLevel: 2, Message: 気づいたら汚れてた！, Timestamp: 1622959149 }actual: { JAIsuUUID: b82dcff4-8fae-4773-9956-22ab354adb7e, Name: ミラクル1号, IsSitting: false,ConditionString: is_dirty=true,is_overweight=false,is_broken=false, ConditionLevel: warning, Message: 気づいたら汚れてた！, Timestamp: 1622991549 }
12:31:51.481466 expected: { JIAIsuUUID: eb104b95-3532-4828-8550-89da717b9667, Name: リビング玉座, IsSitting: true,ConditionString: is_dirty=true,is_overweight=false,is_broken=false, ConditionLevel: 2, Message: この程度の汚れヘーキだって！, Timestamp: 1622959149 }actual: { JAIsuUUID: eb104b95-3532-4828-8550-89da717b9667, Name: リビング玉座, IsSitting: true,ConditionString: is_dirty=true,is_overweight=false,is_broken=false, ConditionLevel: warning, Message: この程度の汚れヘーキだって！, Timestamp: 1622991549 }

expectedとactualでTimestampが32400秒（9時間）ずれているため、配布されてるAMIがUTCなのが怪しそうです。

isucon@ip-172-31-43-83:~$ date
Mon Jan 17 12:58:56 UTC 2022

本家のplaybookだと https://github.com/isucon/isucon11-qualify/blob/1011682c2d5afcc563f4ebf0e4c88a5124f63614/provisioning/ansible/roles/common/tasks/timezone.yml#L2-L5 でJSTをセットしてますが、

aws-isucon/isucon11-qualify/provision.sh

Line 15 in 0b064ec

sed -i -e '/timezone/d' roles/common/tasks/main.yml

でこのtaskを読み込まなくなってるのが原因のように思われます。

回避方法

インスタンス内で下記を実行することでベンチマーカーのエラーが出なくなるのを確認しました。（エラーになったRubyやPythonだけでなく問題なかった言語に関してもエラーにならなかったことを確認）

sudo timedatectl set-timezone Asia/Tokyo