/// <summary>
/// This routine is only useful/valid for real-time sessions.
///
/// TraceEvent.TimeStamp internally is stored using a high resolution clock called the Query Performance Counter (QPC).
/// This clock is INDEPENDENT of the system clock used by DateTime. These two clocks are synchronized to within 2 msec at
/// session startup but they can drift from there (typically 2msec / min == 3 seconds / day). Thus if you have long
/// running real time session it becomes problematic to compare the timestamps with those in another session or something
/// timestamped with the system clock. SynchronizeClock will synchronize the TraceEvent.Timestamp clock with the system
/// clock again. If you do this right before you start another session, then the two sessions will be within 2 msec of
/// each other, and their timestamps will correlate. Doing it periodically (e.g. hourly), will keep things reasonably close.
///
/// TODO: we can achieve perfect synchronization by exposing the QPC tick sync point so we could read the sync point
/// from one session and set that exact sync point for another session.
/// </summary>
public void SynchronizeClock()
{
if (!IsRealTime)
{
throw new InvalidOperationException("SynchronizeClock is only for Real-Time Sessions");
}
DateTime utcNow = DateTime.UtcNow;
_syncTimeQPC = QPCTime.GetUTCTimeAsQPC(utcNow);
_syncTimeUTC = utcNow;
}
// Process is called after all desired subscriptions have been registered.
/// <summary>
/// Processes all the events in the data source, issuing callbacks that were subscribed to. See
/// #Introduction for more
/// </summary>
/// <returns>false If StopProcesing was called</returns>
// [SecuritySafeCritical]
public override bool Process()
{
stopProcessing = false;
if (processTraceCalled)
{
Reset();
}
processTraceCalled = true;
if (fileNames != null)
{
foreach (var fileName in fileNames)
{
if (handles != null)
{
Debug.Assert(handles.Length == 1);
if (handles[0] != TraceEventNativeMethods.INVALID_HANDLE_VALUE)
{
TraceEventNativeMethods.CloseTrace(handles[0]);
}
}
Initialize(fileName, TraceEventSourceType.FileOnly);
if (!ProcessOneFile())
{
OnCompleted();
Debug.Assert(sessionEndTimeQPC != long.MaxValue); // Not a real time session
return(false);
}
}
OnCompleted();
Debug.Assert(sessionEndTimeQPC != long.MaxValue); // Not a real time session
return(true);
}
else
{
var ret = ProcessOneFile();
// If the session is real time, set he sessionEndTime (since the session is stopping).
if (sessionEndTimeQPC == long.MaxValue)
{
sessionEndTimeQPC = QPCTime.GetUTCTimeAsQPC(DateTime.UtcNow);
}
OnCompleted();
return(ret);
}
}
private void Initialize(string fileOrSessionName, TraceEventSourceType type)
{
// Allocate the LOGFILE and structures and arrays that hold them
// Figure out how many log files we have
if (type == TraceEventSourceType.MergeAll)
{
List <string> allLogFiles = GetMergeAllLogFiles(fileOrSessionName);
logFiles = new TraceEventNativeMethods.EVENT_TRACE_LOGFILEW[allLogFiles.Count];
for (int i = 0; i < allLogFiles.Count; i++)
{
logFiles[i].LogFileName = allLogFiles[i];
}
}
else
{
logFiles = new TraceEventNativeMethods.EVENT_TRACE_LOGFILEW[1];
if (type == TraceEventSourceType.FileOnly)
{
logFiles[0].LogFileName = fileOrSessionName;
}
else
{
Debug.Assert(type == TraceEventSourceType.Session);
logFiles[0].LoggerName = fileOrSessionName;
logFiles[0].LogFileMode |= TraceEventNativeMethods.EVENT_TRACE_REAL_TIME_MODE;
IsRealTime = true;
}
}
handles = new ulong[logFiles.Length];
// Fill out the first log file information (we will clone it later if we have multiple files).
logFiles[0].BufferCallback = this.TraceEventBufferCallback;
handles[0] = TraceEventNativeMethods.INVALID_HANDLE_VALUE;
useClassicETW = !OperatingSystemVersion.AtLeast(OperatingSystemVersion.Vista);
if (useClassicETW)
{
IntPtr mem = Marshal.AllocHGlobal(sizeof(TraceEventNativeMethods.EVENT_RECORD));
TraceEventNativeMethods.ZeroMemory(mem, sizeof(TraceEventNativeMethods.EVENT_RECORD));
convertedHeader = (TraceEventNativeMethods.EVENT_RECORD *)mem;
logFiles[0].EventCallback = RawDispatchClassic;
}
else
{
logFiles[0].LogFileMode |= TraceEventNativeMethods.PROCESS_TRACE_MODE_EVENT_RECORD;
logFiles[0].EventCallback = RawDispatch;
}
// We want the raw timestamp because it is needed to match up stacks with the event they go with.
logFiles[0].LogFileMode |= TraceEventNativeMethods.PROCESS_TRACE_MODE_RAW_TIMESTAMP;
// Copy the information to any additional log files
for (int i = 1; i < logFiles.Length; i++)
{
logFiles[i].BufferCallback = logFiles[0].BufferCallback;
logFiles[i].EventCallback = logFiles[0].EventCallback;
logFiles[i].LogFileMode = logFiles[0].LogFileMode;
handles[i] = handles[0];
}
DateTime minSessionStartTimeUTC = DateTime.MaxValue;
DateTime maxSessionEndTimeUTC = DateTime.MinValue + new TimeSpan(1 * 365, 0, 0, 0); // TO avoid roundoff error when converting to QPC add a year.
// Open all the traces
for (int i = 0; i < handles.Length; i++)
{
handles[i] = TraceEventNativeMethods.OpenTrace(ref logFiles[i]);
if (handles[i] == TraceEventNativeMethods.INVALID_HANDLE_VALUE)
{
Marshal.ThrowExceptionForHR(TraceEventNativeMethods.GetHRForLastWin32Error());
}
// Start time is minimum of all start times
DateTime logFileStartTimeUTC = SafeFromFileTimeUtc(logFiles[i].LogfileHeader.StartTime);
DateTime logFileEndTimeUTC = SafeFromFileTimeUtc(logFiles[i].LogfileHeader.EndTime);
if (logFileStartTimeUTC < minSessionStartTimeUTC)
{
minSessionStartTimeUTC = logFileStartTimeUTC;
}
// End time is maximum of all start times
if (logFileEndTimeUTC > maxSessionEndTimeUTC)
{
maxSessionEndTimeUTC = logFileEndTimeUTC;
}
// TODO do we even need log pointer size anymore?
// We take the max pointer size.
if ((int)logFiles[i].LogfileHeader.PointerSize > pointerSize)
{
pointerSize = (int)logFiles[i].LogfileHeader.PointerSize;
}
}
_QPCFreq = logFiles[0].LogfileHeader.PerfFreq;
if (_QPCFreq == 0)
{
_QPCFreq = Stopwatch.Frequency;
}
// Real time providers don't set this to something useful
if ((logFiles[0].LogFileMode & TraceEventNativeMethods.EVENT_TRACE_REAL_TIME_MODE) != 0)
{
DateTime nowUTC = DateTime.UtcNow;
long nowQPC = QPCTime.GetUTCTimeAsQPC(nowUTC);
_syncTimeQPC = nowQPC;
_syncTimeUTC = nowUTC;
sessionStartTimeQPC = nowQPC - _QPCFreq / 10; // Subtract 1/10 sec to keep now and nowQPC in sync.
sessionEndTimeQPC = long.MaxValue; // Represents infinity.
Debug.Assert(SessionStartTime < SessionEndTime);
}
else
{
_syncTimeUTC = minSessionStartTimeUTC;
// UTCDateTimeToQPC is actually going to give the wrong value for these because we have
// not set _syncTimeQPC, but will be adjusted when we see the event Header and know _syncTypeQPC.
sessionStartTimeQPC = this.UTCDateTimeToQPC(minSessionStartTimeUTC);
sessionEndTimeQPC = this.UTCDateTimeToQPC(maxSessionEndTimeUTC);
}
Debug.Assert(_QPCFreq != 0);
if (pointerSize == 0) // Real time does not set this (grrr).
{
pointerSize = sizeof(IntPtr);
Debug.Assert((logFiles[0].LogFileMode & TraceEventNativeMethods.EVENT_TRACE_REAL_TIME_MODE) != 0);
}
Debug.Assert(pointerSize == 4 || pointerSize == 8);
cpuSpeedMHz = (int)logFiles[0].LogfileHeader.CpuSpeedInMHz;
numberOfProcessors = (int)logFiles[0].LogfileHeader.NumberOfProcessors;
// We ask for raw timestamps, but the log file may have used system time as its raw timestamp.
// SystemTime is like a QPC time that happens 10M times a second (100ns).
// ReservedFlags is actually the ClockType 0 = Raw, 1 = QPC, 2 = SystemTimne 3 = CpuTick (we don't support)
if (logFiles[0].LogfileHeader.ReservedFlags == 2) // If ClockType == EVENT_TRACE_CLOCK_SYSTEMTIME
{
_QPCFreq = 10000000;
}
Debug.Assert(_QPCFreq != 0);
int ver = (int)logFiles[0].LogfileHeader.Version;
osVersion = new Version((byte)ver, (byte)(ver >> 8));
// Logic for looking up process names
processNameForID = new Dictionary <int, string>();
var kernelParser = new KernelTraceEventParser(this, KernelTraceEventParser.ParserTrackingOptions.None);
kernelParser.ProcessStartGroup += delegate(ProcessTraceData data)
{
// Get just the file name without the extension. Can't use the 'Path' class because
// it tests to make certain it does not have illegal chars etc. Since KernelImageFileName
// is not a true user mode path, we can get failures.
string path = data.KernelImageFileName;
int startIdx = path.LastIndexOf('\\');
if (0 <= startIdx)
{
startIdx++;
}
else
{
startIdx = 0;
}
int endIdx = path.LastIndexOf('.');
if (endIdx <= startIdx)
{
endIdx = path.Length;
}
processNameForID[data.ProcessID] = path.Substring(startIdx, endIdx - startIdx);
};
kernelParser.ProcessEndGroup += delegate(ProcessTraceData data)
{
processNameForID.Remove(data.ProcessID);
};
kernelParser.EventTraceHeader += delegate(EventTraceHeaderTraceData data)
{
if (_syncTimeQPC == 0)
{ // In merged files there can be more of these, we only set the QPC time on the first one
// We were using a 'start location' of 0, but we want it to be the timestamp of this events, so we add this to our
// existing QPC values.
_syncTimeQPC = data.TimeStampQPC;
sessionStartTimeQPC += data.TimeStampQPC;
sessionEndTimeQPC += data.TimeStampQPC;
}
};
}