Test discovery needs a long time to start up

[vko-insiders]

I'm using VS2017 v15.9.16 with GTA 0.16.1.1369 (installed via Tools -> Extensions and Updates).

When clicking on the Test Explorer Tab the GTA seems to need a long time to start up. The green bar on top is running for about 3-5 minutes before the first output in the Output Window appears, saying "------ Discover test started ------". After that it seems to be quite fast.

If it is any help, attached is the gta.runsettings-file:

<RunSettings>
    <GoogleTestAdapterSettings>
        <SolutionSettings>
            <Settings>
                <AdditionalTestExecutionParam />
                <BatchForTestSetup />
                <BatchForTestTeardown />
                <BreakOnFailure>false</BreakOnFailure>
                <CatchExceptions>true</CatchExceptions>
                <OutputMode>Info</OutputMode>
                <TimestampMode>Automatic</TimestampMode>
                <SeverityMode>Automatic</SeverityMode>
                <SummaryMode>WarningOrError</SummaryMode>
                <PrefixOutputWithGta>true</PrefixOutputWithGta>
                <MaxNrOfThreads>0</MaxNrOfThreads>
                <NrOfTestRepetitions>1</NrOfTestRepetitions>
                <ParallelTestExecution>false</ParallelTestExecution>
                <PrintTestOutput>true</PrintTestOutput>
                <RunDisabledTests>false</RunDisabledTests>
                <ShuffleTests>false</ShuffleTests>
                <ShuffleTestsSeed>0</ShuffleTestsSeed>
                <TestDiscoveryRegex>.*\\tests\\.*Test\.exe</TestDiscoveryRegex>
                <AdditionalPdbs/>
                <TestDiscoveryTimeoutInSeconds>150</TestDiscoveryTimeoutInSeconds>
                <WorkingDir>$(ExecutableDir)\..</WorkingDir>
                <PathExtension>$(ExecutableDir)\..</PathExtension>
                <TraitsRegexesAfter />
                <TraitsRegexesBefore />
                <TestNameSeparator />
                <ParseSymbolInformation>true</ParseSymbolInformation>
                <DebuggerKind>Native</DebuggerKind>
                <KillProcessesOnCancel>true</KillProcessesOnCancel>
                <ExitCodeTestCase/>
            </Settings>
        </SolutionSettings>
        <ProjectSettings/>
    </GoogleTestAdapterSettings>
