Difficulty profiling an MSUnit test

Question

Greetings,

Currently, I'm trying to profile a test under MSUnit so I can use it as a source to determine possible bottlenecks in my design, in addition to having it act as a useful test in itself by testing my entire architecture. The problem is that when I profile the test, the displayed report does not display profiling information for all of the functions actually called by the test, despite the libraries containing the functions are referenced by the test project, are actually instrumented properly, and the functions are actually called, which can be confirmed by running the debugger on the test. If I run the profiler on a "normal" binary, all of the functions called are displayed in the report and everything is fine.

The file linked below has an example project I created to illustrate the problem. If one opens the enclosed solution (and ignores the obvious design error) and runs each of the performance reports, one will notice that the two files are different by opening the resulting .vsp files and , yet the test and the program contain exactly the same code.

The sample project I crafted is available here : http://home.lockecole2.org:7777/profrepo3.zip (md5sum : 1a4ff1d0833fc468d78ae11112537dff)

(No, There are no viruses, etc. ; though you shouldn't care since there are only data files in the archive.)

To reproduce exactly, I used the following steps on my MSVS Team System 2008 Development Edition SP1 installation :

1 - Open the provided "profrepo3" solution.
2 - Create a new performance report *without* using the wizard. Add all of the projects to this report.
3 - Set the report to profile using instrumentation and ensure that all the projects instrument small functions.
4 - Start the only binary under instrumentation and wait for it to finish. Keep it's report handy.
5 - Run the provided unit test by opening the provided ".vsmdi" file and selecting the only test. The test should succeed. Add a performance report based on this test's success.
6 - Make sure this new performance report is run under instrumentation and that all the small functions are instrumented.
7 - Re-run the test under the profiler. Hopefully, MSVS2008 won't crash (it does on my machine, depending on the order I add and run performance reports, but that's a seperate issue).
8 - Open both reports and select the "Functions" view. Notice how the report generated by the unit test reports fewer functions than the one run under the "normal" binary.
9 - Now open both the test source (mytest() in test.cs) and the main program source (Main() in Program.cs). Notice that the contents of each function are *exactly the same*.

Is this behavior by design, or just a stupid error on my part?

Thanks for any hints.

Answer 1

Hi lockehold

 

Could you pleas state the step 5 in more detail? What do you mean by 'Add a performance report based on this test's success'? How you instrument the test project. if a dll is set to launch a performance session, Visual Studio may crash.

Answer 2

Bill.Wang - MSFT wrote:

Could you pleas state the step 5 in more detail? What do you mean by 'Add a performance report based on this test's success'?

Sorry about that, I meant to merely add a performance session by right-clicking on the test's "success" row item, then selecting "Create Performance Session...".This session should be set to "instrument" in the wizard, then the DLLs that it will instrument along with the test should be set to instrument all of the functions, as should be stated in the steps.

Bill.Wang - MSFT wrote:

How you instrument the test project. if a dll is set to launch a performance session, Visual Studio may crash.

