Event Tracing for Windows

An event trace is a sequence of event records, each of which is composed of a standard system defined header with well defined fields that are common to all events, such as the time that the event was written. It may also optionally contain custom data that is specific to that event type.

The event header contains the following fields shown in ETW event header fields, though some fields may have empty values if the field is not applicable for the event or is not defined by the provider.

In addition to the above standard fields, an event may optionally contain custom user data, the structure of which is completely upto the writer of the event. For example, the user data fields for a trace event that records process starting may contain fields with the process id and the path of the executable. The fields for a network connection trace event may contain the local and remote addresses and ports.

The format of this user event data need not be published if the event will only be read or consumed by some private application that already knows about that specific structure. However, for the custom fields to be decoded and intelligently interpreted by any arbitrary event consuming application, including the event viewing programs included with Windows, the event structure must be published.

In Windows versions prior to Vista, the structure of the event was defined in the Managed Object Format (MOF) and registered in the Windows Management Instrumentation (WMI) database where event consumers could use it to decode events. Although this method is supported in Vista and later versions of Windows as well, the recommended method is now to define events using an XML manifest which is embedded in event provider executable. The twapi_etw package supports consuming both types of events. However, for compatibility with Windows XP and Windows Server 2003, events are written using the older MOF-based format.

Some ETW events may also be associated with messages which are constructed from a string template specific to the event id in that provider and the data contained in the user data fields for the event.

Events are written to a event trace which is identified by a name and consists of a set of buffers which store the events and can be read by event consuming applications or written to an associated file for persistent storage. Events are written to one or more traces from where they can be read by any interested parties.

The Windows kernel provides a special preconfigured trace named NT Kernel Logger that receives events from the operating system kernel. There are some special considerations when using this trace as described in The NT Kernel Logger.

Event providers are components that write events to a trace. The provider is responsible for the format and content of the written events but has no control over which trace(s) the events are actually sent; that is an ETW controller function.

Controllers send configuration information to providers in the form of enable flags and the enable level. The interpretation of these is entirely to the discretion of the event provider.

By convention, applications treat the enable flags as a bit mask that indicates the class(es) of events to log. For example, each bit might correspond to a specific subsystem.

Event controllers manage the overall process of event tracing including

The last type of component that plays an role in event tracing is the event consumer. This is any application that reads event records either from a persistent log file or from a real time trace and interprets them as per the published definition from an event provider.

Microsoft itself provides several applications that process and display ETW event traces and are either shipped with the operating system or free to download. Examples are the Windows Event Viewer, the Microsoft Network Monitor and xperf which is part of the Windows Performance Analyzer.

The only item that absolutely must be specified when starting or creating an event trace is its name. Since a event trace is identified by its name, it must be unique on the system. Like file names, trace names are case-insensitive.

More often than not, you will also want to specify the name of the log file to which events are to be written. This is not strictly necessary since events can also be consumed in real-time without being written to a log file. This is described in Real Time Tracing. In most cases, it is advisable to specify a log file for a couple of reasons. Firstly, it reduces the chance that events are lost because the consumer was not able to read the events fast enough. Secondly, most usage scenarios call for the event traces to be iteratively processed which requires the events to have been persisted to a file.

The command etw_start_trace returns a handle to a new event trace.

By default, the log file is written in circular fashion so that newer events overwrite older events once the specified maximum log file size is reached. This behaviour can be changed through the -filemode option to the etw_start_trace command. For example, the -filemode rotate option will create a new log file once the maximum file size is reached. See the documentation of etw_start_trace for the possible values of -filemode and their effect.

Various other options can be specified when starting a trace. The more commonly used ones are shown in Trace configuration options.

A new created event trace has no providers attached to it and therefore will not receive any events. For events to be written to the newly started event trace, one or more providers need to added to it. We next proceed to just that.

Before adding a provider to a trace, we need to find out which provider it is that should be added. A listing of all providers can be obtained through the etw_get_providers command.

Alternatively, the list is also available through the one of the previously mentioned Windows programs, for example, logman

Knowing the name of the provider is not sufficient. When adding a provider to an event trace, a controller also needs to indicate to the provider which events it should log based on the following criteria:

Specifying the level numbers is generally straightforward as levels have the same semantics for all providers. However, the keyword masks and their meaning do not have standard definitions. A provider is free to assign any meaning for each keyword bit so you need to look up them up on a per-provider basis. For older providers that do not use manifests to describe events, this information is sometimes only available through the provider’s documentation. For newer manifest based providers, and providers that come with the system, the easiest way is to use the logman command.

