Discover test takes a long time about googletestadapter HOT 12 CLOSED

Obviously this affects your TDD abilities... I'm not aware that I have seen something like this - will ask my fellow developer later on. The only way I can think of right now to help with that is to provide a version spitting out some more debug output, i.e., some time stamps during discovery and execution. I'll let you know when that version is available (probably at the weekend).

from googletestadapter.

Thank you.

from googletestadapter.

I've just pushed a version producing execution traces with time stamps, to be downloaded here. Maybe this gives a better idea on what's going on. If more trace messages are needed to identify the cause, I can easily add them, but you can, too - have a look at commit 204c00b.

Traces are written to a text file, the location of which is printed to the test console during discovery and execution.

from googletestadapter.

Trace 1:

13:41:06.124704: DiscoverTests called
13:41:06.124704: Starting discovery
13:41:06.124704: Initialized test environment
13:41:06.124704: Identified test executables
13:41:14.309704: Parsed tests
13:41:14.368704: Resolved test locations
13:41:14.368704: Created tests for executable
13:41:14.369704: Finished test discovery
13:41:31.221704: DiscoverTests called
13:41:31.221704: Starting discovery
13:41:31.221704: Initialized test environment
13:41:31.222704: Identified test executables
13:41:31.283704: Parsed tests
13:41:31.347704: Resolved test locations
13:41:31.347704: Created tests for executable
13:41:31.347704: Finished test discovery
13:41:31.963704: TestExecutor instantiated
13:41:32.231704: RunTests(testcases) called
13:41:32.263704: Filtered test cases
13:41:32.325704: Parsed tests
13:41:32.422704: Resolved test locations
13:41:32.426704: Created tests for executable
13:41:32.426704: Identified all test cases
13:41:32.427704: Computing test runner
13:41:32.429704: Staring runner GoogleTestAdapter.Runners.ParallelTestRunner
13:41:32.464704: Staring runner GoogleTestAdapter.Runners.PreparingTestRunner-0
13:41:32.465704: Staring runner GoogleTestAdapter.Runners.PreparingTestRunner-1
13:41:32.467704: Staring runner GoogleTestAdapter.Runners.SequentialTestRunner
13:41:32.467704: Staring runner GoogleTestAdapter.Runners.SequentialTestRunner
13:41:32.469704: Staring runner GoogleTestAdapter.Runners.PreparingTestRunner-2
13:41:32.470704: Staring runner GoogleTestAdapter.Runners.SequentialTestRunner
13:41:32.544704: Finished runner GoogleTestAdapter.Runners.SequentialTestRunner
13:41:32.545704: Finished runner GoogleTestAdapter.Runners.PreparingTestRunner-2
13:41:32.578704: Finished runner GoogleTestAdapter.Runners.SequentialTestRunner
13:41:32.579704: Finished runner GoogleTestAdapter.Runners.PreparingTestRunner-0
13:41:32.583704: Finished runner GoogleTestAdapter.Runners.SequentialTestRunner
13:41:32.583704: Finished runner GoogleTestAdapter.Runners.PreparingTestRunner-1
13:41:32.583704: Finished runner GoogleTestAdapter.Runners.ParallelTestRunner
13:41:33.784704: Finished test execution

from googletestadapter.

Trace 2:

