Regression in build times for Travis CI using 2.2.300 SDK

[livarcocc]

From @martincostello on Saturday, June 8, 2019 9:32:34 AM

I've noticed across several different projects I maintain that since the SDK was updated from 2.2.1xx or 2.2.2xx to 2.2.300, the time to build the projects in Travis CI has regressed by up to an order of magnitude on both Linux and macOS.

However I'm not seeing the same regression in Azure DevOps pipelines for Linux, macOS or Windows, or AppVeyor for Windows.

Below are a selection of projects that show a build time regression immediately after merging a PR that contains a commit that updates the SDK to 2.2.300:

History	Build time pre-update	Build time post-update	Delta	PR with SDK update	Commit with SDK update
project-euler	3 min 40 sec	37 min 13 sec	+1,015%	#33	b2c7ed3
JustEat.StatsD	2 min 33 sec	12 min 19 sec	+483%	#177	4f4ac55
sqllocaldb	3 min 31 sec	16 min 28 sec	+468%	#88	671307a
adventofcode	7 min 4 sec	31 min 51 sec	+450%	#72	8ecc3a7
JustSaying	6 min 49 sec	25 min 55 sec	+380%	#545	88f241c
httpclient-interception	6 min 26 sec	16 min 26 sec	+255%	#85	065c722
alexa-london-travel-site	5 min 34 sec	11 min 31 sec	+206%	#267	48b47a5
api	5 min 54 sec	9 min 46 sec	+165%	#112	40c1dee
website	4 min 26 sec	7 min 13 sec	+162%	#263	3a43580

My hunch is that it is related to the new "progress bar" when running dotnet test which is causing the Travis agents to waste a lot of time trying to "draw" it because the actual test run times printed in the build output are equivalent:

• Build before - Time Elapsed 00:00:10.86
• Build after - Time Elapsed 00:00:15.31
• Test before - Test execution time: 46.8778 Seconds
• Test after - Total time: 46.5308 Seconds

Copied from original issue: dotnet/sdk#3314

[livarcocc]

From @martincostello on Saturday, June 8, 2019 9:35:12 AM

Maybe requires integration of #2024? These projects are all using the 16.1.1 NuGet reference, which shows no improvement (commit, build).

[livarcocc]

From @martincostello on Saturday, June 8, 2019 9:42:31 AM

Related fix: dotnet/cli#11497

[livarcocc]

From @livarcocc on Monday, June 10, 2019 8:53:19 PM

Just to confirm further this is potentially a regression on vstest, would it be possible for you to gather these numbers if you turned off tests on your CI, just to collect data?

cc @singhsarab

[livarcocc]

From @singhsarab on Tuesday, June 11, 2019 8:25:59 AM

@martincostello
Progress indicator would not come into play if Console.IsOutputRedirected is set, which I am guessing should be true.

I looked at logs of one of the PRs, https://travis-ci.org/justeat/JustEat.StatsD/jobs/541122616, the total time reported for test run is 10 seconds, let's add some start and cleanup time, even then it should not call for printing the progress bar more than 20 times as it is called after an interval of 1 sec.

Can you please enable logging and share the logs with me?

[livarcocc]

From @martincostello on Tuesday, June 11, 2019 8:28:11 AM

@singhsarab Can you let me know exactly what logging parameters you need setting through dotnet test (info, verbose, debug?), and I'll do a PR to add them to the slowest run and see what happens.

[livarcocc]

From @singhsarab on Tuesday, June 11, 2019 10:26:43 AM

@martincostello You can use --diag:log.txt argument
https://github.com/microsoft/vstest-docs/blob/master/docs/diagnose.md#dotnet-test

[livarcocc]

From @martincostello on Tuesday, June 11, 2019 11:04:00 AM

There's a test running now, it hasn't gotten as far as printing out anything yet, but it seems like whatever is slow is running after the last test finishes before the process exits.

[livarcocc]

From @martincostello on Tuesday, June 11, 2019 12:58:12 PM

There appears to be a 17 minute gap between these two log messages:

TpTrace Verbose: 0 : 5334, 9, 2019/06/11, 12:37:13.427, 134005118760, vstest.console.dll, ParallelProxyExecutionManager: HandlePartialRunComplete: Total completed clients = 1, Run complete = True, Run canceled: False.
TpTrace Verbose: 0 : 5334, 9, 2019/06/11, 12:54:14.143, 1154721904773, vstest.console.dll, TestRunRequest:TestRunComplete: Starting. IsAborted:False IsCanceled:False.

[livarcocc]

From @livarcocc on Wednesday, June 12, 2019 11:58:36 PM

@singhsarab is @martincostello's lastest reply and logs enough for you to make headway on this?

[livarcocc]

From @singhsarab on Thursday, June 13, 2019 12:43:37 AM

@martincostello Thanks for the logs. I am not able to come up with a hypothesis right away. There seems to be some issue while clean up.

Is this issue happening only on travis CI ? I am trying to see if I can get a local repro to debug this one.

[livarcocc]

From @singhsarab on Thursday, June 13, 2019 12:45:08 AM

Let's transfer this to microsoft/vstest, will help us track this better

[livarcocc]

From @martincostello on Thursday, June 13, 2019 5:37:05 AM

@singhsarab Yes, only Travis CI. Locally, AppVeyor and Azure DevOps Pipelines are all fine.

[livarcocc]

From @martincostello on Thursday, June 13, 2019 5:58:37 PM

@singhsarab This issue does not seem to affect .NET Core 3.0 preview 6: https://travis-ci.org/martincostello/project-euler/builds/545376053

[livarcocc]

From @martincostello on Monday, June 17, 2019 7:39:00 PM

One thing I've noticed that's different in Travis CI compared to Azure Dev Ops is that Test run in progress.. gets printed to the console a lot in Travis, but not in Azure.

Could something different be making vstest think it should be printing progress to an interactive console, rather than say not because $(CI) is true in the environment?

[mayankbansal018]

this should be fixed via dotnet/cli#11497, will keep it open for tracking

[lmartuc]

I stumbled upon this issue as well. Our build times went up from around 1 minute to over 30 minutes.

It fails using the 2.1.700 sdk, rolling back to 2.1.604 solved the issue temporarily, but we are interested to know if there is another workaround as we would like to update to dotnet 2.2.

Edit: Diagnosed by running dotnet test -v diag
1843309 ms Microsoft.TestPlatform.Build.Tasks.VSTestTask 1 calls

[martincostello]

I believe the fix for this is in the 2.2.301 SDK that was just released.

[JSkimming]

It looks like Travis has now incorporated the latest SDK releases.

[singhsarab]

Thanks for confirmation @JSkimming @martincostello. Closing this issue.

[davidruhmann]

Since this issue is closed, posted a new issue since this issue still occurs with 2.2.401 on CircleCI
#2120

[martincostello]

I'm also still observing this with the 3.0.100-preview8-013656 SDK - has the fix been ported to the 3.0.0 SDK yet?