AWS re:Invent 2023参加記録
色々調べていったものの、現地に行ってわかったことも結構あったのでメモ。
電子機器
持っていったもの
- 社用Macbook Pro
- アイリスオーヤマ モバイルモニター 13.3インチ DP-BF132S-B
- 充電系
- Anker 733 Power Bank (GaNPrime PowerCore 65W) 10000mAh
- Anker PowerCore Fusion 5000
- Anker PowerCore Speed 10000
- Anker Nano II 30W
振り返り
- o: モバイルモニターは非常に役立った。GameDayやWorkshop系で手順と操作コンソールを同時に表示できると効率が段違い。
- o: Anker 733は多少重いし高いし10000が若干物足りないがまあよかったと思う。コンセントに直接刺せるのが◯。
- o: 充電器はホテルに放置しておく分があると、毎日抜き差ししなくてよくて楽。
- x: PCは私用のWindowsを持っていけばよかった。社用PCを持って行っても、毎日セッションと明日の予定検討で一杯で日本の仕事を考える余裕などない。また、周りの人が感じてないNW不調を感じることが多くあり、プロキシソフトの影響が疑われ、その点でもストレスだった。WindowsよりMacの方が・・・とも思ったが、ローカル環境を使うことはほぼなかった。
- x: 充電が不安でモバイルバッテリーを多めに持っていったが過剰だった。参加したハンズオン系のセッションでは全部コンセントがあった。
- x: ワイヤレスマウスLift持っていくの忘れて辛かった。Walgreenで急遽買えて助かったが、無駄な出費で悲しい。
ネットワーク周り
- グローバルWiFiレンタル4G無制限プランを借りていった。
- 現地についてから知ったが、ahamoだと特に追加料金なしでローミングできた。10mbps程度。
- レンタルWiFiはずっと速度が微妙だった。1mbps程度。もう途中から充電すらあまりしていなかった。結構高かったのに・・・。あとやはり充電が面倒、次があったらeSIMにしたい。というかahamoローミングがあるからいらない説もある。
- eSIMは使ってみたかったが携帯が対応しておらず断念
衣類
- SWAGパーカーは裏起毛でとても温かい。暖房が効いている場所だと暑いくらい。
- 上着何持っていくか悩み、ウルトラライトダウンベスト(ワイドキルト)とシームレスダウンパーカを持っていった。が、シームレスダウンパーカは腕が動きづらいしかさばるしであまり着なかった。長袖ヒートテック+Tシャツ+SWAGパーカー+ウルトラライトダウンベストくらいで夜はちょっと寒いけどなんとか、くらいだった。
- SWAGのTシャツがいつどれくらい貰えるのか不明瞭だったが、2023の感覚だと以下。
- 資格認定者が貰えるTシャツ:Registrationのホールの後ろ側で受け取りできた。確か3日目くらいに行ったがLサイズはもうなくてXLをもらった気がする。Registrationと同時に貰えば問題なく貰えそう。
- re:playで貰えるTシャツ:すごい数があって多分行けばほぼ貰えそう。4日目の夜なのでタイミングは遅め。
- Expoで貰えるTシャツ:3日目に行ったときはほとんどのブースで無くなっていた印象。ほしいなら初日とかに行ったほうがいいのかも?
- マスクは個人的に持って行ってよかった。ラスベガスは路上喫煙が非常に多く、そこら中で悪臭がしていてしんどかった。またホテルの入り口で何かわからないが変な匂いがしていた。
英語
- 入国審査でDo you travel alone?と聞かれたがaloneが聞き取れず何回も聞き返してしまった。結局相手が翻訳アプリを使ってくれて理解した。
- 聞き取りはOtterを利用してみた。かなり聞き取りには良いが、さらにその文章を翻訳させるのがちょっと手間だった。Chromeの翻訳機能だとotterの書き直しと衝突して文章が変に重なって行ってしまう。
- Keynoteは同時通訳の機器を借りることができ、それで聞いた。
移動関係
- 行きのサンフランシスコ乗継の時間がちょうど2時間で心配していた。たまたま1つ目の飛行機が55分程早く着いたため間に合ったが、時間通りだったら間に合ってなかった。手配会社・・・。
- とにかく税関が時間かかるので、税関に素早く着くのが大事。
- 今回小型スーツケースとリュックを持ち込んで預けもの無しにしたので、それもよかった。
- 空気で膨らませるヨックションを飛行機で使ったが、使わない場合の太ももの血流が圧迫される違和感が明らかに減り、非常に良かった。
- 無印のネッククッションを持っていったが、すごくかさばるのでこちらも膨らませるタイプにしたい。
- 飛行機の揺れが酷いところでは乗り物酔いになった気がする。タクシー・バス移動やモノレールも揺れるので、乗り物酔い薬を持っていけばよかったかも。不味いから飲みたくはないけど。
その他
- 5k
- 荷物が預けられるかを心配していたが、ちゃんと預けられる。ウルトラアリーナのアリーナで預けて紙のリストバンドと交換する。
- ホテル室内用のスリッパを持っていけばよかった。
ISUCON13(2013)参加記録
今年は2名で参戦。おおよそ22000点くらいが最高スコアだった。
https://github.com/shimodatkh/2023-11-25-isu13
決めていたこと
- pproteinで計測する
- go-callvisでコールグラフを見る
- コードはローカルで書いてmainにpush
流れ
- 初回3000点くらいだった
- git周りミスっててリポジトリ作り直したり権限いじったり
- port番号のミスにハマる。pproteinでprofとalpが見えるようになる。
- sqlはスペックのせいかslpがインストールできず見れなくて、諦めて競技サーバでptqueryを手打ちして凌ぐ
- go-callvis動かすと計測サーバがスペックのせいか無反応になってしまうので諦め。ほかサーバではPATHがうまくいかなくて諦め。悲しい・・・
- 12時頃インデックス貼って6000点くらい
- getLivestreamStatisticsHandlerのSQLをまとめようとするが失敗。ここはgithub PRでやったのでrevertしやすかった
- このあたりでプロファイラにsha256.Sum256が目立つ状況になっていたので、hashをテーブルに保存するように修正することにした
- 修正したがbenchmark timeoutでなんだこれ?となる。実はベンチマーカーに障害が起きていた
- しかし、ベンチマーカー障害解消の周知後もbenchmark timeoutが続き、原因がわからない。ただweb画面にアイコンが出なくなっていてアプリがおかしくなっていることはわかっていた
- 結局右往左往したあとrevertした。見直しながら1つずつ入れていくと、型変換ミスに気づいた
db:"name"
忘れ- fillLivestreamResponse N+1改善
- 17:12 13,188点 UserRankingのN+1改善
- SetMaxOpenConns(50)
- 17:32 21,120点 計測系外す
振り返り
pproteinを競技サーバとは別のサーバに置いて使う
今年のISUCONはpproteinを使ってみようと思う。
pprotein用サーバ作成
- pprotein用のec2を立てる. 9000port開け
- static ip割当
- pproteinインストール、起動、ブラウザアクセス
pprotein→競技サーバアクセス疎通
最初IP直でsettingに書いたが穴開いてないので駄目なんだった。本番ではセキュリティグループはいじれないので、ポートフォワードでやってみる。
pprotein用サーバから競技サーバへポートフォワード実行
ssh isucon@18.182.156.175 -L 127.0.0.1:3001:localhost:3000 -i /tmp/isu13
pproteinのgroup/targetsに以下を設定
[ { "Type": "pprof", "Label": "srv1", "URL": "http://localhost:3001/debug/pprof/profile", "Duration": 60 }, { "Type": "httplog", "Label": "srv1", "URL": "http://localhost:3001/debug/log/httplog", "Duration": 60 }, { "Type": "slowlog", "Label": "srv1", "URL": "http://localhost:3001/debug/log/slowlog", "Duration": 60 } ]
これでアクセスが通るようになった。
自動起動設定
pprotein
sudo vi /etc/systemd/system/pprotein.service
[Unit] Description=pprotein service [Service] ExecStart=/home/isucon/pprotein WorkingDirectory=/home/isucon Restart=always User=isucon [Install] WantedBy=multi-user.target
sudo systemctl daemon-reload sudo systemctl restart pprotein.service sudo systemctl status pprotein.service
ポートフォワード
sudo vi /etc/systemd/system/portforward-srv1.service
[Unit] Description=SSH port forwarding [Service] ExecStart=/usr/bin/ssh -i /tmp/isu13 -L 127.0.0.1:3001:localhost:3000 isucon@18.182.156.175 -N Restart=always RestartSec=15 User=isucon [Install] WantedBy=multi-user.target
sudo systemctl daemon-reload sudo systemctl restart portforward-srv1.service sudo systemctl status portforward-srv1.service
ISUCON練習会 過去問(11予選)並走会に参加した
2023/10/21にDiscordのISUCON精進鯖で開催された並走会に参加した。
GitHub - shimodatkh/isucon-practice-11q
- ssh接続
- 10:19 初回走行 2220点
- サービス確認
- ブラウザアクセス確認
- pprotein導入
- pproteinの結果を見る
- nginx設定
- 13:27 インデックス設定 16,311点
- 14:16 trendの不要なデータ取得をlimit 21,788点
- 17:52 postIsuConditionのinsertを非同期&bluk化 27,774点
- 時間経って再開
- dropProbabilityを消してみる:24,178点
- getIsuConditionsFromDBの効率化:71,780点
ssh接続
rlgファイル作る プライベートキーどれだっけ? ユーザ名がubuntuじゃなくてisuconだった
10:19 初回走行 2220点
score: 2220(2248 - 28) : pass
サービス確認
sudo systemctl status
├─nginx.service │ ├─ 524 nginx: master process /usr/sbin/nginx -g daemon on; master_process on; │ ├─3002 nginx: worker process │ └─3003 nginx: worker process ├─mariadb.service │ └─587 /usr/sbin/mysqld ... ├─isucondition.go.service │ └─769 /home/isucon/webapp/go/isucondition ... ├─jiaapi-mock.service │ └─438 /usr/local/bin/jiaapi-mock
ブラウザアクセス確認
JIAのアカウントでログイン を押下するとhttp://localhost:5000/?callback=https://18.~~~
に遷移してしまう。ブラウザで見るのは諦めた。
pprotein導入
2xxと3xxが同じ→キャッシュ効いてそう
静的ファイルならnginxが返せないのかとか検討
pproteinの結果を見る
Avg(RowsExamined):DBから読み込んだ行数 Avg(RowsSent):送った行数
この乖離が大きいのは効率が悪い可能性が高い
nginx設定
isucon@ip-192-168-0-11:~$ alp ltsv --format tsv --file /var/log/nginx/access.log -m "^/api/isu/.+[0-9a-f\-]$,^/api/condition/.+[0-9a-f\-]$,^/api/isu/.+[0-9a-f\-]/graph$,^/api/isu/.+[0-9a-f\-]/icon$,^/isu/.+[0-9a-f\-]$,^/isu/.+[0-9a-f\-]/graph$,^/isu/.+[0-9a-f\-]/condition$" --sort sum -r Count 1xx 2xx 3xx 4xx 5xx Method Uri Min Max Sum Avg P90 P95 P99 Stddev Min(Body) Max(Body) Sum(Body) Avg(Body) 140974 0 131782 0 9192 0 POST ^/api/condition/.+[0-9a-f\-]$ 0.008 0.324 1291.483 0.009 0.020 0.100 0.100 0.026 0.000 14.000 112.000 0.001
pprofの設定をアップデート
matching_groups: - ^/api/condition/.+[0-9a-f\-]$ - ^/api/isu/.+[0-9a-f\-]$ - ^/api/isu/.+[0-9a-f\-]/icon$ - ^/api/isu/.+[0-9a-f\-]/graph$ - ^/isu/.+[0-9a-f\-]/condition$ - ^/isu/.+[0-9a-f\-]/graph$ - ^/isu/.+[0-9a-f\-]$
13:27 インデックス設定 16,311点
まずは
の乖離が多いものにインデックス設定。
CREATE INDEX idx_jia_isu_uuid_timestamp ON isu_condition (jia_isu_uuid, timestamp DESC);
14:16 trendの不要なデータ取得をlimit 21,788点
次に大きそうなtrendを見る。 コードを読んでいると複数行SQLで取得しているのに1行しか使ってないことに気づいた。
"SELECT * FROM
isu_conditionWHERE
jia_isu_uuid= ? ORDER BY timestamp DESC limit 1"
17:52 postIsuConditionのinsertを非同期&bluk化 27,774点
postIsuConditionがhttplogのsumで最大であり、sql.withLockのブロックも大きいことから、細かいinsertが大量に入り待ち状態になっていると想定した。
参考:
postIsuConditionをバックグラウンドバルク化 · tohutohu/isucon-practice-11q@168a4dd · GitHub
時間経って再開
cd bench ./bench -all-addresses 192.168.0.11 -target 192.168.0.11:443 -tls -jia-service-url http://192.168.0.10:4999
sudo mysql -uroot -e "show databases;set global slow_query_log_file = '/var/log/mysql/m ysql-slow.log';set global long_query_time = 0;set global slow_query_log = ON;show variables like 'slow%';"
dropProbabilityを消してみる:24,178点
点数はあまり変わりないが、post conditionの2xx回数が11312>32812と増加。これ自体は今後のためになりそうなので戻さず維持。
getIsuConditionsFromDBの効率化:71,780点
getIsuConditionsFromDBは最後にconditionsResponse[:limit]で20個までで切っているのでここは減らせるはず
ただし取り方が複雑なので少し面倒。とりあえずすぐ手前のSQL2つに limit 20をつけてみる。 ただし、これはcalculateConditionLevelの計算がエラーになる、またはconditionLevelがinfo/warning/criticalにならないような変なデータがあると単純なlimit 20の場合最終的な個数が変わってしまう。
点数は3倍くらいに伸びた。今まで見かけなかった↓のエラーログが出るようになった。
00:18:49.141812 ERR: load: mismatch: GET /api/condition/:jia_isu_uuid か GET /api/isu/:jia_isu_uuid/graph で確認
された condition がありません: 200 (GET: /api/condition/c1b42d3d-2b68-42bb-b0f6-48edfaeb338a?condition_level=warning%2Ccritical&end_time=1629583549)
これは指定したcondition_levelのデータだけを取ってくるということなのでwarning%2Ccritical、つまりinfoは無視していたということ
やはりcondition_levelを事前計算するのがよいか。
当日できたのはここまで。
ISUCON練習 private-isu[4] ~16275点 アプリ書き換え時デバッグ、getIndex・getAccountNameのN+1解消
getIndexの改善
引き続き無駄な部分を改善する。
- コメントは3個まででよい
- UserのデータはAccountNameだけしか使ってないと思われる
GitHub - jmoiron/sqlx: general purpose extensions to golang's database/sql
sqlxは多分、フィールドの配列構造体を直接SQL結果からバインドできない・・・と思う。
- Post
ので、Postの取得とCommentの取得は別SQLで実行する。
デバッグ
post取得部分
SQL
今のpost取得SQL
ポストのユーザとコメント数をくっつけたもの
Go
{ "version": "0.2.0", "configurations": [ { "name": "Launch Go App", "type": "go", "request": "launch", "mode": "debug", "program": "${workspaceFolder}/app.go", "env": { "ISUCONP_DB_HOST": "localhost", "ISUCONP_DB_PORT": "3306", "ISUCONP_DB_USER": "root", "ISUCONP_DB_PASSWORD": "root", "ISUCONP_DB_NAME": "isuconp", "ISUCONP_MEMCACHED_ADDRESS": "memcached:11211" } } ] }
vscodeでデバッグ起動。dockerのmysqlに接続。
docker compose build app && docker compose up -d --force-recreate app
{"pass":true,"score":15863,"success":12204,"fail":0,"messages":}
GET /が0.004secまで行った。
getAccountName
次はURI実行時間が1位になったgetAccountNameを見る。AVGが0.030。
処理を読むとgetIndexと同様のmakePostsを使っていたのでN+1を解消。
{"pass":true,"score":16275,"success":12514,"fail":0,"messages":}
これでgetAccountNameのAVGが0.018になった。
インデックスも改善できるかと思ったが、逆にスコア8000くらいに減ってしまったので取り消し。
CREATE INDEX idx_posts_created_at_user_id ON posts (user_id, created_at desc);
ISUCON練習 private-isu[3] ~13148点 Nginxログ解析、pprof、無効ユーザの除外とpost20個制限
Nginxログ解析
ログフォーマットを設定。
apt update && apt install -y vim vi /etc/nginx/nginx.conf # nginx -t nginx: the configuration file /etc/nginx/nginx.conf syntax is ok nginx: configuration file /etc/nginx/nginx.conf test is successful
alpの集約を調整。
../../../alp.exe json --file access.log -r --sort=sum -m "/image/\d+.(jpg|png|gif), @[a-zA-Z]+, /posts/\d+" | head -n 30
GET /、getIndexが支配的。
プロファイラ
を使う。 コード修正
fgprof導入 · shimodatkh/private-isu@93f42fe · GitHub
docker compose up -d --force-recreate app
go tool pprof --http=:6061 http://localhost:6060/debug/fgprof?seconds=120
を仕掛けてベンチ実行。
getIndexに絞るとこうなった。
コード読み解き
まずはgetIndexを読む。処理を箇条書きで書いてみる。
とりあえず無効ユーザは無駄なこと、Postは20個、コメントは3個まででよいことはわかった。
一旦簡単なところから、無効ユーザの除外とpost20個制限をつけてみる。
getIndex 無効ユーザの除外とpost20個制限 · shimodatkh/private-isu@9c47086 · GitHub
docker compose build app docker compose up -d --force-recreate app
{"pass":true,"score":13148,"success":10431,"fail":0,"messages":[]}
real 1m12.421s
GET /のAVGが0.133から0.030と減っている。
ISUCON練習 private-isu[2] スロークエリ解析、インデックス作成 ~9315点
スロークエリログ設定
webapp\etc\my.cnfに追記
slow_query_log = 1 slow_query_log_file = /var/log/mysql/mysql-slow.log long_query_time = 0
出ないと思ったらパーミッション問題。
mysql: [Warning] World-writable config file '/etc/my.cnf' is ignored.
chmod 644 /etc/my.cnf ls -l /var/log/mysql/mysql-slow.log
これで出るようになった。ログをクリアしてベンチ。
初期状態のスロークエリ解析
pt-query-digestをdockerで実行。
docker run -it --rm -v $(pwd)/$mysql_log_dir/mysql-slow.log:/tmp/mysql-slow.log perconalab/percona-toolkit /bin/bash -c "pt-query-digest /tmp/mysql-slow.log --limit 20" > $mysql_log_dir/mysql-slow-analyze.log
# Profile # Rank Query ID Response time Calls R/Call V/M Item # ==== ================== =============== ===== ====== ===== ============= # 1 0x16849282195BE09F 1214.9183 73.6% 1318 0.9218 0.46 SELECT comments # 2 0x7539A5F45EB76A80 352.4430 21.4% 1346 0.2618 0.29 SELECT comments # 3 0x839C127C71B69E75 37.5151 2.3% 61 0.6150 0.36 SELECT posts # 6 0x3A976F5EBE87A97C 4.8459 0.3% 11 0.4405 0.36 SELECT comments # MISC 0xMISC 40.9680 2.5% 21763 0.0019 0.0 <21 ITEMS>
上位SQLの実行計画取得。
インデックスを作ってみる
mysql -uroot -proot isuconp
ALTER TABLE comments ADD INDEX idx_post_created (post_id, created_at);
$ MSYS_NO_PATHCONV=1 docker run --network host -i private-isu-benchmarker /opt/go/bin/benchmarker -t http://host.docker.internal -u /opt/go/userdata {"pass":true,"score":9659,"success":8170,"fail":0,"messages":[]}
スコアがプラスになった。
スロークエリ解析
# Profile # Rank Query ID Response time Calls R/Call V/M Item # ==== ================== ============= ===== ====== ===== =============== # 1 0x839C127C71B69E75 30.2871 48.2% 765 0.0396 0.06 SELECT posts # 2 0xB2ED5CF03D4E749F 5.7500 9.2% 242 0.0238 0.02 SELECT comments # 3 0x99AA0165670CE848 5.7375 9.1% 88220 0.0001 0.00 ADMIN PREPARE # 4 0xE070DA9421CA8C8D 4.0315 6.4% 43555 0.0001 0.00 SELECT users # 5 0xB718D440CBBB5C55 3.5114 5.6% 3611 0.0010 0.01 SELECT posts # 6 0x3027353C36CAB572 2.4114 3.8% 35 0.0689 0.11 SELECT posts # 7 0x16849282195BE09F 2.0960 3.3% 18612 0.0001 0.00 SELECT comments # 8 0x7539A5F45EB76A80 2.0318 3.2% 19310 0.0001 0.00 SELECT comments
元々の1,2位のクエリが7,8位まで下がった。
さらに追加
R/Callが比較的大きい以下を改善できそうなインデックスを追加。
- 1 0x839C127C71B69E75 30.2871 48.2% 765 0.0396 0.06 SELECT posts
- 2 0xB2ED5CF03D4E749F 5.7500 9.2% 242 0.0238 0.02 SELECT comments
- 5 0xB718D440CBBB5C55 3.5114 5.6% 3611 0.0010 0.01 SELECT posts
- 6 0x3027353C36CAB572 2.4114 3.8% 35 0.0689 0.11 SELECT posts
ALTER TABLE comments DROP INDEX idx_post_created; CREATE INDEX idx_post_id_created_at ON comments (post_id, created_at DESC); CREATE INDEX idx_posts_created_at ON posts (created_at DESC); CREATE INDEX idx_comments_user_id ON comments (user_id);
{"pass":true,"score":9315,"success":7865,"fail":0,"messages":[]}
スコアあまり変化なし。
# Profile # Rank Query ID Response time Calls R/Call V/M Item # ==== ================== ============= ===== ====== ===== =============== # 1 0x839C127C71B69E75 30.7378 52.8% 755 0.0407 0.06 SELECT posts # 2 0x99AA0165670CE848 5.9871 10.3% 90271 0.0001 0.00 ADMIN PREPARE # 3 0xE070DA9421CA8C8D 4.4016 7.6% 45531 0.0001 0.00 SELECT users # 4 0xB718D440CBBB5C55 3.5164 6.0% 3528 0.0010 0.01 SELECT posts # 5 0x7539A5F45EB76A80 2.1383 3.7% 19372 0.0001 0.00 SELECT comments # 6 0x16849282195BE09F 2.1295 3.7% 18699 0.0001 0.00 SELECT comments # 7 0x3027353C36CAB572 2.0670 3.6% 41 0.0504 0.04 SELECT posts # 8 0x4097914B4DBD1C07 1.9715 3.4% 63 0.0313 0.06 INSERT posts # 9 0xC67B1B05D2469241 1.4163 2.4% 248 0.0057 0.00 SELECT posts # 10 0xAB05CA526E3FEDDC 1.3343 2.3% 214 0.0062 0.01 INSERT comments # 11 0x80CA8067F971EA04 0.7754 1.3% 178 0.0044 0.00 INSERT users # 12 0xE819735F00B6DBDF 0.5309 0.9% 248 0.0021 0.00 SELECT posts # 13 0x111FD2D3F3B3B4EB 0.4868 0.8% 90271 0.0000 0.00 ADMIN CLOSE STMT # 14 0x798DE77E477DF648 0.1663 0.3% 1 0.1663 0.00 DELETE posts # 15 0x746D96521AE5B82C 0.1405 0.2% 2150 0.0001 0.00 SET # 16 0x81F9D7F7FA80A53D 0.1245 0.2% 673 0.0002 0.00 SELECT comments # 17 0xE5B367867F4BDDDD 0.0962 0.2% 554 0.0002 0.01 SELECT users # 18 0x3A976F5EBE87A97C 0.0560 0.1% 248 0.0002 0.00 SELECT comments # 19 0xB4BB2E774B30F1D4 0.0319 0.1% 248 0.0001 0.00 SELECT users # 20 0xB2ED5CF03D4E749F 0.0316 0.1% 248 0.0001 0.00 SELECT comments
さっきの - 0xB2ED5CF03D4E749F 5.7500 9.2% 242 0.0238 0.02 SELECT comments が20位まで行ってる。
posts周りのインデックスは効いていないかも。
8以上なのでdescも有効のはず。
mysql> select version(); +-----------+ | version() | +-----------+ | 8.0.34 | +-----------+ mysql> select count(1) from posts; +----------+ | count(1) | +----------+ | 10063 | +----------+
forceしたらようやく実行計画で有効になった。全行取ってくるクエリだから使わない方がマシ、という判断なのかな。
explain SELECT id
, user_id
, body
, mime
, created_at
FROM posts
FORCE INDEX (idx_posts_created_at)
ORDER BY created_at
DESC;