負荷試験で壊れたのは、性能ではなく発信番号だった

現場でしか確かめられないものが、最後に残った

システムがほぼ出来上がって、最後に残ったのが現場でしか確かめられない類のものだった。

複数の職員が一斉にログインする。収受文書を登録する。起案して決裁に上げる。届いた決裁を承認する。この一連を、何十人分も同時に走らせないと分からないことがある。

だが本番の役所で数十人を集めて、いっせいのせで操作してもらうわけにはいかない。業務が止まる。

だから、負荷試験ツールを作った。

結果として性能の限界も分かったのだが、本当の収穫はそこではなかった。

壁は認証ではなく、フォームだった

この手のシステムを外から叩くとき、普通は認証が難関になる。ところが今回は逆だった。

認証は POST パラメータ1個で通る。 CSRF トークンも、事前のセッション変数も要らない。ここは拍子抜けするほど簡単だった。

本当の壁はフォームの作りである。

収受登録の画面は、全ステップが jQuery の form.serialize() でフォーム全体を往復する作りになっている。1回の登録に70個以上のフィールドが飛ぶ。しかもその中身は、簿冊・決裁経路・分掌事務・文書記号といった相互に依存するマスタの組み合わせで、どれか1つでも辻褄が合わないと登録が通らない。

これを外から組み立てるのは、現実的ではなかった。職員がブラウザで選択肢を選ぶたびに次の選択肢が絞り込まれていく仕組みを、全部再現しなければならないからである。

1本だけ「動くシナリオ」を手で作ることはできる。だがそれでは、部署も簿冊も決裁経路も1種類しか通らない。1本のシナリオを何百本流しても、確かめているのは1本ぶんでしかない。

突破口は、デバッグのためのログだった

行き詰まってデータベースを眺めていて気づいた。

操作ログのテーブルに、$_POST が丸ごと JSON で記録されている。

不具合が出たときに後から追えるように残していたものだ。最大規模の団体では38万件あった。内訳を見ると、収受登録が約5千件、起案が約9千件、決裁の承認が4万5千件。すべて、実際に職員が現場で流したリクエストそのものである。

このログを職員ごとに取り出して、ログインIDと文書IDだけ差し替えて、そのまま投げ返す。

これで2つ同時に片付いた。組み立ての推測がゼロになること。そして部署・簿冊・決裁経路のばらつきが、現場そのままの分布で再現されること。私が想像で作った1本のシナリオより、現場が1年かけて作った5千通りのほうが、明らかに良い試験である。

ハーネスは Go で書いた。単一バイナリなので負荷生成側の機体に置くのが楽で、レスポンスの HTML から入力要素を拾って次の POST を組み立てる — つまりブラウザと同じことをやる。

デバッグのために淡々と溜めていたログが、そのまま試験シナリオの資産になった。

一斉ログインは、思ったほど問題ではなかった

まず気になっていたのが朝の一斉ログインである。8時半に全員が同時にログインする。グループウェアで一番荒れる瞬間だ。

ログインだけを測っても意味がない。実際にはログイン直後にポータル画面が開くので、そこまで含めて完全同時（待ち時間ゼロ）で流した。

同時人数	ログイン p50	ログイン最大	ポータル p50
25名	203ms	369ms	167ms
100名	773ms	5,398ms	159ms
200名	1,681ms	6,400ms	368ms
392名	6,496ms	13,662ms	149ms

392名が同時にログインしても全員成功する。エラーは1件も出ない。ただ待たされるだけだ。最悪で13.7秒。朝の一斉ログインとしては、許容範囲だろう。

面白いのはポータル画面のほうで、392名同時でも p50 が149ms しかない。以前この画面が6秒かかっていた時期があり、索引を足して0.15秒にした経緯がある。その修正が効いたままだと、こうして確認できた。重かったのはログイン処理そのものだったわけである。

索引を疑ったが、外れた

ログインが遅い理由を、私は索引不足だと考えた。

実際そう見えた。ログイン1回ごとに、ログイン情報テーブルの全走査と、勤怠テーブル5万3千行の全走査が走っている。索引を足すと、実行計画は全走査から1行に改善した。