This shows the list of keyword bits defined by the Microsoft-Windows-Kernel-Process provider and a brief description of each. We can guess from the above listing that this provider logs events related to processes, threads and image loading. We will assume only process events are of interest to us.

We can now go ahead and enable the provider in the trace we created earlier. We will enable messages at informational level and below for process related events (keyword mask 0x10) only.

The etw_enable_provider command attaches the provider to the trace. Just to ensure that there are events written to the trace we will start a child process and have it immediately exit.

Event providers can be added to a trace at any time and multiple event providers can be attached to a trace. You can even change the settings for a previously enabled provider.

For example, we can request for image loading events to be logged as well.

When a trace is running we can query its status from Tcl with etw_query_trace which returns a dictionary containing various pieces of information about the trace.

Many of the status fields are self-explanatory and you can refer to the etw_query_trace documentation. Some fields reflect the configuration settings of the trace and are discussed in the next section. Here we draw attention to only those fields pertaining to lost events.

An event trace has a set of associated buffers, buffer_count in number, of a specific size, buffer_size KB, that store events as they are written by providers. As each buffer fills up, it is written out to the persistent log file or provided to a Real Time Tracing consumer. This frees up the buffer to receive more events. If the rate at which buffers can be flushed cannot keep up with the rate at which events are being written to the trace, new events are thrown away. The events_lost counter keeps track of this number. The trace may then have to be configured to increase the number of buffers.

The log_buffers_lost and real_time_buffers_lost fields counts the number of buffers that could not be written to disk or delivered to real-time consumers respectively. Note this is not necessarily due to direct event rate problems; for example, the disk may be inaccessible or the consuming process may have died. Changing buffer configuration in such cases may not help.

The next section describes how to change the configuration of a trace to deal with these issues.

Some aspects of the configuration of an event trace can be modified while it is running. For example, you may want to increase the number of buffers used by the trace if you see events being lost as described in the previous section.

The command returns the state of the event trace in the same dictionary format as the evt_query_trace. As you can see, the max_buffers configuration parameter is incremented.

Another configuration setting that is often useful is -logfile which switches the trace to a different log file. See the documentation of etw_update_trace for other configuration options that can be set.

Event providers can be removed from a trace at any time with the etw_disable_trace_provider.

It is good practice to do this before stopping a trace. If an event provider remains enabled when a trace is stopped, behaviour depends on the version of Windows and the specific provider. On newer versions of Windows with manifest based providers, when a trace with the same name is started again, the provider will be automatically be reenabled for that trace. On older systems and with MOF based providers, the exact behaviour depends on the provider implementation and whether it was enabled for other traces in the meantime. It is best to not rely on this.

Stopping a trace is simple.

The etw_stop_trace command returns the final state information about the trace.

Notice we supplied the name of event trace to etw_stop_trace, not the trace handle. We could have used the trace handle as well. In fact, most commands demonstrated above will accept either the trace name or the trace handle. Using the trace handle is slightly more efficient but since the commands are infrequently invoked, this is not of much consequence.

Windows contains one specific predefined trace named NT Kernel Logger which logs kernel events like disk I/O, context switches etc. This trace has one provider - Windows Kernel Trace - attached to it. Kernel traces differ from the user traces discussed so far in several respects.

Although the etw_start_trace command can be used to start a kernel trace, the easier method is to use the etw_start_kernel_trace wrapper which allows the kernel components of interest to be specified without having to know the appropriate keyword masks.

In the example below, we trace a socket connection using the kernel logger.

We will analyze and compare these trace in Consuming Event Traces.

The kernel components that can be traced depend on the Windows version. See the documentation for etw_start_kernel_trace for the allowed values for the various Windows versions. The references Improve Debugging And Performance Tuning With ETW, Core OS Events in Windows 7, Part 1 and Core Instrumentation Events in Windows 7, Part 2 provide additional information about the various types of kernel events and their usage in application analysis.

The etw_dump command returns a record array containing trace records from one or more trace files. The recordarray command can then be used to extract specific records or fields. In the following example, we extract the first record pertaining to process start events as a dictionary and print it.

The trace record fields correspond to the fields described in ETW event header fields with the -properties field being a dictionary that holds the custom event data specified to the event type.

Note the message string is actually a string template that includes insert placeholders of the form %N. The message string for an event is formed by replacing the placeholders with appropriate values from the -properties dictionary for the trace record. The etw_format_event_message does this as shown in the sample code below.

