この記事は、C# その2 Advent Calendar 2019 の一日目の記事です。
C# で書いたアプリをLinuxやコンテナ環境で動かすことも当たり前になりました。コンテナイメージを作成するのにCircleCI は非常に便利な機能が多く、私も多くの場面で CircleCI をCI環境として第一に選ぶことが多いです。
さて、CircleCI で dotnet sdk を使ってDocker image でビルドを行っていると、「手元で1秒で終わるテストが30秒余りかかったりタイムアウトする」状況に出会うことがあります。
今回はこの「CircleCI で dotnet test の実行が遅い問題」を適切な時間で終わるようにする方法についてみてみましょう。
目次
TL;DR
dotnet test の実行時に < /dev/null 付けて標準入力に null を与えることで CircleCI でのみテストが遅い問題が解消する。
ローカルでは早いテストがCircleCIでのみ遅い状況になった場合は、dotnet test < /dev/null としてみて下さい。
手元では次のグラフのように20秒程度改善し、restore/buildを含めると妥当な実行時間になりました。
環境
CircleCI での dotnet core ビルドなので、Docker Image で行います。
ビルドする環境なので、dotnet core sdk イメージ上で dotnet test を実行します。
- dotnet core: 3.0 1
- Docker Image:
mcr.microsoft.com/dotnet/core/sdk:3.0
dotnet test で行っていること
先に dotnet test が行っていることを把握しておきましょう。
dotnet test コマンドは、まだビルドしていないプロジェクトの場合は、restore + build + test が実行されます。
もし事前に restoreやbuildを行っている場合、それぞれオプション引数の --no-restore、--no-build を使うことでスキップできます。
これらのオプションを指定した場合、nuget packageが restoreされていない、テストに利用する対象 dll といったスキップするべきではない状況ではテストが失敗するので使いどころは選びます。
dotnet test command - .NET Core CLI | Microsoft Docs
つまり、もしCircleCI でテストが時間かかると思っても、restore / build の分は当然時間がかかります。
この記事の問題は、test で時間がかかることが判明している状況です。
どのような問題なのか
.NET Core 3.0 の C# プロジェクトで、ローカル環境の dotnet test や Visual Studio の Test Explorer で実行してみると1sec 以内に終わるテストがあるとします。
このテストを、CircleCI で Dockerイメージ上で dotnet test すると数十秒余計に時間がかかるのが問題です。
なお、dotnet SDK バージョンによっては即時に終わる中身のないテストであってもdotnet test が終わらずタイムアウトします。(CircleCI の無出力時のデフォルトタイムアウト 10min 以上かかっても終わらない)
CircleCI の config.yml は次のようなニュアンスのものです。
version: 2.1 executors: dotnetcore3: docker: - image: mcr.microsoft.com/dotnet/core/sdk:3.0 environment: DOTNET_SKIP_FIRST_TIME_EXPERIENCE: "true" NUGET_XMLDOC_MODE: skip workflows: dev: jobs: - build jobs: build: executor: dotnetcore3 steps: - checkout - run: dotnet build - run: dotnet test -c Debug
問題の再現するC# プロジェクトのサンプルとして次のプロジェクトがあります。(すでに対策された config.yml がコミットされています)
問題のCircleCI のテスト結果は次の通りです。
https://app.circleci.com/jobs/github/tasadar2/vstest-issue-2080/11
NOTE: なお、無出力の問題ではないので
dotnet test -v nでログをたれ流せばいいかというとそういうわけではありません。
コミュニティの状況
この dotnet test がやけに時間かかる問題は、CircleCI 1.0 のころから CircleCI のユーザーフォーラムでちょくちょく言われていたものです。
幸いにして今年6月 (2019/June) に microsoft/vstest リポジトリで Issue が立って、対処方法が練られています。
本状況ですが、docker image のバージョンによってずれがあります。
mcr.microsoft.com/dotnet/core/sdk:2.2.204では再現されずmcr.microsoft.com/dotnet/core/sdkでタイムアウトが発生しdotnet testが完走しないmcr.microsoft.com/dotnet/core/sdk:3.0では 数十秒遅延する
手元のプロジェクトは.NET Core 3.0 で作っており、CircleCI のビルド時間を見ていた時にやけに dotnet test がローカルよりも時間がかかっていることから見つかりました。
対処方法
実はこの問題は、vstest のIssue 前から、x=$(dotnet test); echo $x とすると回避できるというワークアラウンドが見つかっていました。
ただこの方法で回避すると、テスト結果表示がぐちゃぐちゃになるので推奨できません。
またこの回避方法があることから、Console 出力において何かしら問題があることはわかっていました。2
Issue 2080 の中で、コミュニティによって回避方法が2つ見つかっています。
--logger:"console;noprogress=true"を指定してprogress 切る 3< /dev/nullを足して入力がないとみなす
状況から Progress処理に問題がありそうです。
それぞれ見ていきます。
--logger:"console;noprogress=true"は、テスト実行中の状況が見えないため余り好ましくないように思います- 標準入力に null を渡す
< /dev/nullを使うのは、テストが滞りなく実行され出力結果にも影響がないので好ましいでしょう
改善結果
手元のプロジェクトで、4つのUnit Testプロジェクトに対して dotnet test を実行したときの結果を共有します。
| Compare | A UnitTest | B UnitTest | C UnitTest | D UnitTest |
|---|---|---|---|---|
| Before | 00:25 | 00:37 | 00:34 | 00:59 |
dotnet test .... < /dev/null |
00:05 | 00:17 | 00:13 | 00:35 |
dotnet test に < /dev/null を追加するだけでテスト実行時間がやけに遅い問題が解消しています。
注目すべきはどのテストにおいても、before -> after でおおよそ 20sec の改善が見られます。
症状は、dotnet test の実行ログが出た直後に止まって20sec前後 たってから各テストの進捗が出るのでちょうどこの部分が解消されているのが実感と一致しています。
なお、私のほかのプロジェクトで永遠にフリーズしていた問題も解消しています。
結論
CircleCI で dotnet test を実行するときは、dotnet test < /dev/null にしておくと安パイ。
効果がないならほかの原因かもしれないので、これだけが原因と思わず取り掛かるといいでしょう。(今のところ、私はCircleCI 上の dotnet test はこの問題だけ引っ掛かりました)
コード上に具体的に20sec な場所はないものの、Progress の待ち受けがあるところで Infinite なので ServerConnection 待ちあたりのような追い切れていません。