ところが所要時間は6.5秒のまま、まったく変わらなかった。

実行中のサーバを観測して、ようやく分かった。Apache のプロセスが151で頭打ちになっている。ワーカー上限の既定値150だ。そして実行待ちキューが114まで積み上がっていた。4コアに対して28倍の過負荷である。メモリは1.9GB空いていて、swap も増えていない。

つまり、CPU が足りていないだけだった。

仮説より観測が勝った、という当たり前の話ではある。ただ「遅い＝索引」と決め打ちしていたら、効かない索引を足して、直った気になって終わっていた。

本題は、発信番号が重複したこと

性能はだいたい見えた。問題はここからである。

試験で作ったデータを検査して、血の気が引いた。

収受文書を3,493件登録して、そのうち869件が、他の文書と同じ受発番号を持っていた。

受発番号は公文書の背番号である。重複してはいけない。市民に返す文書に書かれ、他の役所との照会にも使われる。同じ番号の文書が2つあるということは、文書管理としては成立していない。

原因はすぐ分かった。採番がこうなっていた。

SELECT MAX(JUHATU_BANGOU) FROM ... WHERE 年度=? AND 文書記号=?
      ↓ PHP側で加算
UPDATE ... SET JUHATU_BANGOU = ?

トランザクションもロックも一意制約もない。同じ年度・文書記号で同時に登録すれば、2人が同じ最大値を読んで、同じ番号を振る。

なぜ現場では起きていなかったか

ここで開発者から「実運用では一度も重複したことがない」と指摘を受けた。

実際そのとおりだった。調べると、衝突はすべて5秒以内、96%は1秒以内に登録されたもの同士である。

実データを見ると、文書記号ひとつあたりの登録は1日1〜10件が大半だった。8時間に10件なら、1秒の窓に2件が重なる確率は0.3%程度。起きなくて当然である。私が90秒に3,500件を叩き込んだから出ただけだ。

ただし、1日86件という繁忙な文書記号も実在した。そこには現実的なリスクがある。

つまり「現場で起きていない」は、直さなくていい理由にはならない。起きていないのではなく、まだ引いていないだけである。

打てる手が、1つしかなかった

普通なら一意制約を張るか、SELECT ... FOR UPDATE で行をロックする。どちらも使えなかった。

一意制約が張れない — このテーブルは履歴型で、同じ文書が更新のたびに行を増やす。同じ番号の行が複数あるのが正常である
FOR UPDATE も使えない — MAX() は集約関数で、しかも対象がビューだった

残ったのは名前付きロックだけである。年度×文書記号を単位にして、採番の読み取りから書き込みまでを囲む。

	登録数	番号衝突	スループット
ロックなし	3,493	869	39.9 req/s
ロックあり	3,431	0	39.2 req/s

衝突は消え、性能の劣化もなかった。ロックの単位を文書記号ごとに分けたので、別の記号の登録は待たされない。

そして一度、間違えた

最初の実装では、ロック名に「受発区分」も含めていた。年度×文書記号×受発区分である。

これで8件の衝突が残った。

採番の SQL をよく見ると、MAX() は受発区分で絞っていない。番号空間は年度×文書記号だけなのに、区分までロック名に入れたせいで、区分違いの同時登録が素通りしていた。

厄介だったのは、私が書いた検証クエリも、まったく同じ盲点を持っていたことだ。区分ごとに集計していたので、区分をまたいだ衝突が見えない。おかげで一度「衝突ゼロ」と誤って報告している。

対策と検証を同じ思い込みで書くと、直っていないものが直ったように見える。

これは今回いちばん怖かった瞬間である。数字は緑だった。緑を見て、私は満足していた。

数え方を、間違えた

試験で作ったデータを検査する段で、私は集計を誤っている。「テーブルの意味を取り違えた」たぐいで、書き留めておく価値がある。

不整合な起案が29件あると報告した。ところがこのテーブルは履歴型で、更新のたびに行が増える。最新行だけを返すビューで数え直すと3件だった。26件は、正常な過去の履歴である。