11:54:14.183111: TestDiscoverer instantiated
13:41:59.866704: DiscoverTests called
13:41:59.866704: Starting discovery
13:41:59.867704: Initialized test environment
13:41:59.892704: Identified test executables
13:42:07.759704: Parsed tests
13:42:08.165704: Resolved test locations
13:42:08.170704: Created tests for executable
13:42:08.391704: Finished test discovery
13:42:24.736704: DiscoverTests called
13:42:24.736704: Starting discovery
13:42:24.736704: Initialized test environment
13:42:24.736704: Identified test executables
13:42:29.004704: Parsed tests
13:42:29.062704: Resolved test locations
13:42:29.062704: Created tests for executable
13:42:29.062704: Finished test discovery
13:42:46.157704: TestExecutor instantiated
13:42:46.434704: RunTests(testcases) called
13:42:46.467704: Filtered test cases
13:42:46.508704: Parsed tests
13:42:46.601704: Resolved test locations
13:42:46.605704: Created tests for executable
13:42:46.605704: Identified all test cases
13:42:46.607704: Computing test runner
13:42:46.608704: Staring runner GoogleTestAdapter.Runners.ParallelTestRunner
13:42:46.641704: Staring runner GoogleTestAdapter.Runners.PreparingTestRunner-0
13:42:46.641704: Staring runner GoogleTestAdapter.Runners.PreparingTestRunner-2
13:42:46.641704: Staring runner GoogleTestAdapter.Runners.PreparingTestRunner-1
13:42:46.643704: Staring runner GoogleTestAdapter.Runners.SequentialTestRunner
13:42:46.643704: Staring runner GoogleTestAdapter.Runners.SequentialTestRunner
13:42:46.643704: Staring runner GoogleTestAdapter.Runners.SequentialTestRunner
13:42:46.728704: Finished runner GoogleTestAdapter.Runners.SequentialTestRunner
13:42:46.729704: Finished runner GoogleTestAdapter.Runners.PreparingTestRunner-2
13:42:46.746704: Finished runner GoogleTestAdapter.Runners.SequentialTestRunner
13:42:46.747704: Finished runner GoogleTestAdapter.Runners.PreparingTestRunner-0
13:42:46.753704: Finished runner GoogleTestAdapter.Runners.SequentialTestRunner
13:42:46.754704: Finished runner GoogleTestAdapter.Runners.PreparingTestRunner-1
13:42:46.754704: Finished runner GoogleTestAdapter.Runners.ParallelTestRunner
13:42:47.955704: Finished test execution

Test output:
------ Discover test started ------
Trace file: C:\Windows\Temp\GTA_ExecutionTrace.txt
Found 3 tests in executable D:\workspace\bcu_applications\test\Debug\database.exe
========== Discover test finished: 3 found (0:00:25.304) ==========
------ Run test started ------
Starting execution
Trace file: C:\Windows\Temp\GTA_ExecutionTrace.txt
Found 3 tests in executable D:\workspace\bcu_applications\test\Debug\database.exe
Running 3 tests...
Executing tests on 3 threads
Test execution completed.
========== Run test finished: 3 run (0:00:23.265) ==========

from googletestadapter.

Any idea why DiscoverTests is being called twice?

from googletestadapter.

No, not really - some aspects the VS test framework are still a mystery (the according method is called by VS)...

I see two different kinds of gaps:

• After "Finished test discovery" - that one is probably totally out of our control, since this is the last in the code we control (and "RunTests(testcases) called" marks the beginning of the execution part we control - the according method is again called by VS). I do not see anything we can do about that, I fear...
• Before "Parsed tests" - that's right within our code (but doesn't seem to always happen, strangely). I will in the next days add some traces within that part of the code, maybe that will help.

One more thing just comes to my mind: When I'm running VS with a debugger attached (i.e. an experimental instance launched in debug mode), and when I have the Child Process Debugging Power Tool activated as described in the docs, I get rather slow execution times - is there any chance that a debugger is involved on your machine?

from googletestadapter.

Ok, I created your version right away (CI makes life so easy :-) ) - download here... But to be honest, it feels like this is a problem of your machine.

from googletestadapter.

New trace:

