Introducing the Concurrency Visualizer SDK

 

The Concurrency Visualizer displays rich data related to CPU thread behavior, DirectX activity, and disk I/O, among other things.  This information can be incredibly valuable when investigating application behavior, but sometimes it's difficult to quickly understand how the data displayed in the Concurrency Visualizer maps to application behavior.  For this reason, we've added the Concurrency Visualizer SDK, which you can use in Visual Studio 11 Developer Preview.  This SDK allows you to instrument your code in order to augment the visualizations displayed in the Threads View of the Concurrency Visualizer.  These visualizations, referred to as "Markers", make the Threads View data more semantically meaningful because they represent specific phases and events in your application.

For those of you who have used Scenario Markers with the Visual Studio 2010 Concurrency Visualizer, you'll find that the Concurrency Visualizer SDK is conceptually similar, but provides much more control and flexibility.

The SDK exposes three visual primitives:

  1. Span
  2. Flag
  3. Message

A span represents an interval of time in your application, such as an application phase.  A flag represents a single point in time (e.g. the point where some value reached a threshold or when an exception was thrown).  A message also represents a single point in time, but is meant as a visual analog to classic event-style tracing.  So what might have previously been dumped to a log file can now be wrapped in a message call.  This will yield visualizations in the Threads View and you'll have the ability (via the UI) to export the data into a CSV file.  While there are more advanced ways to make use of this SDK, I'll try to introduce the most basic usage scenarios in this entry.

Adding the SDK to your Project

To get started, you need to add the SDK to your project:

image

In the dialog that appears, select the project in which you want to use the SDK and then click “Add SDK to Selected Project”.  For a managed project, this adds a reference to the DLL associated with the SDK.  For native projects, this adds the SDK header file to the project’s include directories.  Next, reference the namespace associated with the SDK in your source code.  In C#, add the following using statement:

using Microsoft.ConcurrencyVisualizer.Instrumentation;

In C++, include the header file:

 #include "cvmarkersobj.h"

This is a header with C++ style conventions.  If you’re using C (or C++, but want to use the C-style conventions anyway) , include this header file instead:

 #include "cvmarkers.h"

This header exposes the same functionality, but follows C-style conventions.

Basic Span Usage

A span is meant to represent an application phase.  Consider the following example code in C#:

         static void Main(string[] args)
         {
             phase1();
             phase2();
         } 

Both phases perform some unknown amount of work.  When I profile this application and view the results in the Threads View, I get the following:

image

I can see that the main thread executed both phases, but I have no idea which is which.  I may be able to deduce this by clicking each green segment and looking at the call stacks in an attempt to determine where one phase ends and the next beings, but this is not guaranteed to work.  Therefore, I can instrument these with spans.  In C# there are two syntactical ways to do this, I’ll demonstrate the first approach on the first phase and the second approach on the second phase:

         static void Main(string[] args)
         {
             using (Markers.EnterSpan("Phase 1"))
             {
                 phase1();
             }
 
             var span = Markers.EnterSpan("Phase 2");
             phase2();
             span.Leave();
         }

Both phases are now demarcated using a span, each using a different syntax.  The choice of syntax is simply a matter of personal preference.  Either way, I now get the following visualization in the Threads View:

image

Note that in C++, I’d make the following call for a span:

 marker_series series;
 //some code
 {
    span s(series, _T("Phase 1"));
    //some code
 }

I can now see that a new channel is visible in the timeline.  This Marker channel displays the two spans I added to my code: Phase 1 and Phase 2.  These mark the points where each phase begun and ended.  It is now crystal clear exactly which stage of execution in the main thread corresponds to each phase.  I can see that the second phase takes roughly twice as long as the first.  In fact, I can select each span to see the exact duration in the report below.  It turns out that phase 1 took 429.8 ms while phase 2 took 724.2 ms.  Note that the thread ID associated with this Marker channel is the ID of the main thread.  You can see this thread ID next to the name of the Marker channel.  This indicates that the Marker events were generated from the main thread (which makes sense when you look at the source code).  If these events had been generated from a different thread, the Marker channel would be associated with a different thread ID and by default, the channel would appear under the thread that generated its events.

Basic Flag Usage

You may want demarcate a specific event in your application that doesn’t have a duration, but rather occurs at a single point in time.  One example of this is the point at which an exception is thrown.  Another example could be a stock market app that wants to call attention to the value of a particular stock reaching a threshold.  To accomplish this, use a flag.  Using the same code from the span example, suppose I want to indicate when phase 1 completes.  I simply need to add a flag after the call to phase1(), but before the call to phase2():

         static void Main(string[] args)
         {
             phase1();
             Markers.WriteFlag("Phase 1 complete");
             phase2();
         }

This results in the following Visualization:

image

To generate a flag in C++, I’d write the following:

 marker_series series;
 series.write_flag(_T("Phase 1 complete"));

The Marker channel now contains an icon, whose bottom tip represents the exact point in time that the call to WriteFlag() was executed.  This demarcates the point when phase1() was complete, but phase2() hadn’t yet begun.

Basic Message Usage

In many applications, you’ll want to output data to a log file because it may come in handy later when diagnosing performance or when debugging.  Most of the time, you won’t look at a log file, and even if you do, you’ll likely look for specific information in it, ignoring 90% of it.  For this type of information, you can use a message.  Suppose I have the following code, which writes files and measures the amount of time required to output each file:

         static void Main(string[] args)
         {
             getFileNames();
             Stopwatch sw = new Stopwatch();
             foreach (String fileName in fileNames)
             {
                 sw.Restart();
                 writeFile(fileName);
                 sw.Stop();
                 long duration = sw.ElapsedMilliseconds;
             }
         }

If I want to log the amount of time required to write each file using a message, I simply add the following code:

         static void Main(string[] args)
         {
             getFileNames();
             Stopwatch sw = new Stopwatch();
             foreach (String fileName in fileNames)
             {
                 sw.Restart();
                 writeFile(fileName);
                 sw.Stop();
                 long duration = sw.ElapsedMilliseconds;
                 Markers.WriteMessage(fileName + ":" + duration);
             }
         }

In the Threads View, I see the following:

image

To generate a message in C++, I’d write the following:

 marker_series series;
 series.write_message(_T("My Message"));

Each little grey rectangle represents a message.  It is visually nonintrusive because after all, log-style output will be ignored most of the time.  If I want to see the output for a message, I can hover over it and see the tooltip.  In addition, I can view the Markers report by selecting “Markers” in the Visible Timeline Profile:

image

This report lists all of the Markers in the current visible time range (thus, zooming/panning filters this report).  In this case, the only Markers were the 10 messages I generated.  For each message, I can see the time at which it occurred and its associated text (in the Details column), among other things.  In this case, I look at the output I generated (in the Details column) and find that all of the files took roughly the same amount of time to write, ranging from 445 ms to 449 ms.  I can export this table as a CSV by clicking the “Export…” button above this tabular report (not visible in this screenshot because I clipped it).

Conclusion

What I discussed in this entry was the most basic way to get started with the Concurrency Visualizer SDK on made up code examples.  There are more sophisticated ways to use this SDK, including using categories and importance levels, and generating Markers from multiple providers and series.  You can even visualize ETW events that follow the event source convention as Markers.  However, I’ll leave this to future entries, in the interest of brevity.

James Rapp - Parallel Computing Platform