Closed gobater closed 6 years ago
Farwaykorse
commented
6 years ago I'm having the same issue. With just a single project and a few hundred tests.
I can confirm that source discovery fails for TEST macros placed in a namespace.
namespace ExampleTests
{
TEST(A, test1) {} // Warning: Could not find source location for test A.test1
}
TEST(B, test2) {} // all works as expected
csoltenborn
commented
6 years ago This is most likely a duplicate of #227. Fix will be released this week, in the meantime try this build.
Farwaykorse
commented
6 years ago The linked build worked for me.
gobater
commented
6 years ago It works fine for me.
Sorry for the duplicate... :-(
csoltenborn
commented
6 years ago Don't worry, and thanks for letting me know!
gobater
commented
6 years ago Hi,
I still have some issues with the build you provided (1121). Test discovery seems to take much longer than in the past... My solution contains around 20 "EXE" files and a total of ~12000 unittests.
See attached file for details concerning the failure (some details have been removed). gta_debug.txt
In lines 13 and 22 of the debug log, the path is wrong (I guess is just a display issue). In line 17 an empty "error" message appears.
Concerning the 30s timeout: does it make sense to have a "solution discovery timeout" and an "exe" timeout? The EXE "failing" contains losts of tests (~3000) and takes ~7s to list the tests in the command line
Thanks for your support
csoltenborn
commented
6 years ago I'm not aware of changes right now which could cause this... could you maybe enable timestamps and then provide the log files from a test run with 0.12.3 and with the current version, such that we can see where time gets lost?
Concerning the wrong path: You have set Working dir to $(SolutionDir), so I guess that C:\workspace\Apps\Spa\Build\target\windows_x86_dev is indeed the path to your solution? What makes you think that "the path is wrong"?
Line 17 is in fact not an empty line, it's just a line break before printing the warning and error lines ;-)
If "exe timeout" means a different timeout for a certain executable (but the standard timeout for all others), then you can already do this! Use project settings (probably as part of a solution settings file).
Finally, my experience so far is that in most cases, if an executable times out during test discovery, it's a problem of that executable, so I would try to figure out what's going on in the >30s. Not sure why it would be much faster on the command line, though, but I would not rule out that possibility.
gobater
commented
6 years ago Hi Christian,
I sent you via private mail the logfiles (with enabled timestamps) with GTA versions 0.12.3.994 (works fine) and 0.13.2.1123 (fails). Let me know If you also need anything else.
Concerning my remark regarding the Working dir, I was expecting that the command printed in the output of GTA could be "copied" and pasted directly into the console. That is clearly not the case with my settings, which made everything a little confusing, but now I fixed the settings and looks fine.
About Timeouts: with timestamps enabled, I think I understand how they work. The "default" 30s timeout is not a timeout for the complete discovery of all tests in the solution, it is a timeout for each binary file containing tests (in general). That is what I was requesting, so no need to customize it for a certain project :-)
In case you imagine the Problem is in the "executable", I would be happy to provide it to you, but I have used exactly the same binary (no rebuild / relink) between the two runs.
Regards
csoltenborn
commented
6 years ago I haven't seen anything of interest in the log files (despite the two executables with timeout).
The working dir is still different between the two log files, but that shouldn't matter since it did not have any effect during discovery under 0.12.3 (but does now). Does "looks fine" mean that you can now paste the output into the console (as it is indeed supposed to be) and run test discovery, and still as fast as before?
In fact, the only difference I can think of right now concerning execution of test executables is the one mentioned above. I fear that you will have to figure out what makes your executables timeout (and if this is indeed caused by GTA, I will be happy to provide a fix if possible). Here's what I would try:
I have improved the documentation of the timeout option.
gobater
commented
6 years ago Hi,
I've done some additional tests. All tests have been performed without "rebuilding / relinking". Following the results:
Additionally I have checked the "runtime" of the executable in process explorer (debug output disabled):
I have also seen that the executables run really fast during test discovery, but GTA is still running 20s to 30s after the last executable finishes...
Conclusions:
I have sent you per mail more logs. I hope they can help. If not, let me know how can I help you, but I do not see how debugging my binary could help
Regards
csoltenborn
commented
6 years ago Thanks for the log files, and also for your debugging work. Again I haven't seen anything remarkable in the logs...
However, I have seen one case in the past where the code which runs the executables in the case of the new execution framework slows down discovery. Our assumption at that time was that the involved pipes sometimes block for some reason, but we weren't able to figure out the cause, and seems to happen rather seldomly. In think that's probably what your tests are suffering from...
The bad news is that I don't have any knowledge in that area and will not even try to fix that problem. The good news is that you can switch to the old execution framework (and live with the (rather minor) consequences)... In fact, this is the very reason why I have not yet removed the old execution framework ;-)
gobater
commented
6 years ago Which are the differences in the old and new test execution framework? Are both still being maintained. Does the "old" also receive new "features"/ "bugfixes"? It would be a pity to be forced to used the old, if it is not being maintained / improved anymore :-(
The issue is 100% reproducible with one of my binaries (I've tested in different computers). Would it help you to debug/fix the issue? If yes, I could try to provide you the executable. The problem only occurs with 0.13.x, everything was fine in 0.12.x. It shall be something that changed recently.
If you are not even trying to fix the problem, maybe I could try to have a look at it, but I would need some support from you in order to compile and debug GTA.
Thanks
csoltenborn
commented
6 years ago For the differences, have a look here. The old framework has been maintained so far, not sure about the future...
Unfortunately it wouldn't help to provide the executable, since I'm not willing to deep-dive into that stuff any more, I must admit - too less knowledge, too much time...
I would greatly appreciate help on this topic! You will get all the support you need. For compiling and debugging, have a look here.
Here's the problem: GTA would like to parse an executable's output while it is running with the --gtest_list_tests option. However, VS API for launching a process with a debugger attached does not allow that. Therefore, GTA has its own code (the new execution framework) to start the process in suspended mode (and configured such that we can read its output), attach the debugger (if necessary), and then resume the executable. This is implemented in ProcessExecutor. Since the problem appears also without debugger, that's probably the place to look. And with a reproducible example - who knows ;-)
For the sake of completeness: The debugger needs to be attached from within the VS process. Since the adapter code runs in the test framework process (see link above), attaching the debugger means sending a message to the DebuggerAttacherService running inside that VS process. This is done by the MessageBasedDebuggerAttacher.
If you indeed want to give it a try, let's open a new issue and collect the according info over there.
gobater
commented
6 years ago I will give it a try and keep you informed.
csoltenborn
commented
6 years ago Sweet! Not sure whether you receive notifications on that - I've updated the above description...
csoltenborn
commented
6 years ago I have given this issue some more thought, and I think I can at least reduce the problem. Currently, the new execution framework uses the native process execution approach as implemented in ProcessExecutor, the old one relies on the Process class and the test framework's LaunchProcessWithDebuggerAttached() method. The idea would be use ProcessExecutor only for debugging (and if the new execution framework is selected). This would solve your problem and the occasional problem of some tests being executed slowly.
I will try to tackle this today and let you know about the branch...
gobater
commented
6 years ago Hi,
I didn't manage to debug the Code yet, since I only have VS2015, but managed to inspect and analyze the code.
I also saw the option you mention. As you suggest, we could use the "old" Process API for discovery and Process Executor for Running the tests. That could be a valid workaround. I have a few questions/suggestions:
However, I am not sure if we are looking in the right place, since Process Executor has not changed from 0.12.3 (if I diffed correctly). My question here is: if Binary execution in the console is fast (as we have seen in my experiments) why test discovery still takes 20s (in the old fw)? I wish you were right, but I think the problem is somewhere else.
I will try to get another computer with VS2017. I prefer to avoid installing it in my production machine.
Thanks for sharing your thoughts with me Regards
csoltenborn
commented
6 years ago In fact, I went one step further: native process execution is now used only for debugging tests with the new execution framework. See #231...
Concerning your questions: You seem to ask the right stuff :-) The thing is that at the time, I wasn't able to come up with a working solution for debugging a process, so Jonas (my former main contributor) took on the task and came up with the current solution. I.e., I am not able to provide lots of explanation for that code, I fear... However, when we figured that there were occasional problems, he tried to reproduce them by extracting the ProcessExecutor into a simple C++ program and could still see (but not resolve) the problem if I remember correctly. Therefore, I'm rather sure that the (i.e., at least one ;-)) problem is in that code. That you haven't seen the problem with 0.12.3 might be due to the fact that something else has changed, and that "triggers" the problem more often (or in your particular case).
Here's my suggestion: Let's test what I did in the branch mentioned above. This should solve your discovery problem and all problems with test execution. With some luck, problems will also not occur when debugging because of the debugger's overhead, or they will be acceptable because usually not all, but some specific tests are debugged.
If debugging still causes issues, let's start over at that place - I will then invite Jonas to join the discussion, and to (try to) provide the information he got when working on that issue.
Thanks already for your willingness to look into the problem, and for making me rethink it!
gobater
commented
6 years ago The changes you mention in #231 sound really great! Can I have a test build? :-) I hope I can manage today to get a PC with VS2017 which shall allow me to help you in the development.
I will have a look to your Pull Request
Thanks for your support.
csoltenborn
commented
6 years ago Don't be scared by the PR ;-) - I took the opportunity to do some heavy-needed refactoring (as the PR message indicates).
The PR has a link to the resulting builds...
gobater
commented
6 years ago Bad news... :-( Version 0.13.2.1127 does not solve the issue. In fact it makes it (sometimes) worse, in a few tries, more than one binary failed to execute within 30s (many of them differents, excepting our well known old friend, that fails always), while in the past, it was most of the times only one.
I still think the problem is in the somewhere else, i.e. in the C# Action (lambdas?), that process each line in the pipe. I have observed, that the output in the "Test Output" window remains for a long time with just one/two lines like "Found X tests in executable: XXXX.exe", while in the background, Process explorer (task manager) shows that many executables (>5) in my solution (containing tests) have already finished execution.
Is there any possibility to measure (in a debug build) the processing time of the C# Action?, additionally, you could (in another build) forward the stdout+stderr of the process to a "dummy" Action that discards the results without any processing, and measure the "discovery time". That should help us to isolate the problem.
PS: I keep trying to get the stuff compiling in my PC
csoltenborn
commented
6 years ago That's indeed surprising :-|
It should certainly be possible to measure execution times, be it with the Stopwatch and printing the results via the logger (or even to a file). However, I do not have time right now to tackle this...
Do you need any more assistance for getting the thing to compile?
gobater
commented
6 years ago OK. I finally got the project compiling (Excepting Tests_1.7.0) Now fun starts...
csoltenborn
commented
6 years ago Great! Good luck and enjoy... Tests_1.7.0 are not at all crucial, don't worry about them.
One hint: Have a look at the tests, e.g. GetTestsFromExecutable_SampleTestsDebug_FindsTestsWithLocation(). It should be pretty easy to adjust that test such that your problematic executable is used. If this reproduces the error, it will be much easier to debug what's going on compared to launching an experimental instance, triggering discovery etc... Just in case you did not have that idea ;-)
gobater
commented
6 years ago Thx! I already had that Idea, but didn't know where to look for :+1:
csoltenborn
commented
6 years ago One more thing just came to my mind - pretty obvious actually :-)
Commit 8d42a498 makes a change to adjust the DotNetProcessExecutor to the (imo better) behavior of the NativeProcessEecutor: it reads standard as well as error output. Please give bec15743 a try (the one before)...
csoltenborn
commented
6 years ago And, in fact, maybe give the commit before that one a chance, too (where I removed the difference between modes in test discovery) - just make sure to keep the changes in SequentialTestRunner and FrameworkDebuggedProcessExecutor (otherwise, debugging will crash)...
gobater
commented
6 years ago I hope I can get to you with some information soon. I have managed (thanks to your suggestion) to reproduce the problem with the test you suggested (GetTestsFromExecutable_SampleTestsDebug_FindsTestsWithLocation())
Where do I modify the settings the Tests run with? Is it in SampleTests.gta.runsettings?, or shall I modify the SettingsWrapper class default values.
Thanks
gobater
commented
6 years ago I think I am getting closer to the fix.
I've been doing a few tests. It seems that changing the Pipe buffer size helps. I need to do some further checking before confirming since I change many things.
I will keep you informed 😊
csoltenborn
commented
6 years ago In fact, I was also playing with that stuff right now, and I think I've found part of the problem. The regex to identify source locations has become more complex to be able to deal with prefix situations, and that seems to have a bigger performance impact then I would have expected at all...
I have just committed an improvement to the branch - can you give this a try?
csoltenborn
commented
6 years ago I just created a new pull request containing a performance improvement which might fix your issue. In fact, your assumptions were correct: There was indeed a change which triggered it, and at least part of the cause was not in the NativeDebuggedExecutor. I have added a performance test which clearly shows the difference. The fix should in fact make test discovery faster then the pre-0.13.0 releases.
Note that your debugging work is still highly appreciated! Jonas had reproduced the problem during test execution without anything being involved despite the native execution code (as I described somewhere above), so I think that this can be taken for granted. Thus, I will look very closely at whatever you come up with :-)
I'm planning to release this pretty soon as a performance fix, and then to merge the changes of the other branch into develop as base for 0.14.0.
csoltenborn
commented
6 years ago gobater
commented
6 years ago I have just downloaded your pull request #235 and the performance on my "conflictive" binary is impressive! The old 0.13.2 release took around 60 with my binary. My IPC modifications managed to reduce the time to 35s (in a debug build) and your pull request takes just ~6s!
I will have a look in detail to the changes you made and see what I can learn :-)
I always suspected about the Action that process each line of the code, so the first I did was to remove it, and simply execute the binary with the stdout redirected to the pipe. The binary hanged, and never finished execution. However, when I disabled the pipe, the process finished extremely fast. So I went for the Pipe. I've read a lot in the last days about windows IPC and I discovered, that when the pipe buffer becomes full, the "writing" process (the test binary in our case) blocks, until the pipe buffer is emptied. That explained why my first experiment failed. Next I wrote my custom action that "emptied" the buffer discarding the data. It was amazingly fast, so I got closer to the issue, but still needed to confirm that everything was OK with the data transferred along the pipe, so I increased the pipe buffer size to 1MB. The task manager showed that the process executed very fast, but test discovery was still slow so... I've got the confirmation I was looking for... and you got the fix for it :-)
Maybe (even if already obsolete) I submit a pull request to simplify the IPC.
Thanks for not giving up!
csoltenborn
commented
6 years ago Sweet! The relevant changes are in MethodSignatureCreator and TestCaseResolver...
Your observations do not yet explain pipe blocking in the case of only executing that code (i.e., Jonas has approached the problem in a similar way with the code isolated and still observed some kind of blocking), but who knows what plays into that... I will have a look at what's happening during scanning of test results and see whether there are opportunities for performance improvements.
I'm certainly interested in your pull request!
I will then merge the new pull request into master, and then merge that stuff back into the first pull request - would you mind to give it a try afterwards to make sure I haven't broken anything? I have improved on performance testing, but again - who knows? :-)
gobater
commented
6 years ago Hi,
I've just checked out the latest stand in master (16cadb5e39eb21cae9a6a0c899a60ce4bc2eb249) and seems to work perfectly fine :-)
Next week I will try to provide a pull request concerning the IPC. I guess it could improve the performance of test execution if test output is producing lots of warnings...
Again thanks for your support. Looking forward for the official release.
gobater
commented
6 years ago By the way...
I've been checking the logs I sent you. Test discovery of my complete solution, was taking:
You definitely found and fixed the issue :+1:
Hi,
Since latest update (0.13.x), Google Test Adapter cannot find sources and traits for my tests.
I have already checked the information available in: No source locations and traits are found for my tests, but it didn't help.
I have tried following:
I have downgraded to 0.12.3 and everything worked as it used.
Some information about my system and settings:
Enabling debug Output didn't help to find information (I enabled it in the runsettings file viatrue ). I just see hundreds of entries with the text: "Warning: Could not find source location for test", but nothing additional respecting "DebugMode disabled". Am I doing anything wrong?
I have additionally tried setting additional PDB to "$(ExecutableDir)*.pdb" but didn't help :-( Curiously, from my ~12000 tests, the plugin succeeds to find the sources of 3 tests (all contained in the same project), and fails for all others. I can easily find this if I try to group the tests by "Project". Only difference is that those 3 Tests are not in any namespace, while the others are
Let me know if you need additional information to fix this issue.
Regards