ISUCON練習会過去問(11予選)並走会に参加した

2023/10/21にDiscordのISUCON精進鯖で開催された並走会に参加した。

ISUCON精進鯖（非公式）について - HackMD

ISUCON練習会過去問並走会 - HackMD

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導入

pprotein導入 - HackMD

2xxと3xxが同じ→キャッシュ効いてそう

静的ファイルならnginxが返せないのかとか検討

pproteinの結果を見る

Avg(RowsExamined)：DBから読み込んだ行数 Avg(RowsSent)：送った行数

この乖離が大きいのは効率が悪い可能性が高い

nginx設定

URIの正規表現パターンを探索する

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点

まずは

Avg(RowsExamined)：DBから読み込んだ行数
Avg(RowsSent)：送った行数

の乖離が多いものにインデックス設定。

CREATE INDEX idx_jia_isu_uuid_timestamp ON isu_condition (jia_isu_uuid, timestamp DESC);

14:16 trendの不要なデータ取得をlimit 21,788点

次に大きそうなtrendを見る。コードを読んでいると複数行SQLで取得しているのに１行しか使ってないことに気づいた。

"SELECT * FROMisu_conditionWHEREjia_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個までで切っているのでここは減らせるはず

ただし取り方が複雑なので少し面倒。とりあえずすぐ手前のSQL２つに limit 20をつけてみる。ただし、これはcalculateConditionLevelの計算がエラーになる、またはconditionLevelがinfo/warning/criticalにならないような変なデータがあると単純なlimit 20の場合最終的な個数が変わってしまう。

点数は３倍くらいに伸びた。今まで見かけなかった↓のエラーログが出るようになった。

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を事前計算するのがよいか。

当日できたのはここまで。

kavo’s diary

備忘録