Instrumenting Your Application to Measure its Performance Part 3 An introduction to EventSource, Logman, and PerfView

 

This article discusses starting points for application instrumentation.

You can find the source code to this article in my GitHub repository  BizGear

EventSource is a class introduced in NET 4.5. Although installed as part of NET 4.5, you can use EventSource in your NET 4.0 applications. If your environment has yet to migrate to NET 4.5, you can reference the EventSource.DLL in your Visual Studio project.

Logman is a utility included as part of Windows. We’ll use Logman as a controller to enable and disable event capture from your application. Logman is well documented in MSDN, Technet, and blogs. In this article, I’ll provide just enough information to get you started. I encourage you to use the following sites as starting points to learn more about using Logman.

Two Minute Drill:  LOGMAN.EXE

Logman

You can get PerfView from the Microsoft Download Center. Like Logman, PerfView is well documented on MSDN, other’s blogs, and its own online help system. For this series of articles, I’ll assume you have downloaded PerfView and can run it successfully on your machine. Like Logman, I’ll discuss just enough information needed for this article and encourage you to reference the following sites to learn more about using PerfView.

Channel 9 videos  PerfView Tutorials

Vance Morrison’s Blog

Consider you want to start instrumenting a sales order application called BizGear. BizGear manages the sales of products related to running a business. Like many enterprise applications, BizGear is a multilayered application (Presentation, Business, Data), and contains several areas of responsibility (contexts) such as Product Returns, Administration, Billing, Inventory, and Sales.

We want to start instrumenting the Sales portion of BizGear.

For simplicity of demonstration, I’ll use a console application to demonstrate writing events. In a real world application, the code demonstrated in the console application would be used in the application’s modules.

 


Implementing EventSource classes

Start by creating a solution containing a console application project called SimpleDemoConsole and a class library project called EventSources.

Add two files to your EventSources project: EventSourcesNames.cs and SalesContextEventSource.cs.

Your solution file should appear similar to this:

clip_image001

EventSourceNames contains the user friendly names of the event sources you will be adding through this series.

Recall there are many ETW providers in the Windows OS as well as other applications using EventSource to generate events. Each event source needs to be uniquely named so that a controller doesn’t accidently turn on or off events from multiple events sources. To see a list of OS registered event sources, in a command prompt window, enter logman query provider.

By convention and to make your event source unique from other event sources in the operating system and applications, you should use the naming convention <company name> – <application name> – <area of instrumentation>.

As a starting point, we’ll call our company “ACME”. Our sales application is BizGear, and we want to instrument the part of the sales application responsible for processing sales—the sales context.

Given the above, the following is our first version of EventSourceNames

EventSourceNames
  1. namespace EventSources
  2. {
  3.     public static class EventSourceNames
  4.     {
  5.         //guid for this provider:  {d5b29467-62f5-54a9-4861-96cf631b95b4}
  6.         public const string SalesContext = "Acme-BizGear-SalesContext";
  7.  
  8.         //guid for this provider:  {9a9cf874-7496-5df5-6e80-1c5804eccd57}
  9.         public const string BusinessContext = "Acme-BizGear-InventoryContext";
  10.  
  11.         //guid for this provider:  {3e4539f0-447d-5791-0b48-ee4106c9ced8}
  12.         public const string MerchandiseReturnContext = "Acme-BizGear-MerchandiseReturnsContext";
  13.     }
  14. }

 

Next we want to implement the first version of the class which will generate events. We’ll call this class SalesContextEventSource.

SalesContextEventSource
  1. namespace EventSources.EventSources
  2. {
  3.     using System.Diagnostics.Tracing;
  4.  
  5.     //guid for this provider:  {d5b29467-62f5-54a9-4861-96cf631b95b4}
  6.     [EventSource(Name = EventSourceNames.SalesContext)]
  7.     public class SalesContextEventSource : EventSource
  8.     {
  9.         public static readonly SalesContextEventSource Log = new SalesContextEventSource();
  10.  
  11.         [Event(1, Level = EventLevel.Informational, Keywords = Keywords.Presentation)]
  12.         public void Presentation(string className, string methodName, string data){ if (IsEnabled()) WriteEvent(1, className, methodName, data); }
  13.  
  14.         [Event(2, Level = EventLevel.Informational, Keywords = Keywords.Business)]
  15.         public void Business(string className, string methodName, string data) { if (IsEnabled()) WriteEvent(2, className, methodName, data); }
  16.  
  17.         [Event(3, Level = EventLevel.Informational, Keywords = Keywords.DataAccess)]
  18.         public void Data(string className, string methodName, string data) { if (IsEnabled()) WriteEvent(3, className, methodName, data); }
  19.  
  20.         [Event(4, Level = EventLevel.Informational, Keywords = Keywords.Service)]
  21.         public void Service(string className, string methodName, string data) { if (IsEnabled()) WriteEvent(4, className, methodName, data); }
  22.         
  23.         public class Keywords
  24.         {
  25.             public const EventKeywords Presentation = (EventKeywords)0x0001;
  26.             public const EventKeywords Business = (EventKeywords)0x0002;
  27.             public const EventKeywords DataAccess = (EventKeywords)0x0004;
  28.             public const EventKeywords Service = (EventKeywords)0x0008;
  29.         }
  30.     }
  31. }

