Timestamp skew in TraceEvent?

Apr 9, 2013 at 12:33 AM
I’m using the version of TraceEvent in a real-time consumer project. In my event handling code, I attempt to use the TimeStamp property of the received event object (for example: FileIoReadWriteTraceData) as the DateTime that the event occurred. However, I sometimes get events with TimeStamp values many seconds ahead of the system clock. It happens enough that I’ve gone to substituting receive time as event time in my project, but that has obvious drawbacks. I’d love to figure out what I’m doing wrong. Has anyone seen this? Is there some trick to getting event time from TraceEvent?

Many thanks.
Apr 12, 2013 at 4:45 PM
This is likely a bug in TraceEvent. I have a fix, but I have not tested it. You can get the new TraceEvent.dll from http://sdrv.ms/12Ub95y to try it out
Apr 15, 2013 at 7:52 PM
Looks resolved, I am not seeing any more inconsistencies with the system clock. Thanks! A couple of follow up questions:

1.) Will you be making the source available for this sometime soon? (i'd like to implement pruning of the fileIDToName table, it can grow large in a long running real-time scenario like mine)
2.) Looks like TDHDynamicTraceEventParser was removed in this version? I was using that to parse non-kernel events, what should I now be using instead?

Thanks again
Apr 16, 2013 at 6:23 PM
I will be updating the source but exactly when I don't exactly know at the moment. I will see what I can do, but no promises

In the mean time you can apply the fix without too much grief. The basic problem is that TraceEvent uses the QueryPerformanceCounter (QPC) counter in the events. This has to be converted to normal DateTIme 100ns ticks (QPCTimeToFileTime). To do this properly, you need a time where you know the QPC tick number and the corresponding DateTime tick. I was assuming that the session start time and the first event timestamp were the same (they are for files), but that does not work for real-time providers.

The fix is in the 'ETWTraceEventSource constructor. There is already a call to DateTime.Now to get the FileTime, you aslo need to call Stopwatch.GetTImesamp() to get the QPC time right after this. Then set the 'sessionStartTimeQPC' variable to that timestamp if a real time session is being opened (if you leave it 0, it will be set on the first event).

TDHDynamicTraceEventParser has been renamed to RegisteredTraceEventParser. However if you apply the fix yourself, you won't care (for now).