I have the DLL's that the test uses instrumented, not the test itself, and the test is set as the "binary" that is run when the performance session is executed. I assume that the profiler shouldn't crash if the "binary" running the performance session isn't instrumented, especially considering it works correctly when I only add unit tests, but as I said, that's a different issue (with it's own sample).

Thanks for looking!

Answer 3

In the targets of the performance session, I guess you have set the instrumentation for every assemblies. If you set to instrument an assembly, it will work like start point of instrumentation. In the report generated normal binary, I mean not by the unit test, please change to Modules view. You should be able to see helperlibrary.dll twice. And functions for this library are reported twice in the Functions view.  Please set the instrumentation only on the proprepo3 which is the only executable project and run profiler again.

Answer 4

Bill.Wang - MSFT wrote:

In the targets of the performance session, I guess you have set the instrumentation for every assemblies.

Yes, since I want to collect profiling information for all the functions called by whatever "binary" I am profiling, which includes the underlying libraries.

Bill wrote:

If you set to instrument an assembly, it will work like start point of instrumentation.

Where in the documentation is this stated? I was under the assumption that the "start point of instrumentation" was the only binary instrumented that could be "started up", e.g. a PE file or a "unit test". My intention is to collect profiling information for the binary and all it's underlying libraries.

Bill wrote:

In the report generated normal binary, I mean not by the unit test, please change to Modules view. You should be able to see helperlibrary.dll twice.

That seems like a bug. Is this intended behavior? (and if so, where is it in the documentation?) I don't see this in the project I'm trying to profile "for real", as this "profrepo3" solution is intended only to illustrate the behavior in question.

Bill wrote:

And functions for this library are reported twice in the Functions view.  Please set the instrumentation only on the proprepo3 which is the only executable project and run profiler again.

Alright, doing that makes the duplicate "helperlibrary" reference disappear, but it removes a few functions from the "Functions" view whose profiling data I'd like to see. (the calls to the underlying Dictionary, for instance.)

Guess I should've made my question a bit clearer, so to reinstate, observe the image below :

http://home.lockecole2.org:7777/comparison.png

The top profiler report is run on the normal PE file and has all the functions I want to see profiling data (despite having the duplicated functions), while the report below that one is the profile report run under the provided unit test in the parent post.

My question is, why aren't these profiling reports exactly the same in terms of what functions are displayed in this view, given that the code being executed *is* exactly the same in both the test and the PE file? For example, in the profiling report done by the test, I don't see any data for "worker_bee.work()" or any of the classes from the "profrepo3" assembly, but these functions are present in the report generated from the PE file.

Thanks!

Answer 5

When you instrument an assembly. Visual Studio will inject some code to each function in the that assembly. In the instrumented assembly, the time needed to run functions in it and time needed to directly call functions from referenced assembly are recoded.

 

In you case, the profrepo3 references helperlibrary. If you just instrument profrepo3, the functions calls about the underlying Dictionary will not recorded because they are called from helperlibrary which is not instrumented. But if you instrument both helperlibrary and profrepo3, the profiler will inject code into both assemblies so the function calls to Diction can be recorded. But the report will contain helperlibrary twice. This is the expected behavior. In profrepo3, the time used to call functions in helperlibrary is recorded. In helperlibrary, the time used to run functions within it is also recorded. You can see the time for the reported 2 helperlibrary is not the same. The extra time is consumed by the injected code in helperlibrary. You are recommend to create multiply performance sessions for different perspective.

 

By the way, I appreciate your serious working attitude and hard working style. If there's any problem, please let me know.

Answer 6

Bill.Wang - MSFT wrote:

When you instrument an assembly. Visual Studio will inject some code to each function in the that assembly. In the instrumented assembly, the time needed to run functions in it and time needed to directly call functions from referenced assembly are recoded. <etc... snipped for brevity>

Thanks for the explanation, sounds plausible enough.

However, given that, and I apologize if I'm too dense to deduce why (and if so, for wasting your time), but, observing the following image :

http://home.lockecole2.org:7777/comparison.png

one will notice that they have different functions displayed in the "Functions" view pictured, though both reports were essentially run against the same code, with the same assemblies instrumented. The top report was run against the PE binary, and the bottom was run against the unit test. Again, both execute the same code, so the only difference between the "binaries" run in each of the performance reports is how they're launched by the performance launcher in MSVS.

I guess the question is, does running a performance report (and, by association, the instrumenter) against a unit test instrument/record different information than running the report against a PE binary? That's what seems to be happening in the above image (which should be able to be reproduced with the sample I provided in the parent post).

Said another way, would it be incorrect for me to assume that the function data gathered for both of those performance reports should reflect the same functions being called, given that the code in the unit test and the PE binary is the same, as is all the instrumented binaries?

I tried to see if it was recording the information in the .vsp output and it was just that MSVS's report viewer wasn't picking up on it for some reason, but the .vsp has some sort of proprietary format I don't have time to reverse engineer. These .vsp files I can place online if they're useful for seeing if there's a problem.

Bill wrote:

By the way, I appreciate your serious working attitude and hard working style. If there's any problem, please let me know.

Thanks, I try .

Answer 7

lockecold

 

It seems that there's an issue here. In the performance session created from the unit test, even if the profrepo3 in the targets is set to be instrumented, the binary profrepo3.exe in the out put folder of a test run is NOT instrumented. You can verify this in following steps:

1. Launce the performance session for the unit test.
2. Navigate to the Out folder of that test run.
3. Open command window and run VsInstr against the profrepo3.exe. For example, vsinstr "test_ run\Out\profrepo3.exe". To my surprise, this command runs successfully. So, profrepo3.exe is not instrumented during launching performance session. If you run this command again, it will notify the assembly can only be instrumented once. VsInstr is located in "%Program Files%\Microsoft Visual Studio 9.0\Team Tools\Performance Tools".

 

I will do more investigate on this issue and report it to my tech lead. Thank you for finding this issue . That explains while functions in profrepo3.exe are missed in the performance report for session created from unit test.

Answer 8

Heya,

Bill.Wang - MSFT wrote:

It seems that there's an issue here. <snipped the rest>

Any possible timeline of resolution on this issue, out of curiosity?

Answer 9

Alright, I've investigated this issue more.

Here's what seems to be happening :

* After creating the performance session, I click on "Launch Session".
* This causes the IDE to force recompilation of a few DLLs, of which I don't know about. Due to the following point, I'm guessing it's forcing recompilation of the underlying DLLs I plan to profile.
* Then, the performance session instruments all the underlying DLLs. This I have verified from looking at logger outputs and checking md5 checksums before and after the recompilation described below.
* Then, the performance logic forces compilation of the test container DLL, which then forces compilation of the dependent DLLs, the very ones I plan to profile! I have detailed MSVS08 log output that verifies this.
* Finally, the performance session is executed and only one DLL manages to be instrumented, while the rest are un-instrumented, and thus, useless.

So my question is, why doesn't the performance logic wait for the test to prepare itself before instrumenting? It seems kind of obvious that everything should be compiled before trying to instrument any binaries, so the instrumention should be performed in the test output folder, not in the project folder structure.

In addition, why does one DLL manage to escape being rebuilt? It looks like the performance logic copies one before recompiling the test project for some reason. I want to verify this, but I can't find any way to tell the performance logic to log it's operations to a file, oddly enough. I imagine there must be some hidden options somewhere.

Now, as a solution, I wanted to try placing the instrumented DLLs in a seperate directory so that they won't be overwritten by the eventual rebuild, but I can't do this since there's a node in the performance session file called "TestBinary" under the "Binaries" node, which I assume disables the "redirect" output in the property pages.

Thanks for any hints.

[edit]
Seems to be an issue with MSTest . . .

[edit2]
I've crafted a workaround which is extremely hackish.

Basically, I went into MSTest and configured the test scaffold to run a setup script, which then runs a custom program that simply goes through all the DLLs in the current directory and instruments them.

This produces what seems to be the correct results, yet, the hack should not be necessary. The performance logic should be smart enough to work with the MSTest scaffolding.

Answer 10

I just want to chime in that I'm experiencing the same problem. I "Create performance session" on my test method, I go launch the session and I see the build happen, then the instrumentation happen and then the build happen again. So then, when it runs, I end up with no profiling data for my report.

Someone definitely made a boo boo @ MS (perhaps in SP1?) because, while I haven't used the feature in a while, this definitely used to work flawlessly.

Later,
Drew

Answer 11

So I just found a really easy way to prevent the second build from happening and overwriting the instrumented binaries. When the second build starts, after profiling, stop it with CTRL+BREAK. It will then ask you if you want to continue with your profiling session despite the fact that the build was stopped, say yes and you'll get a good profiling session.

Pain in the ____ for sure, but... at least I'm finally getting my performance data again. So when can we expect a fix? :)

Answer 12

Thank Drew for proving the workaround. This definitely seems like a bug in VSTS. We will investigate it as such, and provide a fix in the future.

---

Daryush Laqab - MSFT ---------------------- To help our tracking, please mark replies as answers if they resolve your issue.

Answer 13

We're also getting this problem, but ours seems to come from a combination of two things;

1) building a project into a folder other than the usual bin\debug or bin\release location.
2) setting CopyLocal=false on a project reference.