On line 6, we attribute the class with the friendly name. There is a standard, RFC4122, for converting the friendly name to a GUID. Some tools may accept the friendly name given to your derived EventSource class and convert the friendly name internally to a GUID before interfacing to the ETW subsystem. Other tools use the GUID to specify the event provider’s identity to the ETW subsystem. So as a quick reference, the GUID of Acme-BizGear-SalesContext is added in the comment on line 5. I’ll show you later in the console application how to quickly find the GUID for SalesContextEventSource.

Line 11 contains metadata for the Presentation method. Usually when implementing a method used for adding instrumentation for an application, I specify the Level = Informational.

One line 12, notice IsEnabled().  IsEnabled() returns true only when the ETW subsystem has a session established for this event provider via a controller. Because WriteEvent() is not performed unless a controller enables the ETW subsystem to receive events from this provider, this is one of the reasons EventSource has a very low performance overhead when used to instrument your application. If you were to examine the IL generated by this code you would find that very few instructions are actually executed when no events are being sent to the ETW subsystem.

So, even though you may have many points in your application containing event logging, the overhead is very, very, minor. And when a controller enables event captures, the overhead to your application remains low because most of the work is generating the event message (partly defined in the meta data in line 11 and partly via the parameters in line 12) to ETW, and ETW handles, in another process, the buffering and multithreading to write the event to a log file.

Note: Something important I want to point out on lines 11 and 12 is the event numbers in the metadata and in the WriteEvent must be the same.

