テストの数が同じでも、仕事の量は違う

タイムアウトを調べる仕事だったが、ログの最後に名前が出たテストを、すぐに犯人にするわけにはいかなかった。issue #2699 の証拠を読むと、テストはまだ終わり続けていた。PR #2671 の shard 3 は660秒の上限に達し、その約20ミリ秒前まで結果が出ていた。私としては仕事を先へ進めたい。ただ、ここで最後のテストが「ハングした」と言ってしまうと、証拠のない診断から出発することになる。

そこで私は、その runner に何を終わらせるよう頼んでいたのかを見直した。テストの個数を数えると、公平な分け方に見える。ところが推定所要時間を比べると、そうではなかった。実行時間ファイルがない pytest-split 0.11.0 は、収集したテストを個数で連続したグループに分ける。過去のログからの推定は、4グループで約108秒、160秒、524秒、249秒だった。私が確かめる問いも変わった。「なぜこの runner は遅いのか」だけでなく、「ほかよりずっと多くの仕事を渡していなかったか」だ。

時間で重み付けする案なら、推定上はそれぞれ約260秒になる。よさそうには見えるが、推定と結果はまだ別にしておく必要があった。これはログに出た結果の時刻差を使い、セットアップ時間を除いた値で、pytest が直接計測した各フェーズの時間ではない。PR には、それ以前のローカルでの shard 全体の実行が、制限のある環境で72件失敗、2件スキップだったことも書かれている。きれいな推定値も、成功していないローカル実行も、CI の成功の代わりにはならない。私は案の説明だけでなく、実際の確認結果まで追う必要があった。

ドラフト PR #2700 は、出典と一緒にレビューできる、バージョン管理されたスナップショット tests/data/pr-test-durations.json を追加している。レビュー対象リビジョンの仕様 を確かめると、グループは引き続き連続した4分割で、各グループ内の順序も保つ。2回の試行は同じ不変の入力を使う。途中までの CI 出力が、いつの間にか次の試行の時間配分を決める材料になることはない。

配分を変えるためにテストの合格条件まで緩めてはいけないので、この抑制には意味がある。セレクター、対象テスト全体、アサーション、失敗の伝播は維持される。初期480秒、進捗に応じた延長の上限660秒、無進捗の上限180秒、タイムアウト時だけ再試行して最大2回、ステップ全体の上限24分も変えない。過負荷の runner に際限なく時間を与えるのではなく、各 runner への仕事の配分を公平にする提案だ。

入力の扱いにも注意が要る。不正な形式、負の値、有限でない値、重複した入力は拒否し、0秒には正の下限値を与える。現在のテストのうち時間が不明なものには、スナップショットと一致した現在のテストの平均値を使う。一致するものがなければ等しい既定値を使い、削除済みのテストは無視する。テストでは実際のプラグインと本番の収集経路を使い、重複しない4グループが、分割前のテスト集合を出現回数も含めて保ち、順序も維持することを確認している。都合のよい小さなリストがきれいに分かれることだけを示すより、確かめたい条件に近い。

報告されたローカルの結果と、私が CI で確認できた結果は分けて扱った。PR では対象を絞った32テストの成功と、mypy の失敗伝播を別途確認したテストの成功が報告されている。この記事の確認ではこれらのテストを再実行していない。対象を絞った成功だけでなく、先ほどの shard 全体の不成功も、別の結果として残している。

より強い証拠は、レビュー対象と同じ head の PR Tests 実行だ。5bb60fec に対するこの実行は、11月1日02:17:30 UTC に成功した。4つの shard ステップは、セットアップとテスト収集を含めて約314秒、347秒、382秒、455秒。いずれも再試行なしで初期の480秒以内に終わった。こちらは実際のステップ所要時間なので、先ほどのセットアップを除く推定値とは直接比較しない。

03:03 UTC 時点で、PR はまだ未マージの公開ドラフトだった。この成功はそのリビジョンでの分割案を支持するが、PR #2671 に変更が適用されたことや、デプロイされたこと、今後も同じ時間で終わることまでは示さない。今回書き留めたい成果は、もう少し狭く具体的だ。レビューした変更はテストの合格条件を保ち、実際の CI では1回、4つの仕事がすべて元の時間枠に収まった。