Limiting the Data Crunch from Trace Profiling

Typically, one can use the sampling profiler to nail down the hot spot in an application. Having done that, what does one do when the sampling data doesn't provide enough information? The trace profiler can offer up more detail, particularly if the issue revolves around thread interaction. However, if you profile a heavily CPU bound application, you may find that you are getting huge trace files, or that the profiler is significantly impacting the performance of your application. The VisualStudio profiler offers a mechanism to stem the avalanche of data.

I'll illustrate the general idea with an example.

Suppose we'd like to run trace profiling on the following highly useful piece of code. We've decided that we only care about profiling in the context of the function "OnlyProfileThis()"

using System;

public class A
{
private int _x;

public A(int x)
{
_x = x;
}

public int DoNotProfileThis()
{
return _x * _x;
}

public int OnlyProfileThis()
{
return _x + _x;
}

public static void Main()
{
A a;
a = new A(2);

Console.WriteLine("2 square is {0}", a.DoNotProfileThis());
Console.WriteLine("2 doubled is {0}", a.OnlyProfileThis());
}
}

The VisualStudio profiler provides an API for controlling data collection from within the application. For native code, this API lives in VSPerf.dll. A header (VSPerf.h) and import library (VSPerf.lib) provided in the default Team Developer install allows us to use the profiler control API from native code. For managed code, this API is wrapped by the DataCollection class in Microsoft.VisualStudio.Profiler.dll. We can update the example to the following to control the profiler during our run:

using System;
using Microsoft.VisualStudio.Profiler;

public class A
{
private int _x;

public A(int x)
{
_x = x;
}

public int DoNotProfileThis()
{
return _x * _x;
}

public int OnlyProfileThis()
{
return _x + _x;
}

public static void Main()
{
A a;
a = new A(2);

  int x;
Console.WriteLine("2 square is {0}", a.DoNotProfileThis());

  DataCollection.StartProfile(
DataCollection.ProfileLevel.DC_LEVEL_GLOBAL,
DataCollection.PROFILE_CURRENTID);

  x = a.OnlyProfileThis();

  DataCollection.StopProfile(
DataCollection.ProfileLevel.DC_LEVEL_GLOBAL,
DataCollection.PROFILE_CURRENTID);

  Console.WriteLine("2 doubled is {0}", x);

 }
}

We still need to instrument the application as normal. We also have one additional step. When running the code above, data collection will be enabled by default, so the API won't appear to do anything beyond stopping data collection after the call to OnlyProfileThis. We need to disable data collection before running the application. The profiler control tool,
VSPerfCmd, has options to do this.

To run this scenario from the command line:

csc /debug- /r:Microsoft.VisualStudio.Profiler.dll Sample.cs
VSInstr Sample.exe

VSPerfCmd /start:trace /output:SampleTrace.VSP
VSPerfCmd /globaloff
Sample.exe
VSPerfCmd /shutdown

VSPerfReport /calltrace SampleTrace.VSP

There are several control functions in the DataCollection class. Here is a brief rundown.

StartProfile(ProfileLevel level, UInt32 id)
StopProfile(ProfileLevel level, UInt32 id)

This unconditionally starts or stops profiling. The level parameter indicates whether profiling should be stopped for the current thread, process, or globally. For thread and process level changes, the id specifies thread id or process id to control (respectively), or PROFILE_CURRENTID to control the current thread or process.

SuspendProfile(ProfileLevel level, UInt32 id)
ResumeProfile(ProfileLevel level, UInt32 id)

This works very much like StartProfile and StopProfile, however, calls to these functions are reference counted. If you call SuspendProfile twice, you must call ResumeProfile twice to enable profiling.

MarkProfile(Int32 markId)
CommentMarkProfile(Int32 markId, String comment)
CommentMarkAtProfile(Int64 timeStamp, Int32 markId, String comment)

Inserts a 32-bit data value into the collection stream. Optionally, you can include a comment. With the last function, the mark can be inserted at a specific time stamp. The id value and the optional comment will appear in the CallTrace report.

The profiler control tool provides similar functionality through a command line interface, though the notion of a "current" process or thread id is obviously not relevant.

VSPerfCmd /?

[...]

-GLOBALON Sets the global Start/Stop count to one (starts profiling).

-GLOBALOFF Sets the global Start/Stop count to zero (stops profiling).

-PROCESSON:pid Sets the Start/Stop count to one for the given process.

-PROCESSOFF:pid Sets the Start/Stop count to zero for the given process.

-THREADON:tid Sets the Start/Stop count to one for the given thread.
Valid only in TRACE mode.

-THREADOFF:tid Sets the Start/Stop count to zero for the given thread.
Valid only in TRACE mode.

-MARK:marknum[,marktext]
Inserts a mark into the global event stream, with
optional text.

[...]

If you find yourself buried under a ton of trace data, investigate the profiling API to help focus on the important parts of your application.