{"id":4801,"date":"2015-09-30T13:00:33","date_gmt":"2015-09-30T13:00:33","guid":{"rendered":"http:\/\/writeasync.net\/?p=4801"},"modified":"2015-09-30T04:32:06","modified_gmt":"2015-09-30T04:32:06","slug":"eventsource-and-rich-payload-data","status":"publish","type":"post","link":"https:\/\/writeasync.net\/?p=4801","title":{"rendered":"EventSource and rich payload data"},"content":{"rendered":"

Long ago, I wrote about EventSource<\/a>, the simple and modern ETW-based tracing solution for .NET 4.5+. Much to the diagnosticians’ delight, EventSource<\/a> continues to evolve in .NET 4.6<\/a>. Check out Vance Morrison’s post describing the useful new “rich payload data” feature<\/a>.<\/p>\n

Here is a minimal example showing a new manifest-free way to log such semi-structured data with EventSource.Write<T><\/code><\/a>:<\/p>\n

\r\nnamespace RichPayloadDataSample\r\n{\r\n    using System;\r\n    using System.Diagnostics.Tracing;\r\n    using System.Threading;\r\n    using System.Threading.Tasks;\r\n\r\n    internal sealed class Program\r\n    {\r\n        private static void Main(string[] args)\r\n        {\r\n            using (CancellationTokenSource cts = new CancellationTokenSource())\r\n            {\r\n                Task loop = EventLoop(cts.Token);\r\n                Console.WriteLine("Press ENTER to quit.");\r\n                Console.ReadLine();\r\n\r\n                cts.Cancel();\r\n                loop.Wait();\r\n            }\r\n        }\r\n\r\n        private static async Task EventLoop(CancellationToken token)\r\n        {\r\n            await Task.Yield();\r\n            MyEventSource myEvents = MyEventSource.Instance;\r\n            int n = 0;\r\n            try\r\n            {\r\n                while (!token.IsCancellationRequested)\r\n                {\r\n                    ++n;\r\n                    Console.WriteLine("[{0}] Iteration {1}.", Thread.CurrentThread.ManagedThreadId, n);\r\n\r\n                    myEvents.Write("SomethingGood", new GoodStuff { Name = "X" + n, Number = n });\r\n                    await Task.Delay(500, token);\r\n\r\n                    myEvents.Write("SomethingBad", new BadStuff { Name = "Z" + n, Number = -n });\r\n                    await Task.Delay(500, token);\r\n                }\r\n            }\r\n            catch (OperationCanceledException)\r\n            {\r\n            }\r\n        }\r\n\r\n        [EventData]\r\n        private sealed class GoodStuff\r\n        {\r\n            public string Name { get; set; }\r\n\r\n            public int Number { get; set; }\r\n        }\r\n\r\n        [EventData]\r\n        private sealed class BadStuff\r\n        {\r\n            public string Name { get; set; }\r\n\r\n            public int Number { get; set; }\r\n        }\r\n\r\n        [EventSource(Guid = "554283bf-0ce9-4216-a925-f8629295ba1d")]\r\n        private sealed class MyEventSource : EventSource\r\n        {\r\n            public static readonly MyEventSource Instance = new MyEventSource();\r\n\r\n            private MyEventSource()\r\n            {\r\n            }\r\n        }\r\n    }\r\n}\r\n<\/pre>\n
Let’s see what this data looks like in plain old ETL format. Using logman<\/code><\/a>, we can log the events to a file (remember, elevated command prompt):<\/p>\n
\r\nlogman create trace RichPayload -p {554283bf-0ce9-4216-a925-f8629295ba1d} 0xFFFFFFFF 5 -ow -o RichPayload.etl\r\nlogman start RichPayload\r\n[ ... at this point, we run the app for a few seconds and quit ... ]<\/em>\r\nlogman stop RichPayload\r\n<\/pre>\n
With tracerpt<\/a>, we can then decode the traces into EVTX format for easy viewing:<\/p>\n
\r\ntracerpt -l RichPayload_000001.etl  -of evtx -o RichPayload.evtx\r\n<\/pre>\n
Now, open the EVTX file in Event Viewer<\/a> and look at the event payload in the Details tab, selecting XML View. You will see output like the following:<\/p>\n
\r\n<Event xmlns="http:\/\/schemas.microsoft.com\/win\/2004\/08\/events\/event">\r\n  <System>\r\n    <Provider Name="MyEventSource" Guid="{554283bf-0ce9-4216-a925-f8629295ba1d}" \/>\r\n    <EventID>2<\/EventID>\r\n    <Version>0<\/Version>\r\n    <Level>5<\/Level>\r\n    <Task>0<\/Task>\r\n    <Opcode>0<\/Opcode>\r\n    <Keywords>0x0<\/Keywords>\r\n    <TimeCreated SystemTime="2015-09-30T03:41:27.305685200Z" \/>\r\n    <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" \/>\r\n    <Execution ProcessID="7448" ThreadID="14300" ProcessorID="11" KernelTime="0" UserTime="0" \/>\r\n    <Channel \/>\r\n    <Computer \/>\r\n  <\/System>\r\n  <EventData>\r\n    <Data Name="Name">X1<\/Data>\r\n    <Data Name="Number">1<\/Data>\r\n  <\/EventData>\r\n  <RenderingInfo Culture="en-US">\r\n    <Task>SomethingGood<\/Task>\r\n  <\/RenderingInfo>\r\n<\/Event>\r\n<\/pre>\n
Note the EventData<\/code> payload which contains the key\/value pairs that were logged.<\/p>\n
Windows Performance Analyzer<\/a> is smart enough to decode these events as well. It shows data of this type as generic fields with names derived from the event payload:
\n\"WPA<\/a><\/p>\n
Obviously there are pros and cons to manifest-based events and rich data payloads. As Vance points out, performance of rich data is going to be substantially worse when compared to manifest-based events. So don’t go converting all your events to rich data payloads just yet… However, it’s a useful capability to have in your tracing arsenal.<\/p>\n","protected":false},"excerpt":{"rendered":"
Long ago, I wrote about EventSource, the simple and modern ETW-based tracing solution for .NET 4.5+. Much to the diagnosticians’ delight, EventSource continues to evolve in .NET 4.6. Check out Vance Morrison’s post describing the useful new “rich payload data”… <\/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-4801","post","type-post","status-publish","format-standard","hentry","category-diagnostics"],"_links":{"self":[{"href":"https:\/\/writeasync.net\/index.php?rest_route=\/wp\/v2\/posts\/4801","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=4801"}],"version-history":[{"count":0,"href":"https:\/\/writeasync.net\/index.php?rest_route=\/wp\/v2\/posts\/4801\/revisions"}],"wp:attachment":[{"href":"https:\/\/writeasync.net\/index.php?rest_route=%2Fwp%2Fv2%2Fmedia&parent=4801"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/writeasync.net\/index.php?rest_route=%2Fwp%2Fv2%2Fcategories&post=4801"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/writeasync.net\/index.php?rest_route=%2Fwp%2Fv2%2Ftags&post=4801"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}