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.
