Timestamp handling in ETW #60
Description
We have observed a somewhat weird behaviour:
- We started a trace collector real-time session using the Microsoft.Diagnostics.Tracing.TraceEvent NuGet package.
- We started logging events using the EventSourceProxy NuGet package.
- We get the events and the TraceEvent.TimeStamp property contains the current system time.
- Now we keep everything running and change the system time, e.g. we add 5 minutes.
- We still get the events but THEY CONTAIN THE UNCHANGED TIME which differs from the current system time.
This is a problem because in production the trace collector runs over a longer period of time. The system time gets synchronized regularly and is therefore more or less correct but the logged events start to differ from server to server and also to values written to the db using DateTime.Now. This of course makes analyzing the log entries a pain - the difference can be up to several seconds!
We assume that there is some logic involved that handles a "session time" to ensure that events are always in chronological order. However, we think that this causes more problems that an occasional overlapping of events would and we'd like to always have the current system time logged.
It is unclear to us who is actually setting the timestamp value - is it the EventSourceProxy component, the ETW framework or the trace collector component? All we can see is that we don't manually set it using the EventSourceProxy component and we get it in the TraceEvent objects that are delivered to the events in the trace collector component, so it must happen somewhere in between. Any hints as to who is doing this and how we can change the behavior would be appreciated.