Introducing the Concurrency Visualizer SDK

發行項
10/17/2011

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:

Span
Flag
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:

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:

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:

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:

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:

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:

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

Comments

Anonymous
December 01, 2011
The comment has been removed
Anonymous
December 01, 2011
BTW: Some comments on the C++ classes: a) cvmarkersobj.h misses the marker_series destructor and it's cleanup job, causing memory losses. b) is it correct that write_message() and write_flag() both get CvDefaultFlagCategory? What purpose has CvDefaultCategory then? c) in my eyes, the destructor(s) should be made virtual, to enable inheritance d) another marker_series constructor, taking an MarkerUUID parameter to create an own MarkerWriter, would have been nice ;)
Anonymous
December 05, 2011
@Christian For you first comment I hope that blogs.msdn.com/.../how-can-visual-studio-11-developer-preview-visualize-the-behavior-of-a-multithreaded-application.aspx helps. Also the first picture in this post shows the menu item for the Concurrency Visualizer.
Anonymous
December 05, 2011
OK, I found it (duh!), but I always get

Microsoft Visual Studio

The report cannot be displayed. The trace file may be corrupt. Try recollecting the trace.

OK

when VS is trying to read an event log created in such an CV Analyzing session. Christian

Anonymous
December 05, 2011
@Christian Does that happen, even if you trace for only a few seconds? The trace generated two .etl files. Can you open both of them with xperfview with no warnings?
Anonymous
December 06, 2011
@Christian As for your first comment, you can access the Concurrency Visualizer under the Analyze menu -> Concurrency Visualizer (if you are using VS 11 Developer Preview). The Concurrency Visualizer is, however, not in the Express version of Visual Studio 11 Developer Preview. As for your second comment, thanks for your detailed feedback. You made a number of good points so we're currently taking another look at our implementation of cvmarkersobj.h. I can't make any promises at this point, but you're likely to find these fixes in the beta release of Visual Studio 11.
Anonymous
December 06, 2011
@Christian When you see the error, are you collecting the trace on a VM?
Anonymous
December 07, 2011
@James and @Jared Well after noticing that I used Win7 64 bit without SP1, I installed VS11 on a new VM machine with Win7 32 bit and SP1, and now it works. Thank you for your assistance.
Anonymous
December 07, 2011
Sorry, another question: How can I define an own name of the thread in the "Name" column of the threads? There's a way to set a thread's name that Visual Studio works with (using exception 0x406D1388), but that is not displayed, it only says "Worker Thread". Would it be possible to use the thread name passed by the exception?
Anonymous
December 07, 2011
No, its not possible to show the name of the thread. The reason is because the Concurrency Visualizer gets all of it's information from etw events, and no etw event is generated when a thread is named. A great place to ask future questions, or make future comments, would be the Visual Studio Performance Tools Forum social.msdn.microsoft.com/Forums/en-US/vstsprofiler/threads
Anonymous
December 07, 2011
Well then there should be an event for that purpose ;) Would make life easier. In the last two weeks, we improved a run in our module by 4-5 times (!!!) using the 'old' performance sessions of VS2008, and the multithreading scalability for multiple runs in threads by about the number of CPU cores by using VS2010 Concurrency Visualizer... And more to follow due to an improved overview using CvSpans now in VS11... Great work, that CV!
Anonymous
December 07, 2011
@Christian I'm glad to hear you were able to improve your perf using the Concurrency Visualizer! Regarding thread names, we've gotten this request multiple times. We haven't yet worked to get an ETW event for this, but the fact that you're asking for it certainly boosts the priority of us adding this feature. As for the issue you were seeing, I can't quite say what was causing it but I can say that Concurrency Visualizer isn't officially supported on VMs, since we haven't tested it in that environment. It's quite possible that you'll see errors when trying to use the Concurrency Visualizer on VM. Best of luck speeding up your code! If you have any other questions about the Concurrency Visualizer, feel free to post them in one of the following three forums:

Parallel Computing in C++ and Native Code (social.msdn.microsoft.com/.../threads)
Parallel Extensions to the .NET Framework (social.msdn.microsoft.com/.../threads)
Visual Studio Performance Tools Profiler (social.msdn.microsoft.com/.../threads)

共用方式為