10:28:23.309001: DiscoverTests called
10:28:23.309001: Starting discovery
10:28:23.309001: Initialized test environment
10:28:23.310001: Identified test executables
10:28:30.649735: Listed tests of executable D:\workspace\bcu_applications\test\Debug\database.exe
10:28:30.649735: Created test case descriptor for test database, testInsertingValuesIntoDatabse
10:28:30.649735: Created test case descriptor for test database, testAThousandRandomSetsAndGetsUnsignedInt
10:28:30.649735: Created test case descriptor for test database, testAThousandRandomSetsAndGetsSignedInt
10:28:30.649735: Created test case descriptors
10:28:30.649735: Parsed tests
10:28:30.708741: Resolved test locations
10:28:30.708741: Created tests for executable D:\workspace\bcu_applications\test\Debug\database.exe
10:28:30.708741: Finished test discovery
10:28:47.286398: DiscoverTests called
10:28:47.286398: Starting discovery
10:28:47.286398: Initialized test environment
10:28:47.286398: Identified test executables
10:28:51.458816: Listed tests of executable D:\workspace\bcu_applications\test\Debug\database.exe
10:28:51.458816: Created test case descriptor for test database, testInsertingValuesIntoDatabse
10:28:51.458816: Created test case descriptor for test database, testAThousandRandomSetsAndGetsUnsignedInt
10:28:51.458816: Created test case descriptor for test database, testAThousandRandomSetsAndGetsSignedInt
10:28:51.458816: Created test case descriptors
10:28:51.458816: Parsed tests
10:28:51.516821: Resolved test locations
10:28:51.516821: Created tests for executable D:\workspace\bcu_applications\test\Debug\database.exe
10:28:51.517822: Finished test discovery
10:29:08.291499: TestExecutor instantiated
10:29:08.561526: RunTests(testcases) called
10:29:08.592529: Filtered test cases
10:29:08.647534: Listed tests of executable D:\workspace\bcu_applications\test\Debug\database.exe
10:29:08.649535: Created test case descriptor for test database, testInsertingValuesIntoDatabse
10:29:08.649535: Created test case descriptor for test database, testAThousandRandomSetsAndGetsUnsignedInt
10:29:08.649535: Created test case descriptor for test database, testAThousandRandomSetsAndGetsSignedInt
10:29:08.649535: Created test case descriptors
10:29:08.649535: Parsed tests
10:29:08.743544: Resolved test locations
10:29:08.746544: Created tests for executable D:\workspace\bcu_applications\test\Debug\database.exe
10:29:08.747544: Identified all test cases
10:29:08.748544: Computing test runner
10:29:08.750545: Staring runner GoogleTestAdapter.Runners.ParallelTestRunner
10:29:08.781548: Staring runner GoogleTestAdapter.Runners.PreparingTestRunner-0
10:29:08.781548: Staring runner GoogleTestAdapter.Runners.PreparingTestRunner-1
10:29:08.781548: Staring runner GoogleTestAdapter.Runners.PreparingTestRunner-2
10:29:08.784548: Staring runner GoogleTestAdapter.Runners.SequentialTestRunner
10:29:08.784548: Staring runner GoogleTestAdapter.Runners.SequentialTestRunner
10:29:08.784548: Staring runner GoogleTestAdapter.Runners.SequentialTestRunner
10:29:08.866556: Finished runner GoogleTestAdapter.Runners.SequentialTestRunner
10:29:08.867556: Finished runner GoogleTestAdapter.Runners.PreparingTestRunner-2
10:29:08.887558: Finished runner GoogleTestAdapter.Runners.SequentialTestRunner
10:29:08.888558: Finished runner GoogleTestAdapter.Runners.PreparingTestRunner-0
10:29:08.892559: Finished runner GoogleTestAdapter.Runners.SequentialTestRunner
10:29:08.893559: Finished runner GoogleTestAdapter.Runners.PreparingTestRunner-1
10:29:08.893559: Finished runner GoogleTestAdapter.Runners.ParallelTestRunner
10:29:10.094679: Finished test execution

from googletestadapter.