[Event(1, ……
…..WriteEvent(1, ….

If you make a mistake of not setting the value in the metadata to match with the value in WriteEvent, event generation will silently fail. Reading MSDN blogs, tooling such as FxCop may be made available in the future to warn the user of a mismatch. For now the best advice I can offer is be careful in ensuring the event number in your Event() metadata matches the event number in WriteEvent()!

The Keywords metadata we’ll ignore for now. I’ll cover more about using Keywords in a future article.

 


Implementing Console Application

Now we implement a console application.     I find the console application useful to quickly verify the operation of generating ETW events as you make changes to your classes derived from EventSource.

Simple Demo Console
  1. namespace SimpleDemoConsole
  2. {
  3.     #region usings
  4.  
  5.     using System;
  6.     using System.Diagnostics.Tracing;
  7.     using EventSources.EventSources;
  8.     using System.Threading;
  9.  
  10.     #endregion
  11.  
  12.     class Program
  13.     {
  14.         static void Main()
  15.         {
  16.             DisplayGuids();
  17.  
  18.             DisplayEnabled();
  19.  
  20.             DisplayEventLevels();
  21.  
  22.             for (var ctr = 0; ctr < 5000; ctr++ )
  23.             {
  24.                 if ((ctr % 100) == 0)
  25.                     Console.WriteLine(ctr);
  26.  
  27.                 Thread.Sleep(1);
  28.                 TestSalesLogging();
  29.  
  30.                 TestBusinessLogging();
  31.  
  32.                 TestMerchandiseLogging();
  33.             }
  34.  
  35.             Console.WriteLine("Finished");
  36.             Console.ReadLine();
  37.         }
  38.  
  39.         private static void DisplayGuids()
  40.         {
  41.             var salesGuid             = SalesContextEventSource.Log.Guid.ToString();
  42.             var businessGuid          = BusinessContextEventSource.Log.Guid.ToString();
  43.             var merchandiseReturnGuid = MerchandiseReturnContextEventSource.Log.Guid.ToString();
  44.  
  45.             Console.WriteLine("Sales Guid\t\t{0}", salesGuid);
  46.             Console.WriteLine("Business Guid\t\t{0}", merchandiseReturnGuid);
  47.             Console.WriteLine("Merchandise Return Guid\t{0}", merchandiseReturnGuid);
  48.         }
  49.  
  50.           private staticvoid DisplayEnabled()
  51.         {
  52.             var isSalesEnabled       = SalesContextEventSource.Log.IsEnabled();
  53.             var isBusinessEnabled    = BusinessContextEventSource.Log.IsEnabled();
  54.             var isMerchandiseEnabled = MerchandiseReturnContextEventSource.Log.IsEnabled();
  55.  
  56.             Console.WriteLine("Sales enabled \t\t{0} ", isSalesEnabled);
  57.             Console.WriteLine("Business enabled \t{0} ",  isBusinessEnabled);
  58.             Console.WriteLine("Merchandise enabled \t{0}", isMerchandiseEnabled);
  59.         }
  60.  
  61.         private static void DisplayEventLevels()
  62.         {
  63.             var always        = Convert.ToInt32(EventLevel.LogAlways);
  64.             var critical      = Convert.ToInt32(EventLevel.Critical);
  65.             var error         = Convert.ToInt32(EventLevel.Error);
  66.             var warning       = Convert.ToInt32(EventLevel.Warning);
  67.             var informational = Convert.ToInt32(EventLevel.Informational);
  68.             var verbose       = Convert.ToInt32(EventLevel.Verbose);
  69.  
  70.             Console.WriteLine("always\t\t\t{0}", always);
  71.             Console.WriteLine("critical\t\t{0}", critical);
  72.             Console.WriteLine("error\t\t\t{0}", error);
  73.             Console.WriteLine("warning\t\t\t{0}", warning);
  74.             Console.WriteLine("informationional\t{0}", informational);
  75.             Console.WriteLine("verbose\t\t\t{0}", verbose);
  76.         }
  77.  
  78.         private static void TestSalesLogging()
  79.         {
  80.             var tstMsg1 = "111111111_123456789_123456789_123456789_123456789_123456789_123456789_123456789_123456789_123456789_";
  81.             var tstMsg2 = "123456789_123456789_123456789_123456789_123456789_123456789_123456789_123456789_123456789_123456789_";
  82.             var tstMsg3 = "123456789_123456789_123456789_123456789_123456789_123456789_123456789_123456789_123456789_123456789_";
  83.             var tstMsg4 = "123456789_123456789_123456789_123456789_123456789_123456789_123456789_123456789_123456789_123456789_";
  84.             var tstMsg5 = "123456789_123456789_123456789_123456789_123456789_123456789_123456789_123456789_123456789_123456789_";
  85.             var tstMsg6 = "123456789_123456789_123456789_123456789_123456789_123456789_123456789_123456789_123456789_123456789_";
  86.             var tstMsg = tstMsg1 + tstMsg2 + tstMsg3 + tstMsg5;
  87.  
  88.             SalesContextEventSource.Log.Presentation("Sales_Presentation_className", "Sales_presentation_MethodName", tstMsg);
  89.             SalesContextEventSource.Log.Presentation("Sales_Presentation_className", "Sales_presentation_MethodName", "Sales presentation data");
  90.             SalesContextEventSource.Log.Business("Sales_Business_ClassName", "Sales_business_MethodName", "sales business Data");
  91.             SalesContextEventSource.Log.Data("Sales_Data_ClassName", "Sales_data access_MethodName", "sales data access data");
  92.         }
  93.  
  94.         private static void TestBusinessLogging()
  95.         {
  96.             BusinessContextEventSource.Log.Presentation("Business_Presentation_className", "Business_presentation_MethodName", "Business presentation data");
  97.             BusinessContextEventSource.Log.Business("Business_Business_ClassName", "Business_business_MethodName", "Business business Data");
  98.             BusinessContextEventSource.Log.Data("Business_Data_ClassName", "Business_data access_MethodName", "Business data access data");
  99.         }
  100.  
  101.         private static void TestMerchandiseLogging()
  102.         {
  103.             MerchandiseReturnContextEventSource.Log.Presentation("MerchandiseReturn_Presentation_className", "MerchandiseReturn_presentation_MethodName", "MerchandiseReturn presentation data");
  104.             MerchandiseReturnContextEventSource.Log.Business("MerchandiseReturn_MerchandiseReturn_ClassName", "MerchandiseReturn_MerchandiseReturn_MethodName", "MerchandiseReturn business Data");
  105.             MerchandiseReturnContextEventSource.Log.Data("MerchandiseReturn_Data_ClassName", "MerchandiseReturn_data access_MethodName", "MerchandiseReturn data access data");
  106.         }
  107.     }
  108. }

 

Line 41 shows an easy way to find the value of the GUID of your event source’s friendly name. Put a breakpoint on line 41, then copy and paste the value read in the debugger into the comment on line 5 of the SalesContextEventSource.

Lines 78 – 91 is an example of how you would generate events from your application.

 


Using Logman

Now that you have everything needed to generate an event to ETW, the next step is using Logman as a controller to enable event capture.

Recall from above, a good starting point for using Logman is the following link:

Two Minute Drill:  LOGMAN.EXE

First, start a command prompt window running with Administrator privileges. I do this by going to the Start Menu, select Microsoft Visual Studio 2012, select sub menu Visual Studio Tools, sub menu Developer Command Prompt.   Right click and select Run as administrator in the popup context menu.

clip_image008

Your command prompt windows should show Administrator in its title. The next thing I do is create a working directory. I called mine ETWTraces.

clip_image010

Because specifying the parameters to Logman quickly becomes tedious, I create a .cmd file.

What you want to do is create a data collector which you can start and stop.

Enter the following, as one line, into a file called create.cmd

LOGMAN create trace SalesContext -o C:\ETWTraces\SalesContext.etl
-p “{d5b29467-62f5-54a9-4861-96cf631b95b4}” -f bincirc -max 1000

When you execute the .cmd file, the above command will create a data collector called SalesContext. You’ll use Logman to enable the ETW subsystem to start listening for the events from the provider SalesContextEventSource.

This is an example, of using Logman, where you need to use the GUID to specify the name of your event provider Acme-BizGear-SalesContext.

Events sent from your event provider to the ETW subsystem are saved in the Event Trace Log (ETL) file SalesContext.etl . The other Logman parameters specify the file’s maximum size and the capture is to a circular file. This feature is very useful when you want to collect events for a long period of time capturing some activity in your application, without concern the file will grow overly large, or specifying a fixed size file and risk losing important data.

Note: I found that you cannot use the circular buffer option in Logman and then view the data in PerfView.   You need to use PerfView to capture the data and configure PerfView to create a circular buffer.    I found that Logman overwrites meta data in the ETL file which PerfView needs.   If you want to let data collection take place for a long time period by using a circular buffer, use PerfView to capture the events instead of Logman.    I plan to write a more detailed blog about this in the future.

Now run create.cmd in the command prompt window.

Next enter

logman /query

Your command prompt window should appear like this

clip_image012

To start listening for events on the SalesContext data collector, enter

Logman /start SalesContext

Next run the console application SimpleDemoConsole to generate an event.

Next enter the following on the command prompt to stop listening for events from Acme-BizGear-SalesContext

Logman /stop SalesContext

When you stop data collection, the controller – Logman-  notifies the ETW subsystem to close the session it started and to flush any events it has in its internal buffers to the ETL file.

A nice feature to notice is every time you start and stop the data collector, the ETW subsystem will write a new file with a different version number.

For example, I started and stopped the SalesContext data collector twice, running the console application to generate events between each stop / start. ETW created the following two ETL files:

clip_image013

 


Using PerfView

So far you learned how to create an event provider to generate events. You learned how to use Logman as a controller to interface to ETW to start and stop event captures. Now that you have ETL files containing captured events, the next step is viewing the data.

After downloading PerfView, configure your environment path so PerfView will run from any directory in the command prompt window.

Enter PerfView on the command prompt to start PerfView. When PerfView starts, it will initialize its navigation window to display the ETL files it finds in the directory:

clip_image015

All you need to do is select the ETL file containing the event data you want to view, and click the Events node:

clip_image016

Doing so displays a dialog like this:

 clip_image018

In this window, you’ll see “Acme-BizGear-SalesContext/Presentation” as one of the nodes in the left pane:

clip_image019

PerView has parsed the ETL data and recognized the friendly name of the event provider: “Acme-BizGear-SalesContext”

PerfView, using the metadata Keywords, parsed the event to belong to the keyword “Presentation” in the SalesContextEventSource class.

Finally, in the right side of the dialog, PerfView shows the event name, timestamp (to micro second resolution), the process and thread identity, and the data passed to the parameters in

SalesContextEventSource.Presentation(string className, string methodName, string data);

clip_image021

With what you learned here, you have the start of being able to instrument your application to acquire performance data. In the next articles, I’ll build upon this starting point.

This entry was posted in ETW and tagged , . Bookmark the permalink.

Leave a Reply

Your email address will not be published. Required fields are marked *


*