The last article demonstrated how to use Unity Interception to inject code to emit ETW traces before and after calling a method. Using this technique is a good way to separate tracing / logging concerns from a class method and avoids interlacing your main code with trace statements.
You can find the source code to this article in my GitHub repository BizGear
In this article, following the philosophy of Aspect Oriented Programming, I’ll show you how to write custom WCF behaviors to inject ETW traces into WCF service calls. Similar to doing AOP using Unity Injection, using custom WCF behaviors separates the ETW tracing from your main code and avoids interlacing your code with trace statements.
There are additional benefits too besides separation of concerns.
The first benefit is in a SOA architecture it is a good practice to generate ETW trace statements at system boundaries.
On the client, the client boundary is the event handler for some UI action. At the server, the boundary is at the WCF service call. It is here where the WCF subsystem calls into your service’s method and returns data to the client.
Of course, besides tracing at the boundaries, you may want additional tracing to measure the performance of business logic or CRUD operations on the database if the timings at the system boundaries suggest deeper investigation.
In a large system, it’s easy to start having so many trace statements generated that filtering and interpreting the data becomes difficult. By starting at system boundaries, you have fewer needles and a smaller haystack to search.
A second benefit of using WCF custom behaviors is using WCF behaviors gives you access to information you can find very useful in measuring performance. Besides the timings to perform a WCF call, you can easily get how much data is sent between the client and server, take a snapshot of memory (to watch if memory usage is ever increasing in your service host process), and obtain the identity of the caller accessing the WCF service call.
The WCF Service Stack
WCF has multiple extension points where you can insert custom code which allows you to modify runtime behavior. The three extension points I use the following custom behaviors: Service, Operation, Parameter Inspector, and Message Inspector behaviors. These behaviors can be added programmatically or by adding attributes to the WCF service contract.
The service behavior, not shown in Figure 1, is used to apply Operation behaviors.
You use the operation behavior, which is associated with the WCF service call (the operation contract in WCF), to add a Parameter Inspector behavior.
The Parameter Inspector behavior is called before and after the WCF method executes. In the Parameter Inspector, you can obtain the identity of the user placing the call, access the parameters passed to the WCF method, and trace the WCF method’s execution time.
In the Message Inspector, you can get the size of the data messages transferred between the client and WCF service.
When you combine the traces done in the Parameter and Message Inspectors, you can quickly see:
- Which clients are making calls to the service
- How much time a method call takes
- Memory utilization
- How much data is exchanged between the client and server
As you collect this data over time, you can build a profile of your application via the WCF service calls. Profiling the ‘application meta data’ you can answer questions such as:
- Who are the most frequent users of the server
- Which service methods are most frequently used
- Which service methods take the most time to complete
- How much data is sent by methods, by user
- What are heaviest and lightest server loads:
- The number of concurrent users,
- Times of week or day of peak use.
To understand what your application is doing, how it’s being used, and its affects on the hosting operating system – CPU utilization, memory usage, garbage collection— with ETW tracing you have the ability to combine your application’s ‘meta data’ with other information to get a holistic picture. You don’t need to capture / read the messages exchanged between the client and server. (A tip of the hat to Edward Snowden pointing out the importance of meta data collection.)
With the profile data, you have good starting points to identify server side hot spots and determine where to drill deeper for more granular performance data.
For code reuse and flexibility in allowing behaviors to be applied programmatically or by attributes, I created a class for each of the behaviors, which derive from Attribute.
Given the above overview, let’s start examining some code.
As stated earlier, there are different ways to apply behaviors to the WCF runtime. One approach is to programmatically add the behaviors when creating the service host. Another way is to decorate your service class with an attribute. I’ll show the way of applying a behavior via an attribute first.
The Sales Service interface
The attribute on line 16 of Figure 3 attaches the EtwLoggingServiceBehavior to SalesService.
At runtime, the WCF subsystem will construct the EtwLoggingServiceBehavior, passing Context.Sales to its constructor. (Line 22) The constructor calls a class factory to get an instance of the Etw logger. The specific type of logger the class factory returns depends on the on the context passed to the factory. ( Line 26)
After constructing the Service behavior, the WCF subsystem calls ApplyDispatchBehavior. (Lines 29 – 44)
ApplyDispatchBehavior iterates through the collection of endpoints (line 31), constructs a new EtwLoggingServiceBehavior and adds that behavior to the endpoints behavior collection. (Line 33)
Then it constructs a new EtwLoggingOperationBehavior, and adds the operation behavior to the operation behavior. (Lines 35 – 42).
Because there can be different ways operations are added to the service, such as being added by an attribute on a specific operation, (Figure 2, Line 18) a check is made to determine if a EtwLoggingServiceBehavior is already in the operation behaviors collection (Lines 37 – 39).
As seen in Figure 2, Line 17, there is one Operation on this Service: GetAllCustomers(). For each operation found, there should be one and only one EtwLoggingServiceBehavior added to the Operation collection. (Line 42)
Use the endpoint behavior to add a Message Inspector into the WCF pipeline.
The endpoint behavior can be instantiated at both the client and server sides of the WCF stack. I won’t discuss here in detail, but you may notice in the code sample the endpoint behavior on the client is creating a custom message.
What’s happening here, is this is one way you can create a ‘back channel’ of information from the client to the server, passing a unique identifier in the message from the client to the server. When the client uses ETW to log to a database and the server does the same, you can use the unique identifier to match the log messages made by the client and server. The topic of describing creating the back channel from the client and reading that data in the server’s WCF stack I’ll leave for a future article.
The Service behavior (Figure 4) gets the collection of endpoints for the service and adds a EtwLoggingEndpointBehavior to each endpoint. (Figure 4, Lines 31-33).
In ApplyDispatchBehavior (Figure 5, Line 35-39), the endpoint behavior gets the collection of Message Inspectors and adds a EtwLoggingMessageInspector. (Figure 5, Line 38).
Message Inspector Behavior
In the code above, extracts a ‘cookie’ from the client. Ignore this code: as stated earlier, the code for passing custom data from the client within the header needs a separate article.
The message inspection behavior allows you to access the messages exchanged between the client and server. (Figure 1).
AfterReceiveRequest (Lines 24 – 47) are called by the WCF runtime when receiving data from the client.
Line 26 is check to determine if ETW logging is enabled. If it’s not, the method returns immediately, incurring minimum performance impact on the WCF service call.
A WCF service must have a host process- a windows service, a console application, or IIS. I’ve experienced problems with some services where memory continues to grow through the day and the service host needs to be shut down and the WCF services restarted.
Line 41 takes a snapshot of the current managed memory when any operation (WCF service call) is made on the service. By capturing and monitoring, you can use this as a starting point, like a canary in a coal mine, to warn you that something (business logic, repository, etc.) is consuming memory. Collecting this data on each service will help you focus your investigation if your host process’s memory size is growing.
Line 43 creates a message containing the memory and size of the message received from the client.
Line 45 passes the message to the logger.
As a side note, I want to point out, although it’s not obvious in the code discussed, you should consider using the keyword meta data on the _etwLogger.Service() method, or use a separate method, such as _etwLogger.ServiceMessageInspector() to allow logging of specific behaviors in the WCF service stack.
Often you don’t want to capture and log data at the Message Inspector level, and using specific keywords or methods for the WCF call stack, you can more granularly control what data you collect.
BeforeSendReply() (Figure 6, Line 50), is called before the WCF runtime transmits data to the client. The implementation here is similar to AfterReceiveRequest().
As you see, you can use the Message Inspector behavior to get a profile of the amount of data exchanged between the client and server.
Compared to the other behaviors, the Operation behavior is straight forward.
The EtwLoggingOperationBehavior’s purpose is to create a EtwLoggingParameterInspector behavior and add that behavior to the operation’s ParameterInspector collection. (Figure 7, Lines 28 – 31).
The Parameter Inspector allows you to access the parameters just before the WCF method is performed, and access them just after it returns, and before the parameters are passed down the WCF call stack to be packaged into a message, serialized, and returned to the client.
In a system configured to allow only logged in domain users to access methods on the WCF service, the Parameter Inspector is a good spot where you can get the user’s identity. (Figure 8, Lines 33 – 35).
If important for your analysis, you could access the parameters from the input array, and log the parameter values.
Line 39 logs the name of the WCF service, the operation performed on the service, and the user making the WCF call.
Example Log output
This is the left panel of PerfView, selecting to view the Service output from the ETW trace.
Below is the right panel showing the traces made by the Service behaviors. Because the image is small and difficult to read, I typed the text for the three rows in the grid.
The first message is
className=EtwLoggingMessageInspector” methodName=“AfterReceiveRequest” data=”EtwCookie: “ MsgLen: 828 TotalMemory 1220164”
The second message is
className=”SalesService” methodName=”GetAllCustomers” data=”BeforeCall Name DANSURFACE\Dan”
The third message is
className=”EtwLoggingMessageInspector” methodName=”BeforeSendReply” data=”934”
Injecting WCF behaviors into the WCF call stack can provide a lot of information about the behavior of your application, how it’s used, provide baseline performance during development and allow real time monitoring within a production system.
In the next articles, I’ll explore how to enable the capturing of ETW events within your client application. By capturing events within your application, you can create an administration screen where you can monitor the application’s behavior, or you could send the ETW events to another system using a messaging system or use the new Semantic Log Application Block (SLAB) to send ETW events to a file or database.