この記事は、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待ちあたりのような追い切れていません。
