Windowsでは一瞬なのにMacでは約5秒止まる
ゲームのシーンが白へフェードする。動画が始まる合図だ。
Windowsではフェードの直後に動画が始まり、保持という間は無い。
同じ操作をWine上のmacOSで行うと、フェードした後の画面が五秒以上白のまま止まり動画はまだ何も映さない。
動画ファイル自体の冒頭にも白い一瞬はあるが、1秒に満たない正しい演出の白だ。止まっているのはその手前で、演出ではない白がもう一段挟まっている。
動画デコードとファイルI/Oを原因候補から外す
動画合成、動画データの展開、出力デバイス列挙を観測し、白停止の原因ではないことを確認した。
合成の一瞬のバグ棄却
映像を重ねる処理が一瞬だけ乱れて白いコマが混じったのではないか。画面を録画して色の変化を追うと、止まっているのは1コマではなく数秒間まるごとで乱れではなく保持だと分かる。
動画データの展開が重い棄却
動画ファイルは150MBを超えるので、白の間にこれを読み込んでいるだけではないかと疑った。ファイルアクセスをそのまま観測すると、白の間に大きな読み込みは一件も無い。動画本体が動き出すのは白が終わった後だった。
出力デバイスの列挙が重い誤読
詳細なログを仕掛けて動きを追った。白の途中に約2秒、何も記録されない空白があった。直後に並ぶ行は音声の出力先候補ばかりで、これを列挙しているから重いのだと考えた。
後で計測の掛け方を変えて確かめ直すと、空白の正体は詳細ログ自体の重さだったという結論に至った。その場所に本物の負荷は無い。計測は、計測している側の重さも記録してしまうことがある。
OSトレースで5秒待ちの発生箇所を測る
詳細ログは重すぎて計測対象を歪めるので、今度は処理を止めないOS標準の生トレースで測り直した。
白の間、ファイルの読み込みは動画にもゲームデータにも無い。候補②はここで完全に消える。
代わりに支配的だったのは、ゲーム内部の複数スレッドが互いにやり取りする小さな読み書きだった。白い窓の約6.3秒のうち5.16秒、82%がこれに費やされている。
回数を数えると2312回。1回あたり平均2.2ミリ秒の応答待ちが、動画が始まる直前まで途切れず続いていた。
ゲームとwineserverの待機を分ける
誰が誰を待たせているかを突き止めるため、ゲーム本体とwineserver（Wineが裏で動かす調整用のプロセス）を同時に観測した。
wineserverは、白の窓のほぼ全体で待機中だった。サンプルの94.7%が次の要求を待つだけの状態で、CPU使用率は4%に満たない。
ゲーム側では複数のスレッドが「解放した」「合図した」を交互に送り合い、そのたびに次のスレッドが応答を待っていた。掛け合いのような動きだ。CPU使用率は32%で、計算というより往復待ちで足踏みしている状態だった。
wineserverは、待たせている側ではなかった。疑うべきは「wineserverが遅い」ことではなく、「毎回wineserverへ聞きに行く作り」だった。
msync欠落で同期がプロセス間通信になる
同期処理のソースを探すと、あるはずの仕組みが見当たらなかった。
プロセス内で完結する高速な同期の実装を探したが、このWineフォークには存在しない。あるのは、必ずwineserverへ問い合わせる経路だけだった。
起動オプションには、msyncを有効にする環境変数WINEMSYNCがすでに渡されている。だがその値を実際に読みに行くコードはどこにも見当たらなかったという事実に行き当たった。渡しているのに、受け取る側が存在しない。
実装したのは、そのmsyncだった。macOS標準のプロセス間共有セマフォ（一枚の整理券のようなもので、それを受け取ったスレッドだけが先に進める仕組み）を使ってプロセス内だけで完結する仕組みだ。これをこのWineフォークへ移植した。
配備して実行すると、白い保持は一瞬に縮んで体感できるほど短くなった。
msync移植後は待機がプロセス内で完結する
観測 A ── 白の82%はスレッド間の待ち
window = 6.33s thread handoff read = 5.16s (82%) n = 2312 / avg 2.2ms
白い窓の内訳をそのまま集計すると、大半がスレッド間のやり取りの応答待ちだった。
観測 B ── wineserverは待たせている側ではない
idle samples = 94.7% CPU使用率 < 4%
wineserverは要求を受けたら即座に返すだけで、詰まりや競合は見られなかった。
観測 C ── msyncの実装が存在しない
msync.c / esync.c = 無し WINEMSYNCを読むコード = 0件
WINEMSYNCは渡されていたが、それを読むmsyncの実装自体がどこにも無かった。
OSトレースから待機原因を絞り込む
録画で持続時間を確定し、詳細ログの誤りに気づいてから測り方を変えた。二つのプロセスを同時に見てソースへ辿り着いた。
録画で持続時間を確定する
画面を録画して色の変化を追い、1コマの乱れではなく数秒間の保持だという点を先に確定させた。
詳細ログで当たりをつける
内部の動きを詳しく記録するログを仕掛け、白の途中に現れる空白の直後の手がかりから候補を立てた。
測り方を変えて候補を検算する
同じ候補を処理を止めない生トレースでもう一度確かめた。詳細ログの重さ自体が空白を作っていたと分かり、候補は消えた。
生トレースで実処理だけを見る
無計装のファイルシステムトレースで白の窓を集計し、スレッド間の応答待ちが支配的だと確定させた。
二つのプロセスを同時に見る
ゲーム本体とwineserverを同時にサンプリングし、待たせている側と待たされている側を切り分けた。
ソースを読んで欠けている実装を確認する
同期処理のソースを探し、期待していた近道の実装が存在しないことをコードで確認した。
同期処理は実装の有無と実行経路を確認する
詳細ログは対象そのものを歪める
重い計測は「重い場所」ではなく「計測している自分の重さ」を教えてしまうことがある。疑わしい箇所ほど処理を止めない生トレースで検算する。
待たせている側と待たされている側を同時に見る
片方だけを観測していると「遅い」としか分からない。両方を同時に見て初めて、誰が誰を足止めしているかが分かる。
渡したフラグが読まれているか確かめる
起動オプションが効いていると信じる前に、それを読むコードが実在するかをソースで確かめる。渡しているだけで、届いていないことがある。
1回は軽くても、回数を数える
1回あたり数ミリ秒の待ちは誤差に見える。だが千の桁で繰り返されれば、体感できる遅さになる。
修正済みの範囲と一般化しない条件
原因と修正は確認済みだが、結果を未検証の範囲へ広げることはしない。
- プロセス内で完結する同期の仕組みを、このWineフォークへ移植した。
- 移植後、白い保持は一瞬に縮んで体感できるほど短くなった。
- 動画を使う複数のタイトルで確認し、副作用は見られなかった。
- 変更はWine本体側のみ。ゲーム側のファイルには触れていない。
- 今回の近道が効くのは、この待ち方の種類に限る。別の種類の待ち合わせでは、依然としてwineserverへの往復が残る可能性がある。
- 音声側で別に見つかっている遅延は、この記録とは原因が独立している。
- 対象は動画再生が始まる直前の区間。ゲーム全体のあらゆる待ち合わせを検証したわけではない。