Tuesday, July 30, 2013

Semantic Out-Process Logging using Semantic Logging Application Block - File Sink

In this post, we are going to look how SLAB (Semantic Logging Application Block) can be used for out-process logging for ETW events. Pattern & Practices (P&P) team has provided support for out-process logging of ETW based logs using Semantic Log Service. The executable for the service can be downloaded from here: [ http://go.microsoft.com/fwlink/p/?LinkID=290903 ]. Let's copy the downloaded installer to the some folder.

Running the executable extracts the required files in the specified directory. Here we are specially interested in install-packages.ps, the power shell script to download the required nuget packages to the directory.

Let's run the power shell script. This would download the required nuget packages as follows:

It must be remembered that the Semantic Logging Service must run on the same machine as the source application emanating ETW events data. We need to update the configuration of the out-proc service to utilize the events. You can see that we have updated the event source definition to look for the specified events. Here we have used FlatFileSink. This would write the events data to the file specified. In the current example we are using SemanticETWLogs.log, which would be created in the same folder. Here we have also used the text formatter which would create header text. In the next post, we will be introducing what other text formatting options are available.

Now we can run the out-proc process to register and log the ETW events. The process can run as a Windows Service or Console application. For our example, let us run it as a console application. This requires -console switch to be used to run it. Please make sure that you are running this with a command prompt using the Administrative privileges, otherwise, the command results in a failure.

Now we simply need to run the source application. Since it is registering some events, the logs are available in the specified file. For my case the data is as follows:

Please make sure that your EventSource is decorated with the attribute to specify the ETW event expected by out-proc listener.


Monday, July 8, 2013

EventSource & PerfView

.net framework 4.5 was released by Microsoft with many bells and whistles. Many of the features released were revolving around async. They include support async / await, support for async in file I/O and Task based async support. As a matter of fact, async has attracted so much attention that other new features have slipped away from developer's attention. One such feature is EventSource. This is provided to create strongly typed events to be captured by ETW [Event Tracing for Windows]. You can find the System.Diagnostics.Tracing namespace in mscorlib.

As enterprise developers, we develop systems for supporting different operations of an enterprise. We help them from being technology enabled to becoming technology driven. The software development and Information technology is not a staff department anymore. It is one of the line department. As the businesses are learning, it has become easier for us to convince the management for investing more on the tools of the trade.

Logging has historically been considered as a center piece of debugging tools. It is to diagnose the failures caused by code in error, and fixing that. But what about code running in production. We tend to create our staging and test environments as a replica of prodution as close as possible. But it is never a perfect replica of production. Hence there are some errors which are only seen in production. The complex interaction between various enterprise tools result in such failures and deadlocks. If we enable these logs for our production system, we can go through the logs to discover what interaction of the system caused the situation.

Software provide interactions through its interfaces. For human users, these interfaces are in the form of UI. For commercial products, these user interfaces are created by years of research of UX [User Experience] experts. But there is a limit to all this research, otherwise, all products released by technology giants would always be successful. Building successful products not only attracts more customers but more and more quality professionals willing to work for you. Logging user interactions builds up historical usage data. This can be immensely helpful to determine usage patters of various demograhics. We can determine what part of applications are commonly used and we can work on improving those use cases and target them more towards the demographics obtained through the historical data.

Structured logging
Unstructured data is very hard to consume. They take a string and slap it out to a datasource. Semantic logging is to put a structure to the logging so that it is easier to be consumed for the applications which might be used to generate useful information from these logs. With the current unstructured logging, the logs are generally appended in a text file. The file keeps growing. In case of any failure, this is the first thing developers ask to diagnose the issue.

The non-business requirement is about system maintenance. It is about taking your systems seriously. We need to train our analysts to include logging in requirements. With Domain driven design and now Behavioral driven design, since we are supposed to be part of the discussion from the very start of the system life cycle, we shouldn't just be raising our voices to write better acceptance tests, rather we should be making sure that software maintenance issues are brought up in the earliest of discussion. I know we are not creating software to log, but in order to run it we need logging. It's just a necessary food ingredient for the recipe of system design. It is about changing the way people think about logging. The structured logging suggests to think about the consumption of logging upfront, so it is not an afterthought. How many requirement specifications we have seen which discusses about logging.

Quarterly Earnings from Microsoft & Microsoft System Center
Microsoft's earnings can be seen to determine the industry trends about tools and technologies. Let's look at the recent quarterly earning details from Microsoft. The details can be found on Microsoft. You can notice how much investment is taking place on server tools and System Center.

ETW [Event Tracing for Windows] & .net framework 4.5
ETW events are generally used for server applications. Microsoft introduced EventSource in.net framework 4.5 to provide ease of generation of ETW events for applications. EventSource is not an abstract class but both of its constructor are protected. So we cannot directly instantiate it but we can certainly inherit from it. According to Microsoft, the type is provided for emitting events for interesting operations in your application. It provides a convenient way to log these events.

In order to use EventSource, we need to provide a specialization of EventSource by inheriting from it. In the implementation, we can introduce methods to log any sort of activities we need to log with the appropriate messages. These methods can use WriteEvent method provided by the base class.

Let's look at the definition of MyEventSource type. As is apparent above, this is a specialization of EventSource providing WriteLog method. This can be defined as follows:

So the whole idea is to provide the definition a sub-type of EventSource class. This type would introduce the methods for logging specialized data. Those methods would just be using an overload of WriteEvent method in EventSource. We need to make sure that we are careful about EventId. A missing Id would result in no ETW events. You might learn it the hard way like me. For my case, I was starting the EventId with 2 instead of 1 earlier. Updating the Id as above fixed the issue. This is hard learning, surprise!!!

Collecting ETW Events using PerfView
We can use any industry standard tool to collect the ETW events data generated using EventSource. PerfView is also equipped to support such events. It is available as a separate download from Microsoft.

Running the tool would open up a helpful interface with enough details about its usage.

In order to see the events data generated from a particular provider, we can launch it through Command prompt. This allows us to customize the ETW events collection. In the following, we are launching PerfView for particular provider. Here run would run the specified command and collect the events data.

This would collect the events and load the data in PerfView tool. Here you can see the data being generated from our customized provider. Double clicking the event would show the complete data.

The same result can be obtained by running the command using PerfView as follows:

PerfView also provides Event Stats data. For the case of our MyEventSource, the data looks like this:

Here we have assumed basic knowledge of running PerfView. There are useful references to run the tool.

System.Diagnostics.Tracing Attributes
The namespace provides two attributes on the level of class and method. They are EventSourceAttribute and EventAttribute.

Supported Platforms
EventSource is supported in .net framework 4.5 and Windows Store apps.

Issues and Details
There are some details which you might find through experience like me. I just think it would be easier for you if I list them here. There is no documentation for these anywhere. Make sure that you don't miss an EventId in the EventSource methods, otherwise no collection would take place.