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:
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.
When you instrument your code to measure performance, a good starting point is to add instrumentation at the system boundaries.
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)
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:
Drilling into the Implementation
The following is a basic UML diagram of the classes and interfaces:
This is the ApplicationLogFactory which returns an ApplicationLog:
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.
This is the implementation of ApplicationLog:
This is the LogStrategyBase implementation:
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:
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”
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.