Although the above example only processed one trace file, etw_dump as well as the lower level commands discussed later, will accept multiple trace file arguments. The Windows libraries will merge the records from multiple traces.

The command etw_dump, and the similar etw_dump_to_file, is useful for quick dumps or searches of log files. However, they have the drawback of reading all trace records into memory which may not be desirable if the traces are large and only a subset of the records are of interest. We now look at the lower level programming interfaces which allow consuming of events in smaller chunks using callbacks.

The first step in processing events from an event trace log file is to open it with etw_open_file.

We also need a trace formatter which will translate the raw binary events into a form we can consume.

We define a callback that will be invoked for every buffer in the traces. The callback needs a formatter as it will print records of interest. We will explicitly pass this as the first parameter. The other two parameters are appended on every invocation of the callback and contain the trace buffer and the raw event records respectively. The callback will format the raw events using etw_format_events and then iterates over the returned record array using a filter to restrict the records to those related to TCP/IP. The NT Kernel Logger distinguishes between different kernel components through -taskname event record field values like DiskIo or TcpIp. We will filter the record array accordingly and print out the connection information for each event.

We then do the actual processing of events by invoking etw_process_events. This command will invoke the callback for every buffer in the trace and only return when all the events have been consumed or the callback has terminated the event processing. Note the formatter is explicitly passed to the callback as its first parameter.

We finally need to close the trace consuming session as well as the formatter to release allocated resources.

There are additional options that can be used with the processing of events using callbacks, for example, terminating the processing before all events are processed or limiting the retrieved events to a specific time interval. See the documentation of etw_process_events for details.

The mechanics of setting up a real-time trace are almost identical to those described in Starting a trace. The only difference is that the -realtime option needs to be specified. Although not shown in the sample code below, the -logfile option could have been specified as before to log the trace to a file as well.

Consuming a real time session is also similar to consuming a trace from a log file with the following differences:

This last point needs some elaboration. The Win32 function ProcessTrace on which etw_process_events is layered, does not return from the call until the trace is stopped or until the callback return a break status. In the former case, the program is prevented from doing any other work while the trace exists. In the latter case, the program has to periodically call etw_process_events but risks losing events.

Both these strategies are feasible depending on the application involved, rate of events etc. Below we demonstrate a third option - use of a separate thread - which alleviates both potential issues.

We start off by loading the Thread package which allows manipluation of threads at the Tcl script level.

We then create a thread using thread::create, passing it a script that will do the actual processing of events in real time. The script is identical to that described in Processing traces using callbacks with the exception that since we are dealing with a real time trace, etw_open_session is called instead of etw_open_file. The script collects events in real time and queues them to be retrieved by the main thread. This is merely to demonstrate passing data between threads. In a real application, the created thread could do all required processing itself.

Having started a separate thread for consuming trace events, back in the main thread we start a child process so as to trigger a trace event. We use the combination of after and vwait for the process to start and exit.

We finish up as described in earlier sections by disabling the trace provider and stopping the trace.

Stopping the trace will also cause the etw_process_events command in the secondary thread to return. Because of the thread::wait at the end of the secondary thread script, the thread will not exit but will continue processing messages from other threads. This allows the main thread to retrieve the collected events and print them.

Finally, after retrieving the data we release the secondary thread so it can exit.

We now show a simple example of using ETW to analyse program flow when retrieving a URL using the Tcl http package.

We start off by registering ourselves as a ETW provider and starting a ETW trace. This second action could also be done from a different ETW controller program such as logman.

We then load the http package and use the Tcl trace command to have the TWAPI ETW execution trace logger automatically invoked whenever the http::geturl command is executed.

As discussed in a previous section we need to add ourselves to the event trace. Because we want to also correlate execution with network events, we will also add the Microsoft-Windows-Kernel-Network provider to the trace.

We now fetch a URL.

Assuming no more tracing is to be done, we remove the traces and unregister the provider.

Now that the tracing is done, we will read the trace as described in Consuming Event Traces. We first need to install out event definitions for the trace file to be parsed and then dump the events. Note we filter out events from MSNT_SystemTrace as they are of no interest for our purposes.

For purpose of exposition, we have simply printed the event records. For detailed analysis of program flow, you would add enterstep and leavestep to the trace command arguments. The events would then include enough information to build a complete call tree including nested calls, arguments and return values at each level. Inclusion of system trace information, the network traffic in this case, allows inclusion of flow information through the operating system as well.