Real-time trace sessions with Tx

I recently showed an example of how to use TraceEvent to consume events from real-time trace sessions. Today I will show another way using the Tx.Windows NuGet package.

Tx (LINQ to Logs and Traces) is an offshoot of the Rx (Reactive Extensions) project. (Rx, to quote MSDN, “is a library to compose asynchronous and event-based programs using observable collections and LINQ-style query operators.”) Tx.Windows specifically adds an IObservable<T> implementation for a real-time ETW session (EtwObservable.FromSession) and code for consuming event data (EtwNativeEvent and others).

To show the code in action, I revisited the TraceSample project I created previously and reimplemented it using Tx in the TxSample project. The new project incorporates all of the core code from TraceSample (minus anything TraceEvent-dependent) as well as the real-time trace session code from PlaSample.

The main differences are in the KernelProcessSession class. We begin by starting and subscribing to the event stream:

RealTimeTraceCollectorInfo info = new RealTimeTraceCollectorInfo(this.name);
info.Providers.Add(new ProviderInfo(KernelProcessProviderId) { KeywordsAll = 0x10, Level = 4 });
this.session = info.Create();
this.session.Start();

IObservable<EtwNativeEvent> stream = EtwObservable.FromSession(this.name);
this.subscription = stream.Subscribe(e => this.OnNext(e));

The OnNext method is called each time a trace event arrives. Note that in Tx the core trace event type is a struct, so I’ve opted to pass it by reference to any inner functions — it’s generally a good idea to treat your event consumer code as performance critical to avoid missing events.

private void OnNext(EtwNativeEvent traceEvent)
{
    // An event is uniquely identified by 3 values -- provider ID, event ID, event version
    if (traceEvent.ProviderId == KernelProcessProviderId)
    {
        switch (traceEvent.Id)
        {
            case ProcessStartId:
                this.ReadProcessStartEvent(ref traceEvent);
                break;
            case ProcessStopId:
                this.ReadProcessStopEvent(ref traceEvent);
                break;
        }
    }
}

EtwNativeEvent allows access to the user data payload in the style of a forward-only reader, providing Read[DataType] methods for most supported types. Here is an example from the code to read process start events:

private void ReadProcessStartEvent(ref EtwNativeEvent traceEvent)
{
    if (traceEvent.Version == 0)
    {
        // <data name="ProcessID" inType="win:UInt32" outType="win:PID"></data>
        // <data name="CreateTime" inType="win:FILETIME" outType="xs:dateTime"></data>
        // <data name="ParentProcessID" inType="win:UInt32" outType="win:PID"></data>
        // <data name="SessionID" inType="win:UInt32" outType="xs:unsignedInt"></data>
        // <data name="ImageName" inType="win:UnicodeString" outType="xs:string"></data>
        EventHandler<ProcessEventArgs> handler = this.ProcessStarted;
        if (handler != null)
        {
            int processId = (int)traceEvent.ReadUInt32();
            DateTime createTime = traceEvent.ReadFileTime();
            traceEvent.ReadUInt32(); // ignore
            traceEvent.ReadUInt32(); // ignore
            string imageName = traceEvent.ReadUnicodeString();
            ProcessEventArgs e = new ProcessEventArgs()
            {
                Id = processId,
                ImageName = imageName,
                Timestamp = createTime
            };

            handler(this, e);
        }
    }
}

To stop delivering events, the subscription can simply be Dispose()‘d.

Run the TxSample app (elevated, as always!) and open and close a few processes. The behavior should be exactly the same as TraceSample. Sample output:

[000.002] Starting session...
[000.032] Running.
[010.032] Stopping session...
[010.034] Stopped.
[010.036] Dumping event data...
Process ID 284780 with image name 'cmd.exe' started at 1/17/2014 12:29:18 PM and exited at 1/17/2014 12:29:19 PM with code 255.
Process ID 407984 with image name 'conhost.exe' started at 1/17/2014 12:29:18 PM and exited at 1/17/2014 12:29:19 PM with code 0.
Process ID 396676 with image name 'calc.exe' started at 1/17/2014 12:29:21 PM and exited at 1/17/2014 12:29:22 PM with code 0.
Process ID 29648 with image name 'dllhost.exe' started at 1/17/2014 12:29:18 PM and exited at 1/17/2014 12:29:23 PM with code 0.