Using MS Standalone profiler in VS2008 Professional

Question

I am trying to profile my .NET dll while running it from VS unit testing tools but I am having problems. I am using the standalone command-line profiler as VS2008 Professional does not come with an inbuilt profiler.

I have an open CMD window and have run the following commands (I instrumented it earlier which is why vsinstr gave the warning that it did):

C:\...\BusinessRules\obj\Debug>vsperfclrenv /samplegclife /tracegclife /globalsamplegclife /globaltracegclife
Enabling VSPerf Sampling Attach Profiling. Allows to 'attaching' to managed applications.

Current Profiling Environment variables are:
COR_ENABLE_PROFILING=1
COR_PROFILER={0a56a683-003a-41a1-a0ac-0f94c4913c48}
COR_LINE_PROFILING=1
COR_GC_PROFILING=2

C:\...\BusinessRules\obj\Debug>vsinstr BusinessRules.dll
Microsoft (R) VSInstr Post-Link Instrumentation 9.0.30729 x86
Copyright (C) Microsoft Corp. All rights reserved.

Error VSP1018 : VSInstr does not support processing binaries that are already instrumented.

C:\...\BusinessRules\obj\Debug>vsperfcmd /start:trace /output:foo.vsp
Microsoft (R) VSPerf Command Version 9.0.30729 x86
Copyright (C) Microsoft Corp. All rights reserved.

C:\...\BusinessRules\obj\Debug>

I then ran the unit tests that exercised the instrumented code. When the unit tests were complete, I did...

C:\...\BusinessRules\obj\Debug>vsperfcmd /shutdown
Microsoft (R) VSPerf Command Version 9.0.30729 x86
Copyright (C) Microsoft Corp. All rights reserved.


Waiting for process 4836 ( C:\Program Files\Microsoft Visual Studio 9.0\Common7\IDE\vstesthost.exe) to shutdown...

It was clearly waiting for VS2008 to close so I closed it...

Shutting down the Profile Monitor
------------------------------------------------------------

C:\...\BusinessRules\obj\Debug>

All looking good, there was a 3.2mb foo.vsp file in the directory. I next did...

C:\...\BusinessRules\obj\Debug>vsperfreport foo.vsp /summary:all

Microsoft (R) VSPerf Report Generator, Version 9.0.0.0
Copyright (C) Microsoft Corporation. All rights reserved.

VSP2340: Environment variables were not properly set during profiling run and managed symbols may not resolve.  Please use vsperfclrenv before profiling.
File opened
Successfully opened the file.
A report file, foo_Header.csv, has been generated.
A report file, foo_MarksSummary.csv, has been generated.
A report file, foo_ProcessSummary.csv, has been generated.
A report file, foo_ThreadSummary.csv, has been generated.
Analysis completed
A report file, foo_FunctionSummary.csv, has been generated.
A report file, foo_CallerCalleeSummary.csv, has been generated.
A report file, foo_CallTreeSummary.csv, has been generated.
A report file, foo_ModuleSummary.csv, has been generated.

C:\...\BusinessRules\obj\Debug>

Notice the warning about environment variables and using vsperfclrenv? But I had run it! Maybe I used the wrong switches? I don't know. Anyway, loading the csv files into Excel or using the perfconsole tool gives loads of useful info with useless symbol names:

*** Loading commands from: C:\temp\PerfConsole\bin\commands\timebytype.dll
***   Adding command: timebytype
*** Loading commands from: C:\temp\PerfConsole\bin\commands\partition.dll
***   Adding command: partition

Welcome to PerfConsole 1.0 (for bugs please email: [email protected]), for help type: ?, for a quickstart type: ??

> load foo.vsp
*** Couldn't match to either expected sampled or instrumented profile schema, defaulting to sampled
*** Couldn't match to either expected sampled or instrumented profile schema, defaulting to sampled
*** Profile loaded from 'foo.vsp' into @foo

> 
> functions @foo
>>>>> Function Name

Exclusive            Inclusive            Function Name  Module Name
-------------------- -------------------- -------------- ---------------
900,798,600,000.00 % 900,798,600,000.00 % 0x0600003F     20397910
14,968,500,000.00 %  44,691,540,000.00 %  0x06000040     14736385
8,101,253,000.00 %   14,836,330,000.00 %  0x06000041     5491345
3,216,315,000.00 %   6,876,929,000.00 %   0x06000042     3924533
<snip>
71,449,430.00 %      71,449,430.00 %      0x0A000074     42572
52,914,200.00 %      52,914,200.00 %      0x0A000073     0
14,791.00 %          13,006,010.00 %      0x0A00007B     0
199,177.00 %         6,082,932.00 %       0x2B000001     5350072
2,420,116.00 %       2,420,116.00 %       0x0A00008A     0
836.00 %             451,888.00 %         0x0A000045     0
9,616.00 %           399,436.00 %         0x0A000039     0
18,202.00 %          298,223.00 %         0x06000046     1479900

I am so close to being able to find the bottlenecks, if only it will give me the function and module names instead of hex numbers!

What am I doing wrong?

--- Alistair.

Answer 1

A couple possible things to try (note I'm not an expert in the command line profiler - I've only used it a couple times a while back):

1. The docs for vsperfclrenv says:

   The option that you choose depends on which of the three types of profiling you use: sampling, instrumentation, or global.

   You've got options for all 3 types of profiling in your call to vsperfclrenv - I suggest that you choose one type to start off with, and move on from there if that works but you want to try other things to see if they work better.

2. You might need to specify a location for symbols as well (even if this isn't done using vsperfclrenv). Symbol location can be configured using the _NT_SYMBOLS_PATH environment variable or the /SymbolPath option to vsperfreport (or by having the .pdb files in the same location as the binaries). See "How to: Specify Symbol File Locations from the Command Line" for details.

Answer 2

The reason turns out to be that I was not running the executable in the same process that the environment variables were defined in. It is the instrumented code that needs access to the environment variables, not the profiler.

So I ran VS2008 directly from the command-line after using vsperfclrenv and it all worked and I have my function names.

Sadly I still get the Schema errors meaning I can't drill down through the call tree but I have at least managed to identify this particular bottleneck.

--- Alistair.