Instrumenting Your Application to Measure its Performance Part 5 Wrapping your code with EventSource

 

In the last article, you learned how to use keywords to filter for specific events in an application. Using filtering is one way to narrow listening for events within a specific layer of a specific context in an application.

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

As you instrument your application, you may soon find that adding event trace statements around blocks of code becomes repetitive and tedious. In this article, I’ll demonstrate a way to reduce the trace statements.

The technique described in this article works well when you want to measure the time a block of code, such as a service call, takes to run. This technique is also good for quickly checking the timing changes due to code refactoring.

 


BizGear WPF Application and WCF Service

In this article, I’ll start using a sample WPF application called BizGear. The client application connects to WCF services. BizGear is a simple WPF application using a tab control to segment three areas: Sales, Merchandise, and Administration. In order to keep the application as simple as possible, the WCF service does not access a database. Data returned from the WCF service(s) is a canned result set.

I’ll assume you have some background in WPF and WCF services.

In that these articles are about code instrumentation, the discussion is focused around specific operations in the demo application and not an overview of the entire application. As I progress through these articles, I’ll discuss the application code as needed for the article’s discussion point.

When BizGear starts it should look similar to this:

image

 

Measuring Execution Time to Get Customers

In the BizGear sample application, GetCustomersCommand.Execute() method runs when a user clicks the Get Customers button. The Execute method calls the SalesService which returns a list of customers.

The method then displays the names of the customer in the list box by adding the customers to the view model’s observable collection.

 

Execute
  1. public void Execute(object parameter)
  2. {
  3.     _viewModel.Customers.Clear();
  4.  
  5.     using (var proxy = new SalesClient())
  6.     {
  7.         var customers = proxy.GetAllCustomers();
  8.  
  9.         foreach (var customer in customers)
  10.         {
  11.             _viewModel.Customers.Add(customer);
  12.         }
  13.     }
  14. }

 

 

When you instrument your code to measure performance, a good starting point is to add instrumentation at the system boundaries.

 

image

 

In our example application, one boundary is the event handler of a user action on the client.

For this example, we want to instrument the client side code that’s executed when a user clicks the Get Customers button. As you see in the example above, the code first clears the collection, which clears the display of the customers in the ListBox control at the top of the form. The code then makes a WCF service call to the SalesService GetAllCustomers() to get a list of customers.

Another useful boundary to instrument is the WCF service running on the server. This boundary is where the client interacts with the server. For this example, the client and server are running on a single machine and there is only one client. By using filtering as discussed in the previous article, it’s straight forward to enable ETW to monitor for events which can tell us how long it takes to execute code in the client boundary, at the service boundary, or both.

In a real world environment, there may be several hundred clients using the WCF services on the server. Enabling instrumentation on the client and instrumentation on the server, and consolidating events can give a holistic view of system activity. In a future article I’ll discuss a way to instrument the service boundary as well as how to consolidate data from the client(s) and server. Here we’ll focus on instrumenting the client side code.

Another point for code instrumentation you should consider measuring is performance changes when refactoring code.

You should capture the time before and after your code refactoring to ensure there is no unexpected performance degradation. If you’re running automated unit tests, you may want to enable ETW tracing around key methods of your application to capture performance metrics during unit test.

In the example code above, you could add a call to SalesContextEventSource at the beginning of the method and a second call at the end of the method. The problem is that adding calls at the beginning and end of a method is tedious and adds more ‘noise’.

An alternative is to use an ‘envelope’ class which wraps calls to SalesContextEventSource and derives from IDisposable, allowing you to wrap the code you want to instrument inside a using statement:  (line 20) 

 

Execute with ETW Trace
  1. public void Execute(object parameter)
  2. {
  3.     using (var appLog = ApplicationLogFactory.Create(Context.Sales,
  4.                                                     Layer.Presentation,
  5.                                                     "SalesViewModel",
  6.                                                     "GetCustomersCommand"))
  7.     {
  8.         _viewModel.Customers.Clear();
  9.  
  10.         using (var proxy = new SalesClient())
  11.         {
  12.             var customers = proxy.GetAllCustomers();
  13.  
  14.             foreach (var customer in customers)
  15.             {
  16.                 _viewModel.Customers.Add(customer);
  17.             }
  18.         }
  19.     }
  20. }


