EventSource & Performance for High Volume Events

.net framework 4.5 introduced EventSource API to write events using ETW infrastructure. The choice of ETW infrastructure has made the writing of events lightning fast. Now they can be consumed by any ETW consumer. If the event provider is not enabled, then the events just fall on the floor. On the other hand, if a session is already established, they are written to ETW session buffers. Now they can be consumed by the consumers. The event provider (EventSource) doesn't really have to wait until the messages are consumed. This is independent on the number of consumers registered for a particular type of events. We have discussed about ETW tools and their usage with EventSource API [Reference].



As we discussed above, the choice of ETW infrastructure has made EventSource API extremely fast. But we can even improve on it further. But remember that these recommendations would be useful in the case for high volume events generally. For low frequency events, although you would have performance improvement, but this might not be very noticeable.

Optimization # 1: Use IsEnabled() before WriteEvent()
ETW controllers can enable a provider before registration of provider. So when a provider registers itself and starts emitting events, a session is automatically created and they are forwarded to the buffer. In order to prove that, we can start Semantic Logging Service (from Application Block) and then run our application. Our service should still be able to consume the events. On the other hand, if the provider is not enabled, the events just fall on the floor by the ETW infrastructure. In order to improve it, we can check if the event provider is enabled so that we don't even use the WriteEvent() definition in base class. It does check the same thing in the base class as well.

When an Event Provider is enabled (generated for EventSource), it receives a command to enable itself. We can even use this command in our custom EventSource by overriding OnEventCommand() method. You don't need to use the definition of base class method as there is an empty implementation of the virtual method.



It caches this in a local variable. So EventSource can use this field to check if it is enabled. There is no property available in EventSource type to check that but we can find IsEnabled() method to do just that. Now a method might cause some confusion for you thinking it might be slow as it might do some other stuff and could slow it down further. As the development team suggests, it is just a field fetch. We can also verify this by dotPeeking into the framework assembly from Windows folder.



As a matter of fact there are two overloads of the method. One of these overloads is parameter less. The other one is more interesting, it lets us check if the provider is enabled for a particular level and keyword, which makes it more interesting.



Optimization # 2: Convert static field fetch to local member fetch
This suggestion is not for EventSource implementation but it refers to the use of EventSource instance in the logging site. The logging site is the code from where we call EventSource's methods. As we have seen several examples in this blog, EventSource implementation is singleton based [See singleton], it is a static variable fetch at the call site. Here is an example of the usage:



As we know static variable fetch is more expensive than an instance member fetch, we can assign the singleton instance to a local instance member. In order to improve the usage of EventSource's method, we can assign this to a local variable. Then we can use the local member at the logging site.



Optimization #3: Minimize the number of EventSources in the application
In a previous post, we discussed about the mapping between EventSource and ETW Event providers. Actually the framework registers an Event Provider in ETW infrastructure for every EventSource in the application. This is done using ETW EventRegister API. This allows the framework to pass a command to the EventSource from external controllers.

The framework also maintains a list of EventSources in the application domain. We can get the list of all EventSource (s) in the application domain using the static GetSources() method in EventSource type.



Both of these tasks are performed at startup. Since this would depend on the number of EventSource (s) in the applications so the higher number for event sources in your application would mean slower startup. This can be resolved by minimizing the number of EventSource in your application. I would definitely not suggest an EventSource for each type in your application. There can be two options to resolve this.

The first option is using Partial types. We can span the same type across different files in the same assembly. All of these definitions are combined to generate a consolidated type by the compiler. We generally organize our types in different folders in a project. Here each folder generally represents types belonging to the same group. We can provide all the event methods definition for the method group for the types in this folder.

Most of the real life projects span more than one projects. In this case, we should still be able to minimize the number of EventSource (s), by defining on for each group, in order to improve the startup performance. Here each event source can take care of instrumentation requirement for a group of types in your application. You can group them logically or the way you want.

