{"id":1191,"date":"2014-01-17T13:00:48","date_gmt":"2014-01-17T13:00:48","guid":{"rendered":"http:\/\/writeasync.net\/?p=1191"},"modified":"2014-01-12T12:31:54","modified_gmt":"2014-01-12T12:31:54","slug":"real-time-trace-sessions-with-tx","status":"publish","type":"post","link":"https:\/\/writeasync.net\/?p=1191","title":{"rendered":"Real-time trace sessions with Tx"},"content":{"rendered":"

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

Tx (LINQ to Logs and Traces)<\/a> is an offshoot of the Rx (Reactive Extensions)<\/a> project. (Rx, to quote MSDN<\/a>, “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><\/code><\/a> implementation for a real-time ETW session (EtwObservable.FromSession<\/code>) and code for consuming event data (EtwNativeEvent<\/code> and others).<\/p>\n

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

The main differences are in the KernelProcessSession class<\/a>. We begin by starting and subscribing to the event stream:<\/p>\n

\r\nRealTimeTraceCollectorInfo info = new RealTimeTraceCollectorInfo(this.name);\r\ninfo.Providers.Add(new ProviderInfo(KernelProcessProviderId) { KeywordsAll = 0x10, Level = 4 });\r\nthis.session = info.Create();\r\nthis.session.Start();\r\n\r\nIObservable<EtwNativeEvent> stream = EtwObservable.FromSession(this.name);\r\nthis.subscription = stream.Subscribe(e => this.OnNext(e));\r\n<\/pre>\n
The OnNext<\/code> 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<\/a> to any inner functions — it’s generally a good idea to treat your event consumer code as performance critical to avoid missing events<\/a>.<\/p>\n
\r\nprivate void OnNext(EtwNativeEvent traceEvent)\r\n{\r\n    \/\/ An event is uniquely identified by 3 values -- provider ID, event ID, event version\r\n    if (traceEvent.ProviderId == KernelProcessProviderId)\r\n    {\r\n        switch (traceEvent.Id)\r\n        {\r\n            case ProcessStartId:\r\n                this.ReadProcessStartEvent(ref traceEvent);\r\n                break;\r\n            case ProcessStopId:\r\n                this.ReadProcessStopEvent(ref traceEvent);\r\n                break;\r\n        }\r\n    }\r\n}\r\n<\/pre>\n
EtwNativeEvent<\/code> allows access to the user data payload in the style of a forward-only reader, providing Read[DataType]<\/em><\/code> methods for most supported types. Here is an example from the code to read process start events:<\/p>\n
\r\nprivate void ReadProcessStartEvent(ref EtwNativeEvent traceEvent)\r\n{\r\n    if (traceEvent.Version == 0)\r\n    {\r\n        \/\/ <data name="ProcessID" inType="win:UInt32" outType="win:PID"><\/data>\r\n        \/\/ <data name="CreateTime" inType="win:FILETIME" outType="xs:dateTime"><\/data>\r\n        \/\/ <data name="ParentProcessID" inType="win:UInt32" outType="win:PID"><\/data>\r\n        \/\/ <data name="SessionID" inType="win:UInt32" outType="xs:unsignedInt"><\/data>\r\n        \/\/ <data name="ImageName" inType="win:UnicodeString" outType="xs:string"><\/data>\r\n        EventHandler<ProcessEventArgs> handler = this.ProcessStarted;\r\n        if (handler != null)\r\n        {\r\n            int processId = (int)traceEvent.ReadUInt32();\r\n            DateTime createTime = traceEvent.ReadFileTime();\r\n            traceEvent.ReadUInt32(); \/\/ ignore\r\n            traceEvent.ReadUInt32(); \/\/ ignore\r\n            string imageName = traceEvent.ReadUnicodeString();\r\n            ProcessEventArgs e = new ProcessEventArgs()\r\n            {\r\n                Id = processId,\r\n                ImageName = imageName,\r\n                Timestamp = createTime\r\n            };\r\n\r\n            handler(this, e);\r\n        }\r\n    }\r\n}\r\n<\/pre>\n
To stop delivering events, the subscription can simply be Dispose()<\/code>‘d.<\/p>\n
Run the TxSample app (elevated<\/strong>, as always!) and open and close a few processes. The behavior should be exactly the same as TraceSample. Sample output:<\/p>\n
[000.002] Starting session...
\n[000.032] Running.
\n[010.032] Stopping session...
\n[010.034] Stopped.
\n[010.036] Dumping event data...
\nProcess 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.
\nProcess 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.
\nProcess 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.
\nProcess 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.<\/code><\/p>\n","protected":false},"excerpt":{"rendered":"
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… <\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[71],"tags":[],"class_list":["post-1191","post","type-post","status-publish","format-standard","hentry","category-diagnostics"],"_links":{"self":[{"href":"https:\/\/writeasync.net\/index.php?rest_route=\/wp\/v2\/posts\/1191","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/writeasync.net\/index.php?rest_route=\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/writeasync.net\/index.php?rest_route=\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/writeasync.net\/index.php?rest_route=\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/writeasync.net\/index.php?rest_route=%2Fwp%2Fv2%2Fcomments&post=1191"}],"version-history":[{"count":0,"href":"https:\/\/writeasync.net\/index.php?rest_route=\/wp\/v2\/posts\/1191\/revisions"}],"wp:attachment":[{"href":"https:\/\/writeasync.net\/index.php?rest_route=%2Fwp%2Fv2%2Fmedia&parent=1191"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/writeasync.net\/index.php?rest_route=%2Fwp%2Fv2%2Fcategories&post=1191"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/writeasync.net\/index.php?rest_route=%2Fwp%2Fv2%2Ftags&post=1191"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}