Tracing application via ETW in .NET 4.5

  • Article

Starting with .NET FX 4.5, use of ETW for logging becomes really practical. The ETW has numerous advantages over writing traces (logs) to text files, and over tracing options available in earlier FX versions. Not only it’s faster than anything else, it’s also reliable: you are not losing the last trace record if your application crashes.

You are also not losing a single trace record, if your computer blue-screens. This options requires some setup. Other (and numerous) advantages are discussed elsewhere.

You can also change tracing levels, tracing groups without restarting the application. The list of virtues goes on.

Problem

There is a practical difficulty: How to start using the ETW in FX 4.5 with at least minimal functionality. Like mimic the trace records written to a log file with e.g. Console.WriteLine.

Basic Tracing – Code Side

I want to write two lines (records, log entries, traces) to a trace (to a log), which would be the ETW-based log. I am only interested in writing strings. I don’t care, at the moment, about setting trace levels, trace groups (markers of groups of tracing statements). Nothing special.

How do I do this?

  1. Pick up a name for your trace method. For example, “Trace”. We will also need a name for the “tracing class” – the class, which will contain the method “Trace”. For example, let the class name be the “Tracer”.

  2. Now, code the tracing support class – the Tracer:

     private class Tracer : EventSource

             {

                 public void Trace(string message)

                 {

                      WriteEvent(1, message);

                 }

            }

        3. Do the needed tracing in the application:

private void Run()

{

    var log = new Tracer();

    Console.WriteLine(log.Guid);

    int testCount = 100;

    for (int i = 0; i < testCount; i++)

    {

        var data = string.Format("This is line {0}", i);

        log.Trace(data);

    }

}

This is it. Nothing else is needed.

Basic Tracing – Other Side: “logman”

Run the program. Change the number or repetitions to one million. Run gain. It will be instantaneous. This is because there is no actual logging. Logging should have been activated first.

To activate logging, in the elevated command prompt, type (in one line):
logman create trace mytrace -p {da97437f-63db-5ccd-8c1f-2e8598d8df67} -o c:\mylogs\mytrace.etl -ets

<Here you run the tracing program again>

To stop logging, type
logman stop mytrace –ets

Now, change the number of repetition again to a million. Again, it is almost instantaneous. While the sustained rate is typically lower, it’s still very, very fast.

The “logman” utility is part of the OS; no need to install it. The logman is not the only utility to control the logging – there are many other ways, including XPERF, and many more. The logman is probably the least amount of hassle. Of course, you can script the logman invocations, or control the logging from code.

Now: How to view the resulting trace?

Decoding ETL File

There are two ways. This section describes the first way, not very convenient, but readily available in the OS.

The trace (log) result is in the binary format. Each log line not only contains your data, but, in addition, a set of items like high-resolution timestamp, process and thread identifier, log level and what was earlier named, in ETL, “flags” – a lot extended though.

Anyway, there is need to decode the binary ETL file – that is, to convert to a textual form.

To convert the ETL file into textual (XML) representation, enter

tracerpt c:\mylogs\mytrace.etl

The tracerpt utility has many more options. In particular, it allows to select from a set of output formats.

DecodeEtl3

The second way [to decode ETL files] is to use a custom decoder.

For example, there is a DecodeEtl3 utility, which can be downloaded from https://sergeim.azurewebsites.net. It can only decode the ETL “version 3” files – the files which we are working with (emitted by .NET FX 4.5 EventSource). Another limitation is that this utility can only decode the trace records created by the WriteEvent(1, message) overload – the one we used in the above example. The output looks like below:

DecodeEtl3.exe trace3.etl

08/29/2013-20:01:36.309579 PID:0x3A94 TID:0x1DBC This is line 0

08/29/2013-20:01:36.309582 PID:0x3A94 TID:0x1DBC This is line 1

08/29/2013-20:01:36.309584 PID:0x3A94 TID:0x1DBC This is line 2

 

The DecodeEtl3 has a set of options, like “/short”:

DecodeEtl3.exe /short trace3.etl

This is line 0

This is line 1

This is line 2