幸い結論は大きく変わらなかったが、変わっていた可能性は十分にある。番号の衝突を数えたときも、同じ形の取り違えで一度「衝突ゼロ」と報告している。

データの意味を取り違えると、試験そのものが嘘をつく。性能の数字は嘘をつかない。だがそれを解釈する私は、いくらでも嘘をつける。

負荷試験は、性能の道具ではなかった

始めたときは、何人まで耐えられるかを知りたかった。それも分かった。同時ログインは392名まで確認して全員成功、頭打ちはワーカー上限と CPU。構成を変えるべきかどうかの判断材料は揃った。

だが、実際に見つかったものを並べると、こうなる。

見つかったもの	種類
受発番号が同時登録で重複する	正しさ
同じ起案を2人が同時に発信すると文書が二重にできる	正しさ

性能の問題は、1件もなかった。どちらも、複数の人が同時に同じことをしたときにだけ壊れる、正しさの問題だった。

考えてみれば当然である。性能の劣化は、誰かが「遅い」と言えば分かる。現場は必ず気づくし、必ず言ってくる。

だが同時実行の不具合は、そうはいかない。頻度が低いうえに再現条件が分からず、現場からは「たまに変になる」としか報告されない。1秒の窓でしか起きないものを、人が手で再現するのは無理だ。

負荷をかけることの本当の価値は、まれにしか起きないことを、確実に起こせるようになることだった。

速さを測る道具だと思っていたものは、確率を上げる道具だった。

AIとの協働作業での学び

今回いちばん効いたのは、「持っているものを見直す」ほうだった。

私は最初、シナリオを1本ずつ手で作ろうとしていた。70個のフィールドと、絡み合うマスタと格闘して、半日で行き詰まった。突破口になった操作ログは、最初からそこにあった。デバッグという別の目的のために、何年も淡々と溜まり続けていたものである。

ここは AI との相性がよかったところでもある。「フォームをどう組み立てるか」を延々と詰めていたところから、「そもそも組み立て済みのものが残っていないか」へ視点を移す。行き詰まったときに、問い自体を置き換えるのは、一人でやっていると意外に難しい。私は目の前の70個を、あと半日は睨んでいたと思う。

もう1つ。緑は、人を安心させる。

区分をロック名に入れた実装のとき、私の検証クエリは「衝突ゼロ」と出した。数字は緑だった。だが対策と検証を同じ手で、同じ思い込みで書いていた。間違った前提は、対策と検証の両方に等しく効く。だから両方が同じ方向に間違って、きれいに一致してしまう。

これは前回、構築ナビの点検が「繋がっているつもり」だった話と同じ形をしている。本物と少し違う条件で確かめると、緑になる。先月から2回続けて同じ穴に落ちているので、そろそろ癖として認めたほうがいい。

検証は、対策を書いた人とは違う根拠で書かなければ意味が無い。今回はその「違う根拠」を、AI との会話の中で作った。私が「区分ごとに集計している」と説明した瞬間に、番号空間の定義と食い違っていることが浮かんだ。説明することが検証になるのは、相手が人でも AI でも変わらない。

そして最後に、いちばん地味な学び。

負荷試験は、性能に不安があるから流すものだと思っていた。そうではなかった。同時に同じことをされたときに壊れないかを、確率を上げて確かめるためのものだった。性能はそのついでに分かる。

役所のシステムは、8時半に全員が同時に触る。同時に触られることが例外ではなく、前提のシステムである。だとすれば、この試験はこれきりではなく、機能を足すたびに流すものなのだろう。

負荷生成ハーネスは Go（単一バイナリ）。操作ログの実 POST をコーパスとしてリプレイし、ログイン → 収受登録 → 起案 → 決裁上程 → オンライン決裁までを並列実行する。決裁 PDF の生成は承認リクエスト本体には含まれず、画面の隠し iframe がブラウザ側で読みに行く作りだったため、そこも明示的に踏むようにしてある。踏まないと、決裁で一番重い処理が試験から丸ごと抜け落ちる。