{"id":104536,"date":"2020-12-10T07:00:00","date_gmt":"2020-12-10T15:00:00","guid":{"rendered":"https:\/\/devblogs.microsoft.com\/oldnewthing\/?p=104536"},"modified":"2020-12-10T07:11:46","modified_gmt":"2020-12-10T15:11:46","slug":"20201210-00","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/oldnewthing\/20201210-00\/?p=104536","title":{"rendered":"Parsing ETL traces yourself, part 2: The EventLogReader"},"content":{"rendered":"

The CLR System.Diagnostics.Eventing.Reader<\/code> namespace contains classes for parsing classic ETL events. You create an Event\u00adLog\u00adReader<\/code> object, giving it the path to the ETL file, and then call Read\u00adEvent<\/code> to extract the next event from the event log.<\/p>\n

Here’s a simple program that parses an event log looking for start and stop events from a specific provider and event ID, and calculating the net time:<\/p>\n

using System;\r\nusing System.Diagnostics.Eventing.Reader;\r\n\r\nclass Program\r\n{\r\n  static readonly Guid MyProviderId = new Guid(\"...\");\r\n  const int beginId = 3141;\r\n  const int endId = 3142;\r\n\r\n  static public void Main(string[] args)\r\n  {\r\n    var filename = args[0];\r\n    using (var log = new EventLogReader(filename, PathType.FilePath)) {\r\n      string currentScenario = string.Empty;\r\n      DateTime beginTime = DateTime.MinValue;\r\n      TimeSpan totalDuration = TimeSpan.Zero;\r\n\r\n      EventLogRecord data;\r\n      while ((data = (EventLogRecord)log.ReadEvent()) != null) {\r\n        if (data.ProviderId == MyProviderId) {\r\n          if (data.Id == beginId) {\r\n            if (beginTime != DateTime.MinValue) {\r\n              throw new Exception(\"Overlapping events not supported\");\r\n            }\r\n            currentScenario = (string)data.Properties[0].Value;\r\n            beginTime = data.TimeCreated.Value;\r\n          }\r\n          else if (data.Id == endId) {\r\n            if (beginTime != DateTime.MinValue) {\r\n              if (currentScenario != (string)data.Properties[0].Value) {\r\n                throw new Exception(\"Unsupported event sequence\");\r\n              }\r\n              var duration = data.TimeCreated.Value - beginTime;\r\n              System.Console.WriteLine($\"{currentScenario},{duration}\");\r\n              totalDuration += duration;\r\n              beginTime = DateTime.MinValue;\r\n            }\r\n          }\r\n        }\r\n      }\r\n      System.Console.WriteLine($\"Total,{totalDuration}\");\r\n    }\r\n  }\r\n}\r\n<\/pre>\n
We start by opening an Event\u00adLog\u00adReader<\/code> on our event log file. The Event\u00adLog\u00adReader<\/code> can connect to an active event log, but we’re using it here for offline analysis.<\/p>\n
The currentScenario<\/code> variable remembers the name of the current scenario being tracked.<\/p>\n
The beginTime<\/code> variable remembers when the current begin\/end pair began. It is MinValue<\/code> if nothing is being tracked.<\/p>\n
The totalDuration<\/code> variable accumulates the total time consumed by our begin\/end pairs so far.<\/p>\n
We pull events from the event log by calling Read\u00adEvent<\/code>. We check if the event was generated by our provider. We could have checked the ProviderName<\/code> property, but I’m going for ProviderId<\/code> because it avoid case-sensitivity questions, ensures uniqueness in the face of somebody else coincidentally choosing the same name, and appeals to me because I like to think comparing two Guid<\/code> objects is faster than comparing two strings.<\/p>\n
Once we verify that the event belongs to our provider, we check the event IDs. If it’s our begin<\/i> event, then we remember the event timestamp and the scenario name, which is a string provided as the first (and only) event payload.<\/p>\n
There are methods and properties on the Event\u00adLog\u00adRecord<\/code> that let you learn about the type of payload attached to the event, but I’m just hard-coding specific knowledge of the way my provider generates the events. This is common when doing event processing. After all, you generated the event. You should know what’s in it.<\/p>\n
I add a little defensive check that there are not two begin<\/i> events in a row. This is a hole in my processing: If there are two begin<\/i> events in a row, then they should both be tracked, and the corresponding end<\/i> events should be matched up against the begin<\/i> events. This is a quick-and-dirty program, so I just complain if overlapping events are discovered, so I know that I need to go back and add support for that.\u00b9<\/p>\n
If we get an end<\/i> event, we check if there is active sequence, and if so, verify that the end<\/i> event matches the begin<\/i>.\u00b9 Assuming everything passes, we print the elapsed time for that sequence, and accumulate it for final reporting.<\/p>\n
Note that we do not complain if we see an end<\/i> event without a begin<\/i>. This can happen if the trace began while a sequence was already in progress.<\/p>\n
When all the events are done, we print the cumulative time.<\/p>\n
The Event\u00adLog\u00adReader<\/code> is a wrapper around the native functions in the winevt.h<\/code> header file, like Evt\u00adOpen\u00adSession<\/code> and Evt\u00adNext<\/code>. It’s handy, but only if you are interested in class for reading classic manifested events. It doesn’t understand the ad-hoc events generated by  TraceLogging<\/a>. The native header file for decoding TraceLogging events is tdh.h<\/code>, but the Event\u00adLog\u00adReader<\/code> doesn’t use it.<\/p>\n
Oh no, what are we going to do?<\/p>\n
Relief arrives next time.<\/p>\n
\u00b9 It’s important to check for these cases, even if you don’t support them, because you may encounter a trace that includes overlapping events, and if you didn’t check for that case, the program would generate incorrect results and cause you to draw the wrong conclusions. Bad data is worse than no data.<\/p>\n","protected":false},"excerpt":{"rendered":"
For true programmatic processing of classic ETL events.<\/p>\n","protected":false},"author":1069,"featured_media":111744,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[1],"tags":[25],"class_list":["post-104536","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-oldnewthing","tag-code"],"acf":[],"blog_post_summary":"
For true programmatic processing of classic ETL events.<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/104536","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/users\/1069"}],"replies":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/comments?post=104536"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/104536\/revisions"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/media\/111744"}],"wp:attachment":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/media?parent=104536"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/categories?post=104536"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/tags?post=104536"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}