Optimization # 4: Avoid fallback WriteEvent method with Object Array Parameter
There are various overloads of WriteEvent() methods in EventSource type. We need to call WriteEvent() method from our [Event] methods in EventSource type. One of these overloads is an overload with params array. If none of the overload matches your call then the compiler automatically falls back to this overload.



We should be avoiding the fallback method as much as possible for performance reasons as it is reported to be 10-20 times more expensive. This is because the arguments need to cast to object, an array needs to be allocated and these casted arguments are added to the array. Then calling the methods with these arguments as serialized.

In order to avoid using the fallback overload, we can introduce new WriteEvent() method by overriding it.

SLAB, EventSource and Standard ETW Tools

As we have been discussing through the past few posts that we can direct event log data generated through EventSource to be saved in different destinations. EntLib6 provides a number of sinks provided just for that purpose out of the box. They include support for console, files, Sql Server database and Windows Azure Table storage. We have also seen how we can direct the event's data to Windows Event Log [Discussion]. It would be interesting to see how we can use the existing ETW tools to view the event's data generated using EventSource API in .net framework 4.5.

EventSource API is based on registration free ETW [Event Tracing for Windows] data. This means we don't have to register an ETW event provider for generation and consumption of these events. The existing tools including LogMan and Windows Performance Analyzer are based on registered event providers. But since EventSource API is still based on the same ETW infrastructure, we can register the Event Provider manually and direct the events' data to an ETL file. Since these tools can work with this format, we can use our expertise in these tools to troubleshoot and analyzer situations we need this data for.

It must be remembered that EventSource API uses ETW infrastructure only in the case of out-proc listeners.

Performance Monitor [Perfmon.exe]
Since EventSource establishes an ETW session for out-proc consumers, we should be able to use PerfMon to see the details of the session.



As an ETW provider, each event source is assigned with a GUID. We can note the unique identifier from the properties of the provider. This identifier is generally used by ETW controllers to start / stop a session. We can also verify that the streaming mode for the configured EventSource as Real time.



PerfMonitor.exe
Like PerfView, PerfMonitor is also based on TraceEvent library. The major benefit of PerfMonitor over Perfmon is that the former can be used as an ETW controller.



https://bcl.codeplex.com/releases/view/99985

Logman
Internally Logman seems to use Performance Logs & Alerts service. If the service is not running, the utility just starts this. Make sure that we are running the command prompt with Administrative privileges.



Here we are creating a trace data collector using Logman utility.


After running the above command, we should be able to find the specified collector when queried. This can also be done using Logman. The utility supports a verb "query" which list all the data collectors.



We need to start the data collection for the events generated from the event provider. In order to do that we can use Logman's start verb with the provider's name as follows:

Querying the provider again should show the status of the provider as Running. This should ensure that the command ran successfully.



Stopping the trace session should flush the trace data in the ETL file. Here is the file generated for our provider in the same folder as we specified while creating trace data collection for the provider.



Logman also registers a user-defined trace which can be viewed with Performance Monitor.



Tracerpt
This is another useful Windows Utility for ETW data. One of the usage for this utility could be to process the ETL files generated using any other tool. It can be used to generate human readable files from the binary data. Let's see the following usage:


The above command should generate dumpfile.xml and summary.txt in the same folder. For the events generated for our event provider, the following files are generated. You can open them to have an idea about the expected format for the generated files. We should note that the utility allows us to control the names and format of dump and summary file names and formats. The supported formats for dump file include XML (default), CSV and EVTX.

  

We can also generate xml (default) or html based report for the generated events data. Here we are generating the report in html format. It generates the report based on the etl file provided in the same command.


You can have a look at the following report generated for events generated from our event source.



Tracerpt can also use ETW data from real time sessions. We can use PerfMon to determine the session we are interested in. We can then use the same name with -rt switch for TraceRpt. Here is the session details for our event source.

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.


Download

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.