Figure 1

 

The class factory (line 20) returns an ApplicationLog class. The parameters to the class factory provide the context (Sales), the filter (Layer.Presentation), and the class name and method name- SalesViewModel and GetCustomersCommand.

When the class factory creates the ApplicationLog class, the constructor makes a call to the SalesContextEventSource with the data ‘enter’. When the using statement (line 20) goes out of scope, ApplicationLog.Dispose() method is called, which calls a method to emit the data ‘exit’.

The resulting trace output seen in PerfView appears similar to the following:

image

 


Drilling into the Implementation

The following is a basic UML diagram of the classes and interfaces:

image

Figure 2

 

 

This is the ApplicationLogFactory which returns an ApplicationLog:

ApplicationLogFactory
  1. public class ApplicationLogFactory : IApplicationLogFactory
  2. {
  3.     private static readonly Dictionary<Context, ILogStrategy> Strategies = new Dictionary<Context, ILogStrategy>();
  4.  
  5.     static ApplicationLogFactory()
  6.     {
  7.         Strategies.Add(Context.Sales, new SalesLogStrategy());
  8.         Strategies.Add(Context.Business, new BusinessLogStrategy());
  9.         Strategies.Add(Context.MerchandiseReturns, new MerchandiseReturnLogStrategy());
  10.     }
  11.  
  12.     public static ApplicationLog Create(Context context, Layer layer, string className, string methodName)
  13.     {
  14.         return new ApplicationLog(Strategies[context], className, methodName, layer);
  15.     }
  16.  
  17.     ApplicationLog IApplicationLogFactory.Create(Context context, Layer layer, string className, string methodName)
  18.     {
  19.         return Create(context, layer, className, methodName);
  20.     }
  21. }

 

Figure 3

 

The ApplicationLogFactory contains a dictionary of Strategy objects following the Strategy design pattern. Each EventSource context- Sales, Business, and MerchandiseReturn, is contained in a Strategy object.

The ApplicationLogFactory’s dictionary, constructor and Create method are static, which essentially makes the ApplicationLogFactory a Singleton and global in the process.

The dictionary is made static and singleton for a quick lookup. But, to prevent incorrect data from being written in a multithreaded application, the implementation, the object from the dictionary is cloned and the appropriate class name, method name, and layer are copied to the clone.

The method Create() (Shown being called in the Execute method at line 21 in the first code example) gets the appropriate Strategy object from the dictionary, sets the layer, class name and method name, and constructs a new ApplicationLog().

ILogStrategy defines two methods for logging. Clone() constructs a new copy of the contained strategy class. Creating a new copy ensures the correct information is emitted in a multithreaded application.

ILogStrategy
  1. public interface ILogStrategy : IDisposable
  2. {
  3.     ILogStrategy Clone(string className, string methodName, Layer layer);
  4.  
  5.     void Enter();
  6.     void Log(string data);
  7. }

 

Figure 4

 

 

This is the implementation of ApplicationLog:

ApplicationLog
  1. public class ApplicationLog : ILogStrategy
  2. {
  3.     private ILogStrategy _logStrategy;
  4.  
  5.     public ApplicationLog(ILogStrategy logStrategy, string className, string methodName, Layer layer)
  6.     {
  7.         _logStrategy = logStrategy.Clone(className, methodName, layer);
  8.  
  9.         Enter();
  10.     }
  11.  
  12.     public ILogStrategy Clone(string className, string methodName, Layer layer)
  13.     {
  14.         throw new NotImplementedException();
  15.     }
  16.  
  17.     public void Dispose()
  18.     {
  19.         _logStrategy.Dispose();
  20.         _logStrategy = null;
  21.     }
  22.  
  23.     public void Enter()
  24.     {
  25.         _logStrategy.Enter();
  26.     }
  27.  
  28.     public void Log(string data)
  29.     {
  30.         _logStrategy.Log(data);
  31.     }
  32. }

 