Our product splits up into two parts; a runtime, and a series of plugins. The runtime dynamically searches through its folder for plugin assemblies, and loads them automatically. On a build, we expect to have a directory structure like this;

    c:\runtime\
        runtime.core.dll
        runtime.dll
        plugin1.dll
        plugin2.dll

Consequently, when we create a plugin project, we set it to build into the runtime's folder (c:\runtime , instead of bin\debug ). This allows the runtime to find it when it runs.

The plugins reference parts of the runtime -- say, 'runtime.core.dll'. When we build the plugin, we don't want to overwrite the existing assembly at 'c:\runtime\runtime.core.dll '. So when we add the reference to runtime.core.dll in the plugin, we set 'Copy Local=false ', and this ensures we don't replace the core dll.

All this works fine; visual studio has no problems with the build, running the app, or with debugging. There are no problems starting the app. We've worked happily this way for years.

Now, when it comes to a test, we want to test classes in the plugins. So if plugin1.dll contains a class called `plugin1.MyPluginClass `, that we want to test, we create a test project that explicitly reference both the plugin and the core runtime; say

    testproject.csproj
      References:
        plugin1.dll
        runtime.core.dll

We can write a test that refers to plugin1.MyPluginClass . The tests also run, and run fine.

So far, then -- building is fine, running and debugging the app is fine, and tests run fine.
   
The problem comes when we create a performance session from a test. If I create a session from a test, and choose either sampling or instrumentation, I get a session which doesn't list plugin1.dll . It seems that when I build to somewhere different and turn off Copy Local, we don't get the instrumented assembly appearing in the performance session's list of targets. On the other hand, if I build into the standard 'bin\debug ' location AND set Copy Local=true on the runtime.core.dll, all the correct files _are_ included.

I hope this helps people track down problems -- until a fix is found, I suggest;

1) avoid building several projects into one folder -- possibly use post-build events to move copies into the appropriate places, but leave the projects to build into isolated folders. Never mix the streams.
2) Allow projects to Copy Local.