TimeStamp difference when consuming the same event with 2 different consumers

[guidovaroli]

Hi

I have 2 different monitoring application that receive the same event and seems that the event has a different time stamp.

In the callback of both the monitoring application I have formatted the timestamp as in the following line:

Console.WriteLine($"Event timestamp: {data.TimeStamp.ToFileTime()} --- {data.TimeStamp.ToString("hh:mm:ss.fff")} --- {data.TimeStamp.ToString("mm:ss.fffffff")} --+-- {data.TimeStampQPC} ### {data.EventName}");

The string formatted with a precision of 1 millisecond is often (but not always) equal in the 2 the consumers, all other formatted date are different.
Is there something wrong?
There is an other way to get a more precise timestamp information ?
It’s a limitation of Microsoft.Diagnostics.Tracing.TraceEvent ?
It’s a bug ?

I’m using Framework 4.7.2 and I had verified the behavior using both Microsoft.Diagnostics.Tracing.TraceEvent 2.034 and 2.0.38 packages.

A repro code with 2 simple console application developed starting from Microsoft.Diagnostics.Tracing.TraceEvent.Samples is here
TestTraceEventTimeStamp.zip

Step to Repro

1. Compile both application
2. Launch 2 instances of the consumer application
3. Call once the producer application.
4. Finally compare the output on Console

[vancem]

It would be helpful if you can cut and paste in some of the console output from the two runs that you got, just so we have e clear idea of exactly what is different. It would also be useful to tell us the version of the OS you are running on.

I can tell you something about how ETW/TraceEvent works which may help set expectations about time.

When a event is logged, a fast tick count call the QPC time), is what is logged in the event (this is what TimeStampQPC returns). Both the start time and the duration of a QPC tick can vary from machine to machine, so we really DISCOURAGE the use of this API. However this is 'the source of truth' in that it is what is actually logged in the file.

Thus I would expect two monitors of the SAME event to have exactly the same TimeStampQPC. This should always be true.

TraceEvent then has logic to convert TimeStampQPC to either TimeStampRelativeMSec, or a DateTime. In theory the tick interval is known and should be the same in the two monitors, but the start time for the tick count is NOT known, and basically we try to calculate it (which is why two differnet monitors might be off by a little bit).

I would EXPECT that this skew should be small (hopefully 1msec or less). It is not clear from what you describe above whether this true or not.

Finally all of this is only true for reasonably current versions of the OS (e.g. Windows 10). If you are running on older OSes, things may be a bit different. Thus the version of your OS is important to tell us.

[guidovaroli]

Our test are running on a single machine with Windows 10 Enterprise 64 bit.

some output on console with the format described above are

Consumer 1
Event timestamp: 131985856748559146 --- 11:47:54.855 --- 47:54.8559146 --+-- 712230068436 ### MyEvent
Event timestamp: 131985856748933307 --- 11:47:54.893 --- 47:54.8933307 --+-- 712230152476 ### MyEvent
Event timestamp: 131985856749332614 --- 11:47:54.933 --- 47:54.9332614 --+-- 712230242164 ### MyEvent
Event timestamp: 131985856749724295 --- 11:47:54.972 --- 47:54.9724295 --+-- 712230330139 ### MyEvent
Event timestamp: 131985856749728079 --- 11:47:54.972 --- 47:54.9728079 --+-- 712230330989 ### MyStopEvent
Event timestamp: 131985856749729566 --- 11:47:54.972 --- 47:54.9729566 --+-- 712230331323 ### ManifestData

Consumer 2
Event timestamp: 131985856748560048 --- 11:47:54.856 --- 47:54.8560048 --+-- 712230068438 ### MyEvent
Event timestamp: 131985856748934214 --- 11:47:54.893 --- 47:54.8934214 --+-- 712230152479 ### MyEvent
Event timestamp: 131985856749333525 --- 11:47:54.933 --- 47:54.9333525 --+-- 712230242168 ### MyEvent
Event timestamp: 131985856749725197 --- 11:47:54.972 --- 47:54.9725197 --+-- 712230330141 ### MyEvent
Event timestamp: 131985856749728977 --- 11:47:54.972 --- 47:54.9728977 --+-- 712230330990 ### MyStopEvent
Event timestamp: 131985856749730473 --- 11:47:54.973 --- 47:54.9730473 --+-- 712230331326 ### ManifestData

[vancem]

Thanks for the data @guidovaroli, it is helpful.

Let's start with the last number (the TimeStampQPC). I am a bit surprised that for a particular event this is not identical, since my (previous) understanding was that this timestamp was set once before the event was dispatched to individual ETW sessions, but clearly this is not true. It must be being set when the event is sent to each session that has subscribed to it, and thus each session can have a slightly different timestamp.

This is somewhat unfortunate because I don't know of any universal 'identity' that can universally and unabiguously determine that two events in two differnet traces are in fact the same event (which is probably what you are after). You would like the timestamp to be this 'id' but it is not because it is a property of the session and not the event.

Anyway this particular issue is an artifact of how Event Tracing for Windows (ETW) works. TraceEvent is simply exposing it. You may wish to ask your question at https://techcommunity.microsoft.com/t5/Ask-The-Performance-Team/bg-p/AskPerf since they can research the details of what is going on inside the operating system, however it does seem to simply be a limitation based on how ETW works.