I did have the Child Process Debugging Power Tool installed when debugging the other issue I posed about. In trying to resolve this slow discovery process, last week I started uninstalling all extensions. This is one of those already uninstalled, but it's good knowing that it's much slower with this installed. I'm the only one on the team that installed it and nobody else is having these issues. I'm either going to reinstall VS (which takes like 2 hours) or possibly just delete all the user data I can find to see if that fixes it.

from googletestadapter.

Followed this page:
https://blogs.msdn.microsoft.com/zainnab/2010/07/16/reset-all-your-development-settings/

Like magic, all is fixed. Again, thanks for all your help with this.

10:35:52.698935: DiscoverTests called
10:35:52.698935: Starting discovery
10:35:52.698935: Initialized test environment
10:35:52.698935: Identified test executables
10:35:52.785944: Listed tests of executable D:\workspace\bcu_applications\test\Debug\database.exe
10:35:52.785944: Created test case descriptor for test database, testInsertingValuesIntoDatabse
10:35:52.785944: Created test case descriptor for test database, testAThousandRandomSetsAndGetsUnsignedInt
10:35:52.785944: Created test case descriptor for test database, testAThousandRandomSetsAndGetsSignedInt
10:35:52.785944: Created test case descriptors
10:35:52.785944: Parsed tests
10:35:52.848950: Resolved test locations
10:35:52.848950: Created tests for executable D:\workspace\bcu_applications\test\Debug\database.exe
10:35:52.848950: Finished test discovery
10:35:53.136979: TestExecutor instantiated
10:35:53.411007: RunTests(testcases) called
10:35:53.443010: Filtered test cases
10:35:53.486014: Listed tests of executable D:\workspace\bcu_applications\test\Debug\database.exe
10:35:53.488014: Created test case descriptor for test database, testInsertingValuesIntoDatabse
10:35:53.488014: Created test case descriptor for test database, testAThousandRandomSetsAndGetsUnsignedInt
10:35:53.488014: Created test case descriptor for test database, testAThousandRandomSetsAndGetsSignedInt
10:35:53.488014: Created test case descriptors
10:35:53.488014: Parsed tests
10:35:53.582024: Resolved test locations
10:35:53.586024: Created tests for executable D:\workspace\bcu_applications\test\Debug\database.exe
10:35:53.586024: Identified all test cases
10:35:53.588024: Computing test runner
10:35:53.589024: Staring runner GoogleTestAdapter.Runners.ParallelTestRunner
10:35:53.620028: Staring runner GoogleTestAdapter.Runners.PreparingTestRunner-0
10:35:53.620028: Staring runner GoogleTestAdapter.Runners.PreparingTestRunner-1
10:35:53.620028: Staring runner GoogleTestAdapter.Runners.PreparingTestRunner-2
10:35:53.623028: Staring runner GoogleTestAdapter.Runners.SequentialTestRunner
10:35:53.623028: Staring runner GoogleTestAdapter.Runners.SequentialTestRunner
10:35:53.623028: Staring runner GoogleTestAdapter.Runners.SequentialTestRunner
10:35:53.710037: Finished runner GoogleTestAdapter.Runners.SequentialTestRunner
10:35:53.714037: Finished runner GoogleTestAdapter.Runners.PreparingTestRunner-2
10:35:53.731039: Finished runner GoogleTestAdapter.Runners.SequentialTestRunner
10:35:53.732039: Finished runner GoogleTestAdapter.Runners.PreparingTestRunner-0
10:35:53.737039: Finished runner GoogleTestAdapter.Runners.SequentialTestRunner
10:35:53.738039: Finished runner GoogleTestAdapter.Runners.PreparingTestRunner-1
10:35:53.739039: Finished runner GoogleTestAdapter.Runners.ParallelTestRunner
10:35:54.939159: Finished test execution

from googletestadapter.

Weird...

Don't worry, thanks to our CI system it wasn't too much work... Feel free, however, to give us a rating at the VS Gallery :-)

I will then label this issue as invalid and close it.

from googletestadapter.