AIでリアルタイム取引プラットフォームを構築したら、時計が嘘をつき始めた

前回の記事で、私はAIに本番インフラへの読み取り専用SSHアクセスを許可し、監査、文書化、監視を行いました。論理的な次のステップは、AIに読み取りだけでなく構築もさせることでした。そこで、Claudeをコパイロットとして、実際のアプリケーション、すなわちOTC金利スワップの価格マッチングプラットフォームを構築しました。リアルタイム、WebSocket、SSO認証、複数のカウンターパーティの補完的な興味を自動的にマッチングするエンジンを備えています。技術スタックはFastAPI、asyncio、SQLiteです。パイロットブローカーとその背後にある約15の銀行カウンターパーティとともに本番環境にデプロイしました。

最初の1か月は順調でした。その後、ブローカーから奇妙な報告が届きました。「時計にまだ時間が残っているのにセッションが切れた」「トレーダーの想定元本がちらつき、消えたり現れたりする」「セッションの時間がおかしい、長すぎる」――私の時計が嘘をつき始めたのです。その原因を突き止めた経緯と、「非同期」という言葉について学んだことを以下に記します。

症状：セッションが時間通りに終わらない

プラットフォームの核心は、固定時間のマッチングセッションです。例えば10分に設定すると、カウントダウン、マッチングウィンドウ、そして終了となります。全員が同じ時計を見ます。ところが本番環境では、600秒に設定したセッションが1202秒（2倍）持続し、別のセッションは1803秒（3倍）続きました。約40のセッションを遡ると、きれいな整数倍は見つからず、以下の分布が見られました：1.0倍、1.2倍、1.41倍、1.5倍、2.0倍、2.5倍、2.67倍、3.0倍、3.5倍……最大5.51倍。10分のセッションが1時間近く続くこともあり、誰も理由を理解できませんでした。

最初の誤った方向：「タイマーのせいだ」

反射的にタイマーコードのバグを疑いました。二重起動や停止忘れなど。単独でテストすると、2秒カウントダウン、3秒マッチングは正確で、単一の遷移、二重起動なし。タイマーは単独では完璧でした。さらに奇妙な（あるいは良い）ことには、本番ではカウントダウンは正確で、30秒ピッタリ。ずれていたのはマッチングフェーズだけでした。違いは何か？カウントダウン中はほとんど何も起こりません。マッチング中は活発で、注文がWebSocket経由で到着し、すべてのクライアントが3秒ごとにAPIをポーリングし、価格フィードが秒間複数回データをプッシュし、サーバーが継続的に状態をブロードキャストします。

タイマーは壊れていませんでした。飢えていたのです。

決め手となった手がかり：エラーの形状

診断を一変させた詳細があります。それは以来私のルールとなっています：エラー分布の形状はバグの種類を示す。離散的バグ（タイマーのリセットや二重カウント）は離散的エラー、つまりきれいな整数倍（×2、×3、×2.67は決して出ない）を生みます。しかし私が目にしたのは連続的な分布でした：1.2倍、1.41倍、2.67倍、3.5倍、5.51倍――連続的な勾配。連続的な勾配は論理バグではなく、競合を示します：負荷が高いほど遅くなり、比例します。伸び率はセッションの活動量と相関していました。そこから、タイマーバグの追跡をやめ、ループをブロックしているものを探しました。

原因：1台の遅いクライアントが全員をブロック

asyncioはシングルスレッドで動作します。サーバー全体（タイマー、注文、ブロードキャスト、WebSocketハートビート）が1つのイベントループを共有します。このループは協調的で、コードが実際に制御を譲るawaitを行うまで、他のコードは実行されません。私のタイマーはawait asyncio.sleep(1)の呼び出しをカウントしていました。理論上、各ループは1秒です。実際には、sleep(1)はループに呼び戻す余裕があるときにのみ再開します。ループが他の処理で忙しい場合、タイマーの1「秒」は1秒に遅延を加えたものになります。遅延したループが蓄積すると、10分のセッションが50分になります。

主な原因はブロードキャスト関数でした。asyncで宣言されてはいましたが、各クライアントに順番に送信し、タイムアウトもなく、タイマーのティックやトレードのたびに待機されていました。1台でも遅い、または半死のクライアント（フリーズしたタブ、期限切れのトークン、ネットワーク側のTCPバッファフル）があると、そのクライアントへの送信がブロードキャストループ全体をブロックします。そしてそのループがブロックされている間、タイマーティックは待たされ、他のすべてのクライアントのハートビートも待たされます。1台の壊れたクライアントがフロア全体を遅くするのです。

すべてがつながった瞬間

真の根本原因の美しさは、1つの症状だけでなく、すべてを説明できることです。「セッションが長すぎる」→ タイマーが飢えで伸びている。「時計に時間があるのに切断される」→ WebSocketハートビートが遅れて到着し、ブラウザが接続断と判断して切断、猶予期間後にクライアントが排除され、時計は最後のティックでフリーズ。「想定元本がちらつく」→ ブロードキャストが遅れて順不同で到着。「トークン期限切れ」のログの嵐 → 遅いリクエストがクライアントに再試行ループを引き起こし、ループ負荷がさらに増大。5つの異なる苦情、1つの病気。5つのバグではなく、5つの仮面をかぶった1つのバグでした。

修正は2つ

1. 壁時計を使用し、ループカウンタを使わない。sleep(1)のカウントをやめました。各フェーズの開始時に絶対デッドラインを固定します：deadline = time.monotonic() + duration。各ティックで、残り時間はceil(deadline - now)で、now >= deadlineになったら即座にフェーズ終了。ループが飽和してティックが遅れても、デッドラインは動きません：セッションは設定された実時間で確実に終了します。ループの遅延は時間を伸ばすのではなく、追いつく形になります（time.monotonic()を使用：NTP調整の影響を受けず、逆戻りしない時計）。

1. 並行ブロードキャスト、クライアントごとに制限付き。ブロードキャストを全クライアントに並行送信（asyncio.gather）するよう書き換え、各送信をasyncio.wait_for(..., timeout=2s)でラップ。遅いクライアント？そのラウンドではメッセージをスキップ（切断はしない、遅いだけで死んでいない）。本当に死んでいるクライアント？削除。結果：ブロードキャストの最悪ケースは約2秒に制限され、全送信時間の合計ではなくなりました。

1文の教訓：async defは何も並行処理にしない。await send()のループは依然として逐次処理。並行処理はgather。

勝利宣言前の証明

「デプロイして祈る」のは嫌でした。毎ティックに1秒の同期的ブロックを注入するテストを書き、飢えを再現可能にしました。修正前（ループカウンタ）：マッチング時間×2。修正後（壁時計）：ブロックを注入しても正確な時間。3つのクライアント（高速、低速（5秒）、死）を用いた2つ目のテストでは、低速はスキップ、死は削除、高速は待たされないことを確認。両テスト合格後、デプロイしました。

得られた教訓

「非同期」は「並行」を意味しません。これがこの物語の核心にある概念的な誤りです。asyncioは並行性の可能性を与えますが、無料では提供しません。各操作を逐次待機するループは、普通のforループと同じく逐次であり、ただ丁寧にブロックするだけです。決して1台のクライアントの遅さを共有状態に影響させてはいけません。ネットワーク通信には常にタイムアウトを設定すべきです。1つのピアのバックプレッシャーが全員の時計を人質に取ることを許してはいけません。時間は反復回数ではなく、時計で測るべきです。sleep(1)のカウントはループが決して遅れないという賭けですが、結局は遅れます。

エラーの形状は診断ツールです。きれいな整数倍 → 離散的論理バグを探す。連続分布 → 競合を探す。この単純な区別が数日を節約してくれました。

そしてメタ的な話：このブログのテーマである、開発者ではないITヘッドがAIを使って本番プラットフォームを投入したこと。AIがコードの多くを書きました。しかしこのバグはコード生成ではなく、推論によって解決されました：連続分布を追跡し、飢え仮説を立て、壁時計とカウンターの選択を行うこと。AIは計測や修正コードの作成には優れたパートナーでしたが、理解は人間の仕事のままでした。まさに3か月前に私が言った通りです：AIはエンジニアを置き換えず、真の仕事である理解に時間を割く余裕を与えるのです。