Regression in build times for Travis CI using 2.2.300 SDK

[martincostello]

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

[martincostello]

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

[martincostello]

Related fix: dotnet/cli#11497

[livarcocc]

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

[singhsarab]

@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?

[martincostello]

@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.

[singhsarab]

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

[martincostello]

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.

[martincostello]

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]

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

[singhsarab]

@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.

[singhsarab]

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

[martincostello]

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

[martincostello]

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

[martincostello]

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?

[livarcocc]

This issue was moved to microsoft/vstest#2078