Figure 5

 

This is the LogStrategyBase implementation:

LogStrategyBase
  1. public class LogStrategyBase : ILogStrategy
  2. {
  3.     public string ClassName { get; set; }
  4.     public string MethodName { get; set; }
  5.     public Layer Layer { get; set; }
  6.  
  7.     public virtual ILogStrategy Clone(string className, string methodName, Layer layer)
  8.     {
  9.         return null;
  10.     }
  11.  
  12.     public virtual void Dispose()
  13.     {
  14.     }
  15.  
  16.     public virtual void Enter()
  17.     {
  18.     }
  19.  
  20.     public virtual void Log(string data)
  21.     {
  22.     }
  23. }

 

Figure 6

 

LogStrategyBase implements the three properties which hold the class name, the method name and the filtering layer. The Log and Dispose methods are virtual, implemented in the derived class.

The following is the implementation for one of the Strategy classes- SalesLogStrategy:

SalesLogStrategy
  1. public class SalesLogStrategy : LogStrategyBase
  2. {
  3.     public override ILogStrategy Clone(string className, string methodName, Layer layer)
  4.     {
  5.         return new SalesLogStrategy {ClassName = className, MethodName = methodName, Layer = layer};
  6.     }
  7.  
  8.     public override void Dispose()
  9.     {
  10.         Log("exit");
  11.     }
  12.  
  13.     public override void Enter()
  14.     {
  15.         Log("enter");
  16.     }
  17.     
  18.     public override void Log(string data)
  19.     {
  20.         if (!IsEnabled()) return;
  21.  
  22.         switch (Layer)
  23.         {
  24.             case Layer.Presentation:
  25.                 SalesContextEventSource.Log.Presentation(ClassName, MethodName, data);
  26.                 break;
  27.  
  28.             case Layer.Business:
  29.                 SalesContextEventSource.Log.Business(ClassName, MethodName, data);
  30.                 break;
  31.  
  32.             case Layer.Data:
  33.                 SalesContextEventSource.Log.Data(ClassName, MethodName, data);
  34.                 break;
  35.         }
  36.     }
  37.  
  38.     private static bool IsEnabled()
  39.     {
  40.         return SalesContextEventSource.Log.IsEnabled();
  41.     }
  42. }

 

Figure 7

 

In Figure 3, line 24, the ApplicationLogFactory passes an object which implements the ILogStrategy interface to the ApplicationLog constructor.

In Figure 5, line 9, the ApplicationLog constructor calls the base class properties to save the class name, method name, and layer.

The constructor then calls Enter(), line 13. Enter() calls IStrategy.Enter(), line 29, which emits the “enter” message, Figure 7, line 17.

The Log() method, Figure 7, line 24, first checks if logging IsEnabled(). This check is an optimization to reduce calling an EventSource trace if logging isn’t enabled for the provider.

If logging is enabled, the appropriate method of the SalesContextEventSource is called to emit the “entry” message in lines 26 – 38.

When the using statement goes out of scope (Figure 1, line 37), the ILogStrategy.Dispose() is called (Figure 7, line 14) which emits “exit”

 


Conclusion

Using the above technique to wrap the ETW trace generation in a using statement makes it quick and easy to find the time a block of code executes.

As a reader exercise, in Figure 1, you can use the variable appLog created in line 21 to emit additional tracing.

For example, in the foreach loop in lines 32 – 35, you could add the line

applog.Log(customer.Firstname + “ “ + customer.Lastname);

to emit tracing of the customer names.

In the next article, I’ll show you how to use the Unity IOC container to inject trace statements so that you need not add any EventSource tracing inside a method.

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

2 Responses to Instrumenting Your Application to Measure its Performance Part 5 Wrapping your code with EventSource

  1. Pingback: Dew Drop – July 10, 2013 (#1,582) | Alvin Ashcraft's Morning Dew

  2. Pingback: Windows Store Developer Links – 2013-07-12 | Dan Rigby

Leave a Reply

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


*

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>