</RunSettings>```

Is there any way to speed up the process?

[csoltenborn]

Can you provide please provide the complete output ending up in the test output window?

[vko-insiders]

I anonymized the output for better readability.

The full output from the Test Output Window is too long to post here, so I divided it into three chunks and uploaded them to pastebin:

• https://pastebin.com/jyjcrrNw
• https://pastebin.com/3en1wNhs
• https://pastebin.com/7A2QHzb4

As for the timings: When navigating from Solution Explorer Window to Test Explorer Window it took a total of 52 seconds until the green bar of the Test Explorer Window started moving.

At about 05:06 minutes first results were shown (about 6400 within 5 seconds)

At about 09:16 minutes about 400 more results were shown, bringing the number up to about 6800 tests

At about 12:16 minutes some results were removed - now showing about 5200 tests in the Test Explroer Window.

At about 14:55 minutes the GTA finished with a little less than 6800 tests.

Not all tests were found, probably because the timeout of 3 minutes is too low. My workaround is to just build a specific test executable I want run in GTA, but even then it needs a long time to start up.

[csoltenborn]

First of all, your attachment appears to consist out of several test discovery runs. Here's some information for you to better understand what's going on:

• ------ Discover test started ------ indicates that VS starts test discovery (e.g. as soon as building has finished). This is not printed by GTA.
• [GTA] Google Test Adapter: Test discovery starting... indicates that VS has called GTA, and that GTA code starts running. Printing this is basically the first thing GTA does.
• Test discovery completed, overall duration: 00:02:56.0693665 indicates that GTA code has finished processing, and that the whole execution has taken 2 mins and 56 secs (which is of course quite a lot). Printing this is basically the last thing GTA does (despite summarizing all errors, which can be switched off).

Note especially that GTA can only be blamed for whatever happens between the 'starting' and 'completed' lines above - everything else is on VS. I nfact, your output contains several 'Test discovery completed' lines (each showing a duration less than 3mins) - not sure why VS would trigger test discovery several times...

Now, here's what you can try next:

• Check out whether the GTA runs mentioned above all try to discover the same tests, or if VS indeed calls GTA over and over, but with different sets of test executables.
• Switch on debugging and time stamping. This will show you in more detail where GTA spends its time (and will massively increase output :-) )
• If I remember correctly, GTA will print test discovery time for each test executable in debug mode. Run test discovery on the console for the problematic ones (in particular the ones timing out). If test discovery takes ages in that cases, your tests are the problem - nothing GTA can do then.
• Try the performance hints of the trouble shooting guide. In particular, disabling symbol parsing will get rid of all the "source location not found" messages, and might help figuring out what's going on.

This might help figuring out what takes that long. However, you appear to be generating lots and lots of test executables, and I haven't seen something like that yet. I would suggest to create (generate?) a script running all executables for test discovery, run that script on the console, and see how long that takes. GTA will run your executables in parallel (using all available processors), but I'm not sure about the actual speed up (after all, GTA needs to report results to VS etc.). Thus, if running all your executables takes, say, 10 or 15 mins, your tests might again be the problem, and there's nothing GTA can do about it.

Let me know about the results!

[csoltenborn]

I have quickly checked, and it indeed appears that e.g. for test executable %some_path%\bin\tests\test_117_Test.exe, test discovery is performed 5 times. That would be consistent with your observation that discovery overall takes 15mins, and my observation that discovery is triggered several (5?) times, each lasting for about 3mins.

Thus, most importantly, you need to figure out why VS triggers test discovery that often - GTA does not have any influence on that. Second, 3mins is still quite long, so maybe there's some optimization potential with respect to that, too...

[vko-insiders]

Thank you very much for your fast answer. I'll have a deeper look into this with this new information.

[vko-insiders]

As for the timing to list all tests from the 133 test-executables: Listing ended in in 33 seconds.

The used Script:

@set /A _tic=%time:~0,2%*3600^
            +%time:~3,1%*10*60^
            +%time:~4,1%*60^
            +%time:~6,1%*10^
            +%time:~7,1% >nul

for %%i in (%some_path%\bin\tests\*.exe) do %%i --gtest_list_tests

@set /A _toc=%time:~0,2%*3600^
            +%time:~3,1%*10*60^
            +%time:~4,1%*60^
            +%time:~6,1%*10^
            +%time:~7,1% >nul

@set /A _elapsed=%_toc%-%_tic
@echo %_elapsed% seconds.

[vko-insiders]

Do you have any suggestions on how I can turn on verbose output in order to find out what VS2017 is doing between opening Test Explorer and GTA starting up?

[csoltenborn]

Have a look at these docs. In general, this might be the right place to ask general questions about the VS test framework.

[vko-insiders]

Thank you very much for your answer. I'll create a ticket on the VS test framework. Setting the Logging level of the Test Explorer in Tools -> Options -> Test -> Logging to Diagnostic, I figured that there are preparations from the Test Explorer for nearly 3 minutes in the solution before the GTA started up.

So there is definitely room for improvements on the side of MS as well.

[csoltenborn]

You're welcome! Any more insights into where GTA spends its time through enabling its Debug mode? Btw: It should be fairly easy to launch GTA from code on your solution - see Wiki (and let me know if you need assistance). That way you might figure out more easily what GTA does when discovering your tests...

[vko-insiders]

Well the anonymized logs of VS2017 until GTA startup are here:

• https://pastebin.com/BKLbGCtt
• https://pastebin.com/K6x0wjcp
• https://pastebin.com/3QwmeYxt
• https://pastebin.com/YgR5rMT7

As for

launch GTA from code on your solution

I'll have a look at that in the wiki as I'm not sure yet what you mean by that.

[csoltenborn]

I meant that it shouldn't be too hard to checkout GTA's code, build it, and than run and debug that code on your C++ solution to investigate GTA's behavior. Basically, the idea is that VS launches a second instance (the so-called experimental instance, from which you can open your C++ solution and run your tests, while at the same time debugging GTA code. See Wiki for how this is done (and don't hesitate to ask).

[csoltenborn]

I had a quick glance at the logs above, and everything appears to be just fine. To get more insight in where GTA spends its time, disable VS diagnostics, set GTA to Debug (not Verbose), and perform test discovery in the case where it takes much longer than the 4s from the above logs (out of which GTA consumes around 1.5s)...

[csoltenborn]

One more thing (always forgot to mention this): I think your gta.runsettings file is not appropriate. Have a look at the docs of the settings, in particular the section starting with:

Note that due to the overriding hierarchy described above, you probably want to provide only a subset of the nodes in your configuration files...

[vko-insiders]

Thank you very much for your answer and sorry for the late reply. I have changed my .gta.settings file accodingly and will have a closer look into debugging the GTA code as soon as I have time to do so.

[csoltenborn]

If you don't mind, I will close this issue until you have more insight into the problem. Feel free to re-open this issue at that point in time!