ISUCON14の参考環境で、Go実装のスコアを 95,656点から567,276点 まで改善しました。最終runはpass=trueで、ベンチマーカーのerror mapはmap[17:6 24:1]でした。542,441点を記録した版からさらに4.6%増えています。
この記事では、自作の計測ツールisutoolsで何を観測し、どの修正を選び、スコアとcorrectnessがどう変わったかを時系列で整理します。50万点を超えていてもcorrectnessでfailしたrunは採用していません。スコアだけでなく、採否の理由も残します。
ベンチマークには揺れがあるため、1回の差だけを厳密な因果効果とは扱いません。一方、各変更を1コミットに分け、1修正ごとにベンチを走らせ、pass=trueを確認してからartifactを保存しています。この運用により、少なくとも「どのコードで何が観測されたか」は追跡できます。
最終結果
| 項目 | 結果 |
|---|---|
| 復旧後の比較可能なbaseline | 95,656 |
| 最終スコア | 567,276 |
| baseline比 | +493.0% |
| 直前の有効最高 | 556,898 |
| 直前比 | +1.86% |
| correctness | pass=true |
| app commit | c8a5d4a |
| artifact ID | 20260806-225651.942413996-000001 |
最終版では、POST /api/chair/coordinateを191,528件処理しながら平均2.2msに収めています。DB pool waitは65,991件、1回あたり平均14.0msでした。CPUはbusy 65.2%、idle 34.7%で、CPUを使い切った状態ではありませんでした。
計測環境
今回の構成はprivate-isuで使ったDocker構成ではなく、ISUCON14の参考環境をWSL2上でsystemd管理したものです。
| 項目 | 構成 |
|---|---|
| application | Go、/home/isucon/webapp/go |
| reverse proxy | nginx、TLS終端、upstreamはUNIX domain socket |
| database | MySQL |
| service | isuride-go.service、isuride-matcher.service |
| benchmark | /home/isucon/bench run |
| isutools | 127.0.0.1:19191、SSH port forwardで閲覧 |
ベンチマーカーのpayment mockはrunごとに未使用ポートを割り当てています。開始直後にss -ltnpでlistenを確認し、前回プロセスやポート競合の影響を除いています。
isutoolsで残したもの
isutoolsは、SQL、HTTP、nginx access log、DB pool、プロセスCPU、host CPU、DB schema、query planを1つのHTMLに保存します。ベンチ終了後にスコアを付けて保存すると、実行時刻、revision、score、diffへのリンクが一覧に残ります。
今回の実行履歴には、採用runだけでなく退行やfailも残しています。失敗した実験を消さないことで、「同じ案を別の名前でもう一度試す」ことを避けられました。
最終レポートの先頭には、HTTP demand、SQL demand、5xx/499、CPU、DB pool、SQL row efficiency、Host I/Oを同じ表で表示しています。
この表は根本原因を自動で断定するものではありません。たとえば542,441点runの最大HTTP累計時間はnotificationですが、現在のnotificationは変更待ちのlong pollingです。並列に待機した時間の合計が大きいため、累計時間だけをCPU需要と解釈すると判断を誤ります。CPU、DB wait、request count、状態通知遅延を併記して読みます。
スコアの時系列
主要な合格runを抜き出すと、次のようになります。
| 段階 | 主な変更 | score | gate |
|---|---|---|---|
| 0 | 計測・サービス復旧後 | 95,656 | pass |
| 1 | rolling Hungarian | 102,260 | pass |
| 2 | matcher入力cache | 149,780 | pass |
| 3 | nearby位置・availability整理 | 210,955 | pass |
| 4 | 距離correctness修正 | 218,468 | pass |
| 5 | notification response cache | 236,006 | pass |
| 6 | matcher周期を100msへ | 285,746 | pass |
| 7 | coordinate transaction短縮 | 309,372 | pass |
| 8 | owner距離の増分管理 | 325,004 | pass |
| 9 | ride statusをmemoryから通知 | 359,732 | pass |
| 10 | chair ACK後にnearby公開 | 392,520 | pass |
| 11 | matcher周期を10msへ | 437,852 | pass |
| 12 | payment transaction短縮 + 100ms visibility grace | 542,441 | pass |
| 13 | matching再公開とnearby再公開を分離 | 567,276 | pass |
ここからは、判断が変わった箇所を中心に説明します。
1. SQLとN+1を整理しました
初期段階では、chairs、chair_locations、rides、ride_statuses、couponsに必要な複合indexを追加しました。GET /api/app/nearby-chairsとowner系endpointのN+1も、まとめて取得するSQLへ変更しました。
この段階では、1本の重いSQLだけでなく、notification pollingから呼ばれる短いSQLの回数も問題でした。1msのSQLでも数十万回実行されれば、DB poolを長時間占有します。以後は「1回の遅さ」と「回数による累計需要」を分けて見ています。
2. 1件ずつのmatcherをrolling Hungarianへ変更しました
初期matcherは500msごとに1 rideだけを割り当てていました。未割当rideとfree chairが複数あっても、割当ての上限は約2件/秒です。
そこで、古い未割当rideとfree chairをwindowで取得し、距離とchair modelの速度をcostにしたHungarian法でまとめて割り当てました。ISURIDEには2地域があるため、遠すぎるchairを無理に割り当てず、一定時間待ったrideだけをstarvation fallbackで救う条件も入れています。
ただし、これはlifelong schedulerではありません。現在は10msごとに現在の候補集合を解くrolling Hungarianです。次の処理は行っていません。
- 一度確定したassignmentの解除と再割当て
- busy chairの完了時刻と完了位置の予測
- 将来到着するrideを含めた時間展開最適化
- assignment churnを含むcommit horizon
障害物のないManhattan格子なので、A*よりdispatch schedulingの方が先の課題でした。
3. マッチングの軌跡を可視化しました
スコアだけでは、2地域の間でどのような割当てが起きたかを確認しにくいため、agent、pickup、destination、assignment eventを再生できるtrajectory viewerをisutoolsへ追加しました。
このsnapshotでは、540 chairs、115,875 points、3,678 rides、3,307 assignmentsを表示しています。同じrideの再割当ては0件でした。この結果も、現在の実装がlifelong再最適化ではないことと一致します。
可視化からは、旧costで2地域間の長距離dispatchが発生していることも分かりました。dummy wait列を持つHungarianに変えるとdispatch Manhattan p95は561から25まで改善しましたが、128 rideをDB transaction内で解いたためpool待ちが増え、scoreは187,425まで下がりました。距離costは参考になりましたが、長いtransaction境界は採用していません。
4. notificationをDB pollingから状態通知へ寄せました
ISUCON14の世界では30msが1 tickです。appとchairのnotificationが高頻度で呼ばれるため、同じride statusを毎回DBから組み立てる処理がDB poolを占有していました。
まずride単位のgenerationを持つresponse cacheを入れました。status挿入、chair assignment、ride更新時にgenerationを進め、生成中に状態が変わったresponseを保存しないようにしています。app_sent_atまたはchair_sent_atが未送信の場合はcacheせず、queueを排出してから再利用します。
次に、状態が変わらないnotificationをevent-driven long pollingへ変更しました。変更前の計測ではapp notificationが約155万回、chair notificationが約37.9万回でした。変更後の比較runでは、それぞれ約14.5万回、約5.6万回まで減りました。
SSEへ移行する方法もありますが、今回はJSON APIの契約を保ったままDB pollingを減らしています。ISUCON14公式解説でも、JSON APIの状態でcacheやlong pollingを使う余地が説明されています。
5. coordinateとstatusのDB往復を減らしました
chairはPOST /api/chair/coordinateの応答が返るまで次の移動を始めません。そのため、このendpointは単なる書込負荷ではなく、ride完了数に直結するcritical pathです。
次の順で同期処理を減らしました。
- INSERT直後に同じ座標rowをSELECTする処理を削除しました。
- 通常の位置更新から長いtransactionを外しました。
- 最新座標をprocess memoryに保持しました。
- latest ride statusを単調増加するmemory stateとして保持しました。
- initialize時にcache generationを作り直しました。
325,004点runではcoordinateが107,643 calls、平均73.6msでした。最終runでは191,528 calls、平均2.2msです。処理数は77.9%増え、平均latencyは97.0%減りました。
ownerのchair総走行距離も、リクエストごとに全chair_locationsへLAGを実行する方式から変更しました。initialize時に一度だけ正確な総距離を作り、以後はcoordinate更新時にManhattan距離を増分加算しています。GET /api/owner/chairsは最終runで平均2.2msでした。
6. matcher周期を100msから10msへ短縮しました
matcher処理自体を軽くした後、poll周期を100msから10msへ短縮しました。ベンチマーカーの30ms tickより細かくrolling windowを更新することで、free chairを次の割当てへ取り込むまでの待ちを減らしています。
この変更で389,614点から437,852点へ上がり、correctnessもpassしました。最終runのGET /api/internal/matchingは1,526 calls、平均19.4ms、p95 134.2msです。
7. paymentをDB transactionの外へ出しました
POST /api/app/rides/:id/evaluationでは、外部payment gatewayへのHTTP requestをDB transaction内で実行していました。payment待ちの間もconnectionとrow lockを保持するため、DB pool waitの大きな要因になります。
修正後は、Idempotency-Keyにride IDを設定してpaymentを先に実行し、成功後だけ短いtransactionを開きます。transaction内では対象rideをFOR UPDATEし、evaluation更新とCOMPLETED確定だけを行います。
この変更単独のraw scoreは591,636でしたが、correctness error code 30が205件出たため採用しませんでした。処理が速くなったことで、serverがevaluationをcommitしてchairを再公開する時点が、benchmark clientがevaluation応答を受け取る時点を追い越したためです。
response全体をlockする方法と、active rideを再確認する方法も試しました。結果は561,815点と519,270点でしたが、どちらもcode 30または31が残りました。
いったん、chairがCOMPLETEDをACKした後も100msだけ再利用を遅らせました。ベンチマーカーは完了したchairがnearbyから3秒以内欠けることを許容するため、その範囲内でserver/client間の観測差を吸収しています。この変更で542,441点になり、correctness gateを通過しました。
8. matching再公開とnearby再公開を分けました
542,441点版では、同じunavailableChairsをmatcherとGET /api/app/nearby-chairsの両方で参照していました。このため、観測順序を守る100ms graceはnearbyの整合性には必要でも、次の割り当てまで一律に止める結果になっていました。
そこで、COMPLETED応答後はmatcherに対してすぐchairを再公開し、nearbyに対してだけ次のchair notification requestまで非表示にしました。次のrequestが来たことを、前のCOMPLETED応答をclientが処理した確認として使います。matcherのスループットとnearbyの観測整合性を、別の境界で管理する形です。
途中の即時公開版は637,737点でしたが、nearbyのcode 30が13件出たため採用しませんでした。分離版は567,276点、pass=trueでcode 30は0件です。同じ割り当て計測を入れた556,898点runと比べると、assignment eventは10,381件から10,760件へ3.7%増え、matching待ちの中央値は7.34秒から5.95秒へ19.0%短くなりました。距離400以上の地域間割り当ては前後とも0件です。
比較を分かりやすくするため、GIFの左側は復旧後baselineの95,656点を記録したコミット72d840f、右側は567,276点の最終runにしました。ただし、95,656点のartifactにはassignment eventが保存されていませんでした。そのため左側の軌跡は、同じアプリケーションコミットへ挙動を変えないmemory-only traceを加え、現在のOS・MySQL・nginx設定上で再実行したものです。この再生run自体は122,320点だったため、GIF内には元artifactの95,656点と再生値の両方を表示しています。右側は最終runで実際に保存したtraceです。
このGIFはchairの全移動軌跡ではありません。各assignmentについて、割り当て時のchair位置からpickupまでの線を、60秒へ正規化して再生しています。初期コミット再生ではassignmentが1,810件、位置を取得できた1,784件のうち距離400以上の地域間割り当てが491件、pickupまでの平均距離が211.3でした。最終版は10,760件、地域間割り当て0件、平均距離13.25です。初期と最終ではアプリ以外の設定も異なるため、95,656点から567,276点までを単一修正の因果効果とは扱っていません。直前版に対する再公開境界分離の効果は、同一計測条件の556,898点との比較で判断しています。
50万点を超えても採用しなかったrun
| commit | raw score | error | 判断 |
|---|---|---|---|
e63bb26 | 591,636 | code 30 ×205 | 不採用 |
54f5f85 | 561,815 | code 30 ×196、code 31 ×313 | 不採用 |
c4d8de8 | 519,270 | code 30 ×244、code 31 ×19 | 不採用 |
4790b53 | 637,737 | code 30 ×13、pass=true | soft errorを増やしたため不採用 |
3bf5e49 | 543,359 | code 30なし、pass=true | 安全だがスループットが戻ったため不採用 |
c8a5d4a | 567,276 | code 30なし、pass=true | 採用 |
4a07343 | 546,855 | DB pool 100→200、pass=true | 退行したためrevert |
ISUCONでは、スコアが高くても仕様不整合があれば採用できません。今回の採用値は、raw scoreが最大だったrunではなく、割り当てを増やしながらnearbyのcode 30を出さなかった567,276点です。
最終レポートで見えている次の課題
| signal | 最終run |
|---|---|
| app notification | 179,908 calls、平均695.0ms |
| chair notification | 109,885 calls、平均270.7ms |
| evaluation | 9,336 calls、平均493.4ms |
| nearby chairs | 74,878 calls、平均16.6ms |
| coordinate | 191,528 calls、平均2.2ms |
| matcher | 1,526 calls、平均19.4ms |
| DB pool | 65,991 waits、平均14.0ms |
| host CPU | busy 65.2%、idle 34.7% |
notificationの平均が大きいのはlong pollingの待機を含むためです。現時点でCPUやdisk I/Oが飽和しているわけではありません。
ベンチマーカーログでは、最終的に87.9%のrideがmatching待ち時間へ不満を持っています。次に改善するなら、現在のpass commitをrollback点として保存し、混雑フェーズのwaiting ageとfree chair数を時系列で計測します。その後、read-only snapshotでcostをtransaction外計算し、短いcommit phaseだけでconditional updateするmatcherを独立実験するのが妥当です。
DB poolは100/100に達していましたが、200へ広げる単独実験は546,855点へ退行しました。pool waitという観測だけから、接続数を増やせば速くなるとは限りません。MySQL側の同時実行競合を増やすため、この変更はrevertしています。
ただし、現在のrolling Hungarianをそのまま「lifelong最適化」とは呼びません。busy chairの将来解放や再割当てまで扱う場合は、append-only assignment history、leaseまたはgeneration、commit horizonを含む別の設計が必要です。
isutoolsで分かったことと、分からなかったこと
isutoolsから直接分かったのは、次のような汎用的な事実です。
- どのendpointとSQLが累計時間を使っているか
- DB pool waitがどの程度あるか
- CPUとI/Oに余力があるか
- 変更前後でrequest count、latency、SQL需要がどう移ったか
- 高いスコアとrevisionが対応しているか
一方、次の内容はISURIDE固有の仕様とベンチマーカーerrorから判断しました。
- chairをnearbyへ再公開してよい正確な時点
- owner salesとCOMPLETED markerの関係
- 2地域間のdispatchをどの距離で見送るか
- evaluation応答受信とserver commitの観測順序
計測ツールがアプリケーション固有の不変条件まで自動で断定することはできません。今回は、isutoolsのresource evidence、ベンチマーカーのcorrectness error、アプリケーションコードの3つを突き合わせました。
この検証で見つかったisutools側の汎用課題は、個別のISURIDE最適化と分けてGitHub Issuesへ記録しています。たとえば、phase shiftや低頻度高影響処理を全期間集計だけでは見落とす問題、SSH port forwardの維持、保存TTL後のfallbackなどです。
他の記録との違い
traPの「ISUCON14感想戦で40万点超えました」では、SSEとevent bus、各種on-memory cache、Badger、owner API、Go 1.24などで417,923点まで改善しています。今回も、coordinate、ride status、active chairをDB hot pathから外す判断は同じ方向です。
実装の共通点と差分を分けると、次のようになります。スコアは環境やrunの需要生成にも左右されるため、この表は優劣ではなく実装範囲の比較です。
| 観点 | 今回の実装 | traPの40万点実装 |
|---|---|---|
| notification | JSON APIを維持し、generation付きresponse cacheとevent-driven long polling | SSEとin-process event bus |
| matching | 2地域の距離上限、starvation救済、rolling Hungarian | 経過時間を含むpriority調整 |
| coordinate | MySQLの履歴を残し、最新位置と総距離をmemoryで増分管理 | chair locationの主データをBadgerへ移動 |
| availability | matching再公開とnearby再公開を別のACK境界で管理 | active chairとride statusのmemory cache |
| 可視化 | assignment trace、2地域viewer、前後比較GIF、isutools artifact | PrometheusとGrafanaでユーザー・椅子の状態分布を表示 |
| 実行環境 | systemd service cgroup、nginx TLS終端、isutoolsのSQL/HTTP/pool/CPU統合計測 | Go 1.24、PGO、sonic、strings.Builderによる低レイヤ最適化 |
今回にしかない実装は、rolling Hungarianそのものだけではありません。2地域間の割り当て抑制、assignment eventの保存、matchingとnearbyの再公開境界分離、correctness errorを含むartifactの時系列保存までを一つの検証経路にしています。特に637,737点版を採用せず、code 30を0件にした567,276点版へ戻した判断は、この経路から得られたものです。
一方、traPの記事にあり、今回まだ実装していないものは次のとおりです。
- chair locationのBadger移行
- app/chair notificationのSSEとevent bus
- Go 1.24のSwiss Table
- PGO、sonic、
strings.Builderによるencode処理の削減 - PrometheusとGrafanaによる状態分布の常設表示
これらをまとめて移植しなかったのは、1修正ごとの効果とcorrectnessを分離できなくなるためです。BadgerやSSEは有力ですが、永続性と通知契約を変えるため単独の小変更ではありません。今回の最終runでは、まず現在のJSON APIとMySQL構成のまま観測できた境界を修正しています。
共通しているのは、latest ride status、latest chair location、active chairをhot pathではmemoryから読むこと、owner APIのN+1を削減すること、nginxとGo間をUNIX domain socketにすることです。同じ方向の改善でも、今回のartifactで効果を確認してから取り込んでいます。
今回の環境では、さらに次の点を別に検証しました。
- systemd service cgroupとnginx TLS終端を含むisutools計測
- rolling Hungarianの軌跡可視化
- 1修正1ベンチのartifact保存
- 50万点を超えたfail runを不採用にするcorrectness運用
- payment transaction短縮で表面化したserver/client visibility race
手法をそのまま移植したのではなく、各段階で現在のレポートに現れた需要を確認してから適用しています。
まとめ
今回の最終結果は567,276点、pass=trueです。95,656点の比較可能baselineから493.0%増えました。
効果が大きかったのは、Hungarian法という名前だけではなく、matcherを複数件処理へ変えたこと、notificationとstatusをDB pollingから外したこと、coordinateを低遅延にしたこと、matcher周期を10msへ短縮したこと、payment待ちをDB transactionから外したことです。
最後は100ms visibility graceを一律に短くするのではなく、matcherとnearbyの再公開を分けました。これによりassignmentを10,381件から10,760件へ増やし、code 30を出さずに567,276点まで伸ばしています。性能改善では、処理時間だけでなく、異なるclientが状態を観測する順序も確認する必要があります。
60万点を狙ってDB poolを100から200へ広げる実験も行いましたが、546,855点へ退行したためrevertしました。今回の時点で、correctnessを保った60万点到達は確認していません。
全コミット、artifact ID、失敗run、rollback理由は、isutoolsリポジトリのcase studyに残しています。