Apache Traffic ServerのAutestによるテストを高速化

2025-04-28

結果

結論から言うと、並列化無しで1時間46分かかっていたのを、16コア24スレッドのPCで24並列で5分以下に短縮できました。

正確には記事の最後のログのとおり、269.6秒です。

$ python3 -c 'print((60+46)*60/269.6)'
23.590504451038573

24並列で1/23.59の時間になったということで、いわゆるEmbarrassingly parallel - Wikipediaと言われる理想的なケースです。

試したことをメモしておきます。

Apache Traffic ServerのAutestによるテストについて

apache/trafficserverのtestsディレクトリに含まれるE2Eテストです。tests/README.mdに説明があります。

このディレクトリ配下の*.test.pyというファイルがテストケースになっています。2025-04-27時点では379あります。

$ find tests -name '*.test.py' | wc -l
379

テスト実行用のスクリプトファイルはtests/autest.shです。

Reusable Gold Testing System (AuTest)

このテストはReusable Gold Testing System (AuTest) というテスト用エンジンを使って書かれています。

PyPIのページ：autest · PyPI
ソースレポジトリ：autestsuite / reusable-gold-testing-system — Bitbucket
ドキュメント：Welcome to AuTest’s documentation! — AuTest 1.4.0 documentation

また、trafficserverのレポジトリのtests/gold_tests/autest-site/ディレクトリ配下に、trafficserver用の拡張が含まれています。

Proxy Verifier

一部のテストケースではProxy Verifierというツールも使われています。

ソースレポジトリ：yahoo/proxy-verifier

proxy-verifierにはverifier-clientとverifier-serverという実行ファイルが含まれています。

verifier-client -> traficserver -> verfier-server という流れでリクエストを送信・受信して、期待する動作になっているかを確認します。

verifier-clientとverfier-serverはreplayファイルとよばれるyamlファイルを読んで動作します。

verfier-clientはreplayファイルを読んで、そこにかかれたリクエストを順次送信します。verifier-serverはreplayファイルを読んで、そこに書かれたリクエストに対応するリクエストを受信したら、replayファイル内に書かれた対応するレスポンスを返します。

現行のCIでの4並列のシャーディング方式

trafficserverのレポジトリにプルリクエストを送るとCIで様々なチェックが走ります。そのうちの1つにJenkins上で4並列のシャーディングで実行するAuTestのテストがあります。

これはapache/trafficserver-ciレポジトリ内のjenkins/github/autest.pipeline#L137-L164の部分が、一部分のテストを実行する処理です。

testsall=( $( find . -iname "*.test.py" | awk -F'/' '{print $NF}' | awk -F'.' '{print $1}' ) )
# …（略）…
if [ ${SHARDCNT} -le 0 ]; then
        ./autest.sh ${autest_args} || true
else
        testsall=( $(
          for el in  "${testsall[@]}" ; do
            echo $el
          done | sort) )
        ntests=${#testsall[@]}

        shardsize=$((${ntests} / ${SHARDCNT}))
        [ 0 -ne $((${ntests} % ${shardsize})) ] && shardsize=$((${shardsize} + 1))
        shardbeg=$((${shardsize} * ${SHARD}))
        sliced=${testsall[@]:${shardbeg}:${shardsize}}
        ./autest.sh ${autest_args} -f ${sliced[@]} || true

fi

まず、find tests -name '*.test.py'でテストの一覧のリストを作ります。

4つの実行環境のすべてでSHARDCNT=4としておきます。 SHARDのほうは4つの環境で0、1、2、3と異なる値を設定します。これにより、1つめの環境では最初の4分の1、2つめの環境では次の4分の1、といった感じで分担して実行します。

autestの–filter (-f)オプションに実行対象のテストを複数指定できるので、それぞれの実行環境（シャード）で上記のように分割したテストを指定して実行します。

ただ、現状ではテストの一覧をテスト名でソートして4分割しているだけなので、実行時間が長いテストが多く含まれるシャードは他のシャードよりも実行時間が長くなってしまいます。

一番長いremap_aclテストは10分もかかる

tests/gold_tests/remap/remap_acl.test.pyはremap.config（10.0.xのドキュメント）のACL (Access Control List)機能のテストです。

これはいくつかの項目のすべての組み合わせのテストを行っていることもあり、実行時間が長く、私の環境では10分かかります。

trafficserverの起動・停止回数を減らすのを試したが、むしろ遅くなってしまった

Reduce the execution time of Remap ACL AuTest · Issue #11917 · apache/trafficserverに複数のテストケースのremap.configを結合して、trafficserverの起動・停止回数を減らせば早くなるのではないかという話が上がっていました。

hnakamur/trafficserver at make_remap_acl_fastで試してみたのですが、11分47秒とむしろ遅くなってしまいました。クライアントがリクエストを送った後にログファイルをチェックするテストが含まれているため、SIGUSR2のシグナルを送ってログファイルをローテートするように改修したので、その影響かもしれません。が、どこがボトルネックかは計測していないです。

単純に分割して別のシャードで並列に実行したら早くなった

テストケースごとにtrafficserverを起動・停止する方式はそのままで、単純にtests/gold_tests/remap/remap_acl.test.py内のテストケースを4分割して、別のシャードで実行するようにしたところ速くなりました。

試したコードはhnakamur/trafficserver at split_remap_acl_testsに置いています。

remap_aclを4分割しての実行時間は以下のようになりました。

remap_acl_part0 68.0 s
remap_acl_part1 170.9 s
remap_acl_part2 156.3 s
remap_acl_part3 195.9 s

単に分割しただけだから当然ですが、合計は約10分で分割前と変わっていません。

また、tests/gold_tests/h2/http2_flow_control.test.pyも349.9 sと長いので、これも2分割すると154.5 sと168.3 sになりました。

テストをIncusで並列実行するPythonスクリプトを書いた

hnakamur/ats-autestに置いてます。実際は先にこちらを作って試していました。現行のCIのように最初に分担を決めて実行する方式だと、早く終わったシャードは終了してしまい、効率がいまいちです。そこで複数のワーカーが1つのタスクキューからテスト名を受け取って実行するような方式にしました。

シェルスクリプトよりPythonのasyncioを使ったほうが楽に書けそうだったのでPythonで書いてみました。AuTest自体やtrafficserverのAuTestのテストケースもPythonで書かれているので、それに合わせたというのもあります。とはいえ私はバリバリのPython使いではないので、asyncioも初めて使ったのですがChatGPTにいろいろ聞きつつ公式ドキュメントを見て書きました。できればvenv環境を作らずに手軽に実行できるようにしたいと思って、標準ライブラリだけを使うようにしてみました。

ソケットの空きポートを探す方式を変更

autest-on-incusでは、各シャードのワーカーがタスクキューから対象のテスト名を1つ受け取るたびに、autestの-fオプションでそのタスクを指定して実行するようにしています。ところが実装して試してみると、Address already in useエラーでソケットのリッスンに失敗するケースが多発しました。

trafficserverのAuTestのテストではtests/gold_tests/autest-site/ports.pyでソケットの空きポートを探しています。これはLinuxのnet.ipv4.ip_local_port_rangeの範囲が十分広ければ、その範囲のポート番号を順番に使うという仕組みになっています。

trafficserverのCI環境のようにautestの-fオプションで多数のテストを指定して実行する場合は、この方式のほうだとテストごとに範囲内のポートを順番に使っていくのでAddress already in useエラーが出にくいということです。

一方、autestの-fオプションで1つずつテストを実行する場合は、この方式だと同じポート番号ばかりを使おうとするので、むしろAddress already in useエラーが出やすくなってしまいます。

tests/gold_tests/autest-site/ports.pyではnet.ipv4.ip_local_port_rangeの範囲がある程度狭くなると、ポート0を指定してリッスンすることで空きポートを探してもらう方式に切り替わるようになっています。

そこで、autest-on-incusでは実行時にnet.ipv4.ip_local_port_rangeの範囲の範囲を狭めるようにしています。

ポート0で空きポートを探す方式でAddress already in useエラーが出にくくはなりましたが、完全には無くなりませんでした。そこで、テストが一通り終わったら、失敗したテストだけをリトライする仕組みを追加しました。デフォルトで最大3回までリトライします。

長いテストを先に実行するようにソート順を調整

1つのタスクキューにテスト名を流し込む方式にしても、テスト一覧を単純にアルファベット順にソートして流し込むと、最後のほうに長いテストがあるとその分遅くなってしまいます。

具体的にはtests/gold_tests/next_hop/zzz_strategies_peer/zzz_strategies_peer.test.pyとtests/gold_tests/next_hop/zzz_strategies_peer2/zzz_strategies_peer2.test.pyは50秒程度とそこそこ長いので早めに実行するほうが良いことが分かりました。

autest-on-incusではテストごとの実行時間もログ出力するようにしてあります。一度実行してみて長いテストをtier1、tier2にグルーピングして、ソートの際に先頭に持ってくるようにしました。

autest-on-incus#L310-L325で実装しています。

def is_long_test_tier1(test):
    return re.match(r'(remap_acl|http2_flow_control)', test)


def is_long_test_tier2(test):
    return re.match(
        r'(parent-retry|stale_response|proxy_protocol|quick_server|active_timeout|'
        r'ja3_fingerprint|dns_down_nameserver|regex_revalidate_miss|zzz_strategies_peer|'
        r'proxy_serve_stale_dns_fail|config|cache-control|number_of_redirects|ip_allow|'
        r'dns_ttl|inactive_timeout|strategies_ch2|background_fill|chunked_encoding|x_remap|'
        r'tls_client_alpn_configuration|per_client_connection_max|traffic_ctl_config_output)', test)


def sort_tests(tests):
    # Move remap_acl to first since it takes a long time to run
    return sorted(tests, key=lambda x: (f'01{x}' if is_long_test_tier1(x) else f'02{x}' if is_long_test_tier2(x) else x))

これらの改修により、冒頭の結論に書いたとおり5分以下に短縮することが出来ました。

以下はログの抜粋です。round #1では384個のテストを実行して、1つ失敗したためround #2でリトライし成功していたことがわかります。

2025-04-28 00:26:02.619 INFO === start running tests ===
2025-04-28 00:26:11.259 INFO === running round #1 of tests, count=384 ===
2025-04-28 00:26:11.313 INFO worker 0 http2_flow_control_part1 start
2025-04-28 00:26:11.315 INFO worker 14 http2_flow_control_part2 start
2025-04-28 00:26:11.317 INFO worker 13 remap_acl_part0 start
2025-04-28 00:26:11.318 INFO worker 10 remap_acl_part1 start
2025-04-28 00:26:11.319 INFO worker 20 remap_acl_part2 start
2025-04-28 00:26:11.327 INFO worker 16 remap_acl_part3 start
…（略）…
2025-04-28 00:30:14.100 INFO worker 20 url_sig FAILED elapsed: 9.8 (s)
2025-04-28 00:30:21.276 INFO worker 22 uri passed elapsed: 17.9 (s)
2025-04-28 00:30:23.923 INFO worker 2 x_cache_info passed elapsed: 18.1 (s)
2025-04-28 00:30:24.327 INFO worker 3 x_effective_url passed elapsed: 18.3 (s)
2025-04-28 00:30:24.328 INFO finished running round #1 of tests, failed_test count=1, elapsed: 253.1 (s)
2025-04-28 00:30:24.328 INFO === running round #2 of tests, count=1 ===
2025-04-28 00:30:24.378 INFO worker 6 url_sig start
2025-04-28 00:30:29.602 INFO worker 6 url_sig passed elapsed: 5.2 (s)
2025-04-28 00:30:29.602 INFO finished running round #2 of tests, failed_test count=0, elapsed: 5.3 (s)
2025-04-28 00:30:32.261 INFO deleted shards, elapsed: 2.7 (s)
2025-04-28 00:30:32.267 INFO cleaned passed directories, elapsed: 0.0 (s)
2025-04-28 00:30:32.267 INFO === finished running tests. elapsed: 269.6 (s) ===