in src/TraceEvent/Computers/TraceManagedProcess.cs [233:1481]
internal static void SetupCallbacks(TraceEventDispatcher source)
{
bool processGCEvents = true;
bool processJITEvents = true;
//
// Set additional TraceManageProcess properties
//
// These parsers create state and we want to collect that so we put it on our 'parsers' list that we serialize.
var clrRundownParser = new ClrRundownTraceEventParser(source);
// See if the source knows about the CLR Private provider, if it does, then
var clrPrivate = new ClrPrivateTraceEventParser(source);
Dictionary<TraceProcess, TraceLoadedDotNetRuntime> processRuntimes = new Dictionary<TraceProcess, TraceLoadedDotNetRuntime>();
// if any clr event is fired, this process is managed
Action<TraceEvent> createManagedProc = delegate (TraceEvent data)
{
var proc = data.Process(); // this will create an instance, if one does not exist
TraceLoadedDotNetRuntime mang;
if (!processRuntimes.TryGetValue(proc, out mang))
{
// duplicate the TraceProcess and create an instance of TraceManagedProcess
mang = new TraceLoadedDotNetRuntime(proc);
// The TraceProcess infrastructure relies on Kernel Events to properly set key process information (like process name)
// Set process name directly if not set
// This is needed for linux traces or traces on Windows which do not have backProcessing enabled (very rare)
if (string.IsNullOrWhiteSpace(proc.Name))
{
proc.name = data.ProcessName;
}
// fire callback and associate this DotNetRuntime with this process
proc.OnDotNetRuntimeLoaded(mang);
processRuntimes.Add(proc, mang);
}
};
// if applying lifetime, trim loaded managed runtimes when processes are terminated and are out of lifetime
source.AddCallbackOnProcessStop((p) =>
{
// check if we are applying a lifetime model
if (source.DataLifetimeEnabled())
{
// iterate through all processes and unload the managed runtime from processes
// that have exited and are out of lifetime
// immediately removing the runtime for stopped processes is possible, but that
// breaks the contract of how long data is kept with the lifetime
foreach (var process in source.Processes())
{
// continue if the process has not exited yet
if (!process.ExitStatus.HasValue)
{
continue;
}
if (process.EndTimeRelativeMsec < (p.EndTimeRelativeMsec - source.DataLifetimeMsec))
{
// remove this managed runtime instance
process.OnDotNetRuntimeUnloaded();
// remove from the local cache
if (processRuntimes.ContainsKey(process))
{
processRuntimes.Remove(process);
}
}
}
}
});
source.Clr.All += createManagedProc;
clrPrivate.All += createManagedProc;
Func<TraceEvent, TraceLoadedDotNetRuntime> currentManagedProcess = delegate (TraceEvent data)
{
TraceLoadedDotNetRuntime mang;
if (!processRuntimes.TryGetValue(data.Process(), out mang))
{
createManagedProc(data);
mang = processRuntimes[data.Process()];
Debug.Assert(mang != null);
}
return mang;
};
Action<RuntimeInformationTraceData> doAtRuntimeStart = delegate (RuntimeInformationTraceData data)
{
TraceProcess process = data.Process();
TraceLoadedDotNetRuntime mang = currentManagedProcess(data);
// replace the current runtimeversion if it is currently not set, or this version has information including revision (eg. qfe number)
if (mang.runtimeVersion.Major == 0 || data.VMQfeNumber > 0)
{
mang.runtimeVersion = new Version(data.VMMajorVersion, data.VMMinorVersion, data.VMBuildNumber, data.VMQfeNumber);
}
mang.StartupFlags = data.StartupFlags;
// proxy for bitness, given we don't have a traceevent to pass through
process.Is64Bit = (data.RuntimeDllPath.ToLower().Contains("framework64"));
if (process.CommandLine.Length == 0)
{
process.CommandLine = data.CommandLine;
}
};
clrRundownParser.RuntimeStart += doAtRuntimeStart;
source.Clr.RuntimeStart += doAtRuntimeStart;
var symbolParser = new SymbolTraceEventParser(source);
symbolParser.ImageIDFileVersion += delegate (FileVersionTraceData data)
{
TraceProcess process = data.Process();
if (string.Equals(data.OrigFileName, "clr.dll", StringComparison.OrdinalIgnoreCase) || string.Equals(data.OrigFileName, "mscorwks.dll", StringComparison.OrdinalIgnoreCase) || string.Equals(data.OrigFileName, "coreclr.dll", StringComparison.OrdinalIgnoreCase))
{
// this will create a mang instance for this process
TraceLoadedDotNetRuntime mang = currentManagedProcess(data);
Version version;
// replace the current runtimeVersion if there is not good revision information
if ((mang.runtimeVersion.Major == 0 || mang.runtimeVersion.Revision == 0) && Version.TryParse(data.ProductVersion, out version))
{
mang.runtimeVersion = new Version(version.Major, version.Minor, version.Build, version.Revision);
}
if (mang.RuntimeBuiltTime == default(DateTime))
{
mang.RuntimeBuiltTime = data.BuildTime;
}
}
};
symbolParser.ImageID += delegate (ImageIDTraceData data)
{
TraceProcess process = data.Process();
if (string.Equals(data.OriginalFileName, "clr.dll", StringComparison.OrdinalIgnoreCase) || string.Equals(data.OriginalFileName, "mscorwks.dll", StringComparison.OrdinalIgnoreCase) || string.Equals(data.OriginalFileName, "coreclr.dll", StringComparison.OrdinalIgnoreCase))
{
// this will create a mang instance for this process
TraceLoadedDotNetRuntime mang = currentManagedProcess(data);
// capture the CLR build stamp to provide deeper version information (when version information is not present)
if (mang.RuntimeBuiltTime == default(DateTime))
{
mang.RuntimeBuiltTime = data.BuildTime;
}
}
};
//
// GC
//
// Blocking GCs are marked as complete (IsComplete set to true) during RestartEEStop, except for the gen1 GCs that
// happen right before the NGC2 (full blocking GC) in provisional mode. For the exceptional case we set the gen1 as
// complete during the NGC2's GCStart at which point we know that's an NGC2 triggered due to provisional mode.
// Background GCs are marked as complete during GCHeapStats as it does not call RestartEE at the end of a GC.
//
if (processGCEvents)
{
// log at both startup and rundown
var clrRundown = new ClrRundownTraceEventParser(source);
clrRundown.RuntimeStart += doAtRuntimeStart;
source.Clr.RuntimeStart += doAtRuntimeStart;
CircularBuffer<ThreadWorkSpan> RecentThreadSwitches = new CircularBuffer<ThreadWorkSpan>(1000);
source.Kernel.ThreadCSwitch += delegate (CSwitchTraceData data)
{
RecentThreadSwitches.Add(new ThreadWorkSpan(data));
TraceProcess tmpProc = data.Process();
TraceLoadedDotNetRuntime mang;
if (processRuntimes.TryGetValue(tmpProc, out mang))
{
mang.GC.m_stats.ThreadId2Priority[data.NewThreadID] = data.NewThreadPriority;
int heapIndex = mang.GC.m_stats.IsServerGCThread(data.ThreadID);
if ((heapIndex > -1) && !(mang.GC.m_stats.ServerGcHeap2ThreadId.ContainsKey(heapIndex)))
{
mang.GC.m_stats.ServerGcHeap2ThreadId[heapIndex] = data.ThreadID;
}
}
foreach (var pair in processRuntimes)
{
var proc = pair.Key;
mang = pair.Value;
TraceGC _gc = TraceGarbageCollector.GetCurrentGC(mang);
// If we are in the middle of a GC.
if (_gc != null)
{
if ((_gc.Type != GCType.BackgroundGC) && (mang.GC.m_stats.IsServerGCUsed == 1))
{
_gc.AddServerGcThreadSwitch(new ThreadWorkSpan(data));
}
}
}
};
CircularBuffer<ThreadWorkSpan> RecentCpuSamples = new CircularBuffer<ThreadWorkSpan>(1000);
source.Kernel.PerfInfoSample += delegate (SampledProfileTraceData data)
{
RecentCpuSamples.Add(new ThreadWorkSpan(data));
if (source.HasMutableTraceEventStackSource())
{
TraceLoadedDotNetRuntime loadedRuntime = null;
TraceProcess gcProcess = null;
foreach (var pair in processRuntimes)
{
var proc = pair.Key;
var tmpMang = pair.Value;
TraceGC e = TraceGarbageCollector.GetCurrentGC(tmpMang);
// If we are in the middle of a GC.
if (e != null)
{
if ((e.Type != GCType.BackgroundGC) && (tmpMang.GC.m_stats.IsServerGCUsed == 1))
{
e.AddServerGcSample(new ThreadWorkSpan(data));
loadedRuntime = tmpMang;
gcProcess = proc;
}
}
}
if (loadedRuntime != null && gcProcess != null && gcProcess.MutableTraceEventStackSource() != null)
{
var stackSource = gcProcess.MutableTraceEventStackSource();
TraceGC e = TraceGarbageCollector.GetCurrentGC(loadedRuntime);
StackSourceSample sample = new StackSourceSample(stackSource);
sample.Metric = 1;
sample.TimeRelativeMSec = data.TimeStampRelativeMSec;
var nodeName = string.Format("Server GCs #{0} in {1} (PID:{2})", e.Number, gcProcess.Name, gcProcess.ProcessID);
var nodeIndex = stackSource.Interner.FrameIntern(nodeName);
sample.StackIndex = stackSource.Interner.CallStackIntern(nodeIndex, stackSource.GetCallStack(data.CallStackIndex(), data));
stackSource.AddSample(sample);
}
}
TraceProcess tmpProc = data.Process();
TraceLoadedDotNetRuntime mang;
if (processRuntimes.TryGetValue(tmpProc, out mang))
{
int heapIndex = mang.GC.m_stats.IsServerGCThread(data.ThreadID);
if ((heapIndex > -1) && !(mang.GC.m_stats.ServerGcHeap2ThreadId.ContainsKey(heapIndex)))
{
mang.GC.m_stats.ServerGcHeap2ThreadId[heapIndex] = data.ThreadID;
}
var cpuIncrement = tmpProc.SampleIntervalMSec();
TraceGC _gc = TraceGarbageCollector.GetCurrentGC(mang);
// If we are in the middle of a GC.
if (_gc != null)
{
bool isThreadDoingGC = false;
if ((_gc.Type != GCType.BackgroundGC) && (mang.GC.m_stats.IsServerGCUsed == 1))
{
if (heapIndex != -1)
{
_gc.AddServerGCThreadTime(heapIndex, cpuIncrement);
isThreadDoingGC = true;
}
}
else if (data.ThreadID == mang.GC.m_stats.suspendThreadIDGC)
{
_gc.GCCpuMSec += cpuIncrement;
isThreadDoingGC = true;
}
else if (mang.GC.m_stats.IsBGCThread(data.ThreadID))
{
Debug.Assert(mang.GC.m_stats.currentBGC != null);
if (mang.GC.m_stats.currentBGC != null)
{
mang.GC.m_stats.currentBGC.GCCpuMSec += cpuIncrement;
}
isThreadDoingGC = true;
}
if (isThreadDoingGC)
{
mang.GC.m_stats.TotalCpuMSec += cpuIncrement;
}
}
}
};
source.Clr.GCSuspendEEStart += delegate (GCSuspendEETraceData data)
{
var process = data.Process();
var mang = currentManagedProcess(data);
switch (data.Reason)
{
case GCSuspendEEReason.SuspendForGC:
mang.GC.m_stats.suspendThreadIDGC = data.ThreadID;
break;
case GCSuspendEEReason.SuspendForGCPrep:
mang.GC.m_stats.suspendThreadIDBGC = data.ThreadID;
break;
default:
mang.GC.m_stats.suspendThreadIDOther = data.ThreadID;
// There are several other reasons for a suspend but we
// don't care about them
return;
}
mang.GC.m_stats.lastSuspendReason = data.Reason;
mang.GC.m_stats.suspendTimeRelativeMSec = data.TimeStampRelativeMSec;
if ((process.Log != null) && !mang.GC.m_stats.gotThreadInfo)
{
mang.GC.m_stats.gotThreadInfo = true;
Microsoft.Diagnostics.Tracing.Etlx.TraceProcess traceProc = process.Log.Processes.GetProcess(process.ProcessID, data.TimeStampRelativeMSec);
if (traceProc != null)
{
foreach (var procThread in traceProc.Threads)
{
if ((procThread.ThreadInfo != null) && (procThread.ThreadInfo.Contains(".NET Server GC Thread")))
{
mang.GC.m_stats.IsServerGCUsed = 1;
break;
}
}
if (mang.GC.m_stats.IsServerGCUsed == 1)
{
mang.GC.m_stats.HeapCount = 0;
mang.GC.m_stats.serverGCThreads = new Dictionary<int, int>(2);
foreach (var procThread in traceProc.Threads)
{
if ((procThread.ThreadInfo != null) && (procThread.ThreadInfo.StartsWith(".NET Server GC Thread")))
{
mang.GC.m_stats.HeapCount++;
int startIndex = procThread.ThreadInfo.IndexOf('(');
int endIndex = procThread.ThreadInfo.IndexOf(')');
string heapNumString = procThread.ThreadInfo.Substring(startIndex + 1, (endIndex - startIndex - 1));
int heapNum = int.Parse(heapNumString);
mang.GC.m_stats.serverGCThreads[procThread.ThreadID] = heapNum;
mang.GC.m_stats.ServerGcHeap2ThreadId[heapNum] = procThread.ThreadID;
}
}
}
}
}
};
// In 2.0 we didn't have this event.
source.Clr.GCSuspendEEStop += delegate (GCNoUserDataTraceData data)
{
var mang = currentManagedProcess(data);
if(!(data.ThreadID == mang.GC.m_stats.suspendThreadIDBGC || data.ThreadID == mang.GC.m_stats.suspendThreadIDGC))
{
// We only care about SuspendStop events that correspond to GC or PrepForGC reasons
// If we had initiated one of those then we set the corresponding threadid field in
// SuspendStart and we are guaranteed that the matching stop will occur on the same
// thread. Any other SuspendStop must be part of a suspension we aren't tracking.
return;
}
if ((mang.GC.m_stats.suspendThreadIDBGC > 0) && (mang.GC.m_stats.currentBGC != null))
{
mang.GC.m_stats.currentBGC.SuspendDurationMSec += data.TimeStampRelativeMSec - mang.GC.m_stats.suspendTimeRelativeMSec;
}
mang.GC.m_stats.suspendEndTimeRelativeMSec = data.TimeStampRelativeMSec;
};
source.Clr.GCRestartEEStop += delegate (GCNoUserDataTraceData data)
{
var process = data.Process();
var stats = currentManagedProcess(data);
if(data.ThreadID == stats.GC.m_stats.suspendThreadIDOther)
{
stats.GC.m_stats.suspendThreadIDOther = -1;
}
if (!(data.ThreadID == stats.GC.m_stats.suspendThreadIDBGC || data.ThreadID == stats.GC.m_stats.suspendThreadIDGC))
{
// We only care about RestartEE events that correspond to GC or PrepForGC suspensions
// If we had initiated one of those then we set the corresponding threadid field in
// SuspendStart and we are guaranteed that the matching RestartEE will occur on the
// same thread. Any other RestartEE must be part of a suspension we aren't tracking.
return;
}
TraceGC _gc = TraceGarbageCollector.GetCurrentGC(stats);
if (_gc != null)
{
if (_gc.Type == GCType.BackgroundGC)
{
stats.GC.m_stats.AddConcurrentPauseTime(_gc, data.TimeStampRelativeMSec);
}
else
{
if (!_gc.IsConcurrentGC)
{
Debug.Assert(_gc.PauseDurationMSec == 0);
}
Debug.Assert(_gc.PauseStartRelativeMSec != 0);
// In 2.0 Concurrent GC, since we don't know the GC's type we can't tell if it's concurrent
// or not. But we know we don't have nested GCs there so simply check if we have received the
// GCStop event; if we have it means it's a blocking GC; otherwise it's a concurrent GC so
// simply add the pause time to the GC without making the GC complete.
if (_gc.DurationMSec == 0)
{
Debug.Assert(_gc.is20Event);
_gc.IsConcurrentGC = true;
stats.GC.m_stats.AddConcurrentPauseTime(_gc, data.TimeStampRelativeMSec);
}
else
{
_gc.PauseDurationMSec = data.TimeStampRelativeMSec - _gc.PauseStartRelativeMSec;
if (_gc.HeapStats != null)
{
_gc.OnEnd(stats.GC); // set IsComplete = true;
stats.GC.m_stats.lastCompletedGC = _gc;
// fire event
if (stats.GCEnd != null)
{
stats.GCEnd(process, _gc);
}
}
}
}
}
// We don't change between a GC end and the pause resume.
//Debug.Assert(stats.allocTickAtLastGC == stats.allocTickCurrentMB);
// Mark that we are not in suspension anymore.
stats.GC.m_stats.suspendTimeRelativeMSec = -1;
stats.GC.m_stats.suspendThreadIDBGC = -1;
stats.GC.m_stats.suspendThreadIDGC = -1;
};
source.Clr.GCAllocationTick += delegate (GCAllocationTickTraceData data)
{
var stats = currentManagedProcess(data);
stats.GC.m_stats.HasAllocTickEvents = true;
double valueMB = data.GetAllocAmount(ref stats.GC.m_stats.SeenBadAllocTick) / 1000000.0;
if (data.AllocationKind == GCAllocationKind.Small)
{
// Would this do the right thing or is it always 0 for SOH since AllocationAmount
// is an int???
stats.GC.m_stats.allocTickCurrentMB[0] += valueMB;
}
else
{
stats.GC.m_stats.allocTickCurrentMB[1] += valueMB;
}
};
source.Clr.GCStart += delegate (GCStartTraceData data)
{
var process = data.Process();
var stats = currentManagedProcess(data);
// We need to filter the scenario where we get 2 GCStart events for each GC.
if ((stats.GC.m_stats.suspendThreadIDGC > 0 || stats.GC.m_stats.suspendThreadIDOther > 0) &&
!((stats.GC.GCs.Count > 0) && stats.GC.GCs[stats.GC.GCs.Count - 1].Number == data.Count))
{
TraceGC _gc = new TraceGC(stats.GC.m_stats.HeapCount);
Debug.Assert(0 <= data.Depth && data.Depth <= 2);
_gc.Generation = data.Depth;
_gc.Reason = data.Reason;
_gc.Number = data.Count;
_gc.Type = data.Type;
_gc.Index = stats.GC.GCs.Count;
_gc.is20Event = data.IsClassicProvider;
bool isEphemeralGCAtBGCStart = false;
// Detecting the ephemeral GC that happens at the beginning of a BGC.
if (stats.GC.GCs.Count > 0)
{
TraceGC lastGCEvent = stats.GC.GCs[stats.GC.GCs.Count - 1];
if ((lastGCEvent.Type == GCType.BackgroundGC) &&
(!lastGCEvent.IsComplete) &&
(data.Type == GCType.NonConcurrentGC))
{
isEphemeralGCAtBGCStart = true;
}
}
Debug.Assert(stats.GC.m_stats.suspendTimeRelativeMSec != -1);
if (isEphemeralGCAtBGCStart || _gc.Reason == GCReason.PMFullGC)
{
_gc.PauseStartRelativeMSec = data.TimeStampRelativeMSec;
if (_gc.Reason == GCReason.PMFullGC)
{
TraceGC lastGC = TraceGarbageCollector.GetCurrentGC(stats);
if (lastGC != null)
{
lastGC.OnEnd(stats.GC);
}
}
}
else
{
_gc.PauseStartRelativeMSec = stats.GC.m_stats.suspendTimeRelativeMSec;
if (stats.GC.m_stats.suspendEndTimeRelativeMSec == -1)
{
stats.GC.m_stats.suspendEndTimeRelativeMSec = data.TimeStampRelativeMSec;
}
_gc.SuspendDurationMSec = stats.GC.m_stats.suspendEndTimeRelativeMSec - stats.GC.m_stats.suspendTimeRelativeMSec;
}
_gc.StartRelativeMSec = data.TimeStampRelativeMSec;
stats.GC.GCs.Add(_gc);
if (_gc.Type == GCType.BackgroundGC)
{
stats.GC.m_stats.currentBGC = _gc;
// For BGC, we need to add the suspension time so far to its pause so we don't miss including it.
// If there's an ephemeral GC happening before the BGC starts, AddConcurrentPauseTime will not
// add this suspension time to GC pause as that GC would be seen the ephemeral GC, not the BGC.
_gc.PauseDurationMSec = _gc.SuspendDurationMSec;
_gc.ProcessCpuAtLastGC = stats.GC.m_stats.ProcessCpuAtLastGC;
}
if ((_gc.Type != GCType.BackgroundGC) && (stats.GC.m_stats.IsServerGCUsed == 1))
{
stats.GC.m_stats.SetUpServerGcHistory(process.ProcessID, _gc);
foreach (var s in RecentCpuSamples)
{
_gc.AddServerGcSample(s);
}
foreach (var s in RecentThreadSwitches)
{
_gc.AddServerGcThreadSwitch(s);
}
}
// fire event
if (stats.GCStart != null)
{
stats.GCStart(process, _gc);
}
// check if we should apply a lifetime limit to the GC cache
if (source.DataLifetimeEnabled() && data.TimeStampRelativeMSec >= stats.GC.NextRelativeTimeStampMsec)
{
// note the next time that lifetime should be applied, to avoid cleaningup too frequently
stats.GC.NextRelativeTimeStampMsec = data.TimeStampRelativeMSec + (source.DataLifetimeMsec / 2.0);
// trim the GCs to only include those either incomplete or completed after lifetime
stats.GC.m_gcs = stats.GC.m_gcs.Where(gc => !gc.IsComplete || gc.StartRelativeMSec >= (data.TimeStampRelativeMSec - source.DataLifetimeMsec)).ToList();
// rewrite the index for fast lookup
for (int i = 0; i < stats.GC.m_gcs.Count; i++)
{
stats.GC.m_gcs[i].Index = i;
}
}
}
};
source.Clr.GCPinObjectAtGCTime += delegate (PinObjectAtGCTimeTraceData data)
{
var stats = currentManagedProcess(data);
TraceGC _gc = TraceGarbageCollector.GetCurrentGC(stats);
if (_gc != null)
{
if (_gc.PinnedObjects == null)
{
_gc.PinnedObjects = new Dictionary<Address, long>();
}
if (!_gc.PinnedObjects.ContainsKey(data.ObjectID))
{
_gc.PinnedObjects.Add(data.ObjectID, data.ObjectSize);
}
else
{
_gc.duplicatedPinningReports++;
}
}
};
// Some builds have this as a public event, and some have it as a private event.
// All will move to the private event, so we'll remove this code afterwards.
source.Clr.GCPinPlugAtGCTime += delegate (PinPlugAtGCTimeTraceData data)
{
var stats = currentManagedProcess(data);
TraceGC _event = TraceGarbageCollector.GetCurrentGC(stats);
if (_event != null)
{
// ObjectID is supposed to be an IntPtr. But "Address" is defined as UInt64 in
// TraceEvent.
if (_event.PinnedPlugs == null)
{
_event.PinnedPlugs = new List<TraceGC.PinnedPlug>();
}
_event.PinnedPlugs.Add(new TraceGC.PinnedPlug(data.PlugStart, data.PlugEnd));
}
};
source.Clr.GCMarkWithType += delegate (GCMarkWithTypeTraceData data)
{
var stats = currentManagedProcess(data);
stats.GC.m_stats.AddServerGCThreadFromMark(data.ThreadID, data.HeapNum);
TraceGC _gc = TraceGarbageCollector.GetCurrentGC(stats);
if (_gc != null)
{
if (_gc.PerHeapMarkTimes == null)
{
_gc.PerHeapMarkTimes = new Dictionary<int, MarkInfo>();
}
if (!_gc.PerHeapMarkTimes.ContainsKey(data.HeapNum))
{
_gc.PerHeapMarkTimes.Add(data.HeapNum, new MarkInfo());
}
_gc.PerHeapMarkTimes[data.HeapNum].MarkTimes[(int)data.Type] = data.TimeStampRelativeMSec;
_gc.PerHeapMarkTimes[data.HeapNum].MarkPromoted[(int)data.Type] = data.Promoted;
}
};
source.Clr.GCGlobalHeapHistory += delegate (GCGlobalHeapHistoryTraceData data)
{
var stats = currentManagedProcess(data);
GCStats.ProcessGlobalHistory(stats, data);
};
source.Clr.GCPerHeapHistory += delegate (GCPerHeapHistoryTraceData data)
{
var stats = currentManagedProcess(data);
GCStats.ProcessPerHeapHistory(stats, data);
};
source.Clr.GCJoin += delegate (GCJoinTraceData data)
{
var stats = currentManagedProcess(data);
TraceGC _gc = TraceGarbageCollector.GetCurrentGC(stats);
if (_gc != null)
{
_gc.AddGcJoin(data);
}
};
clrPrivate.GCPinPlugAtGCTime += delegate (PinPlugAtGCTimeTraceData data)
{
var stats = currentManagedProcess(data);
TraceGC _gc = TraceGarbageCollector.GetCurrentGC(stats);
if (_gc != null)
{
// ObjectID is supposed to be an IntPtr. But "Address" is defined as UInt64 in
// TraceEvent.
if (_gc.PinnedPlugs == null)
{
_gc.PinnedPlugs = new List<TraceGC.PinnedPlug>();
}
_gc.PinnedPlugs.Add(new TraceGC.PinnedPlug(data.PlugStart, data.PlugEnd));
}
};
// Sometimes at the end of a trace I see only some mark events are included in the trace and they
// are not in order, so need to anticipate that scenario.
clrPrivate.GCMarkStackRoots += delegate (GCMarkTraceData data)
{
var stats = currentManagedProcess(data);
stats.GC.m_stats.AddServerGCThreadFromMark(data.ThreadID, data.HeapNum);
TraceGC _gc = TraceGarbageCollector.GetCurrentGC(stats);
if (_gc != null)
{
if (_gc.PerHeapMarkTimes == null)
{
_gc.PerHeapMarkTimes = new Dictionary<int, MarkInfo>();
}
if (!_gc.PerHeapMarkTimes.ContainsKey(data.HeapNum))
{
_gc.PerHeapMarkTimes.Add(data.HeapNum, new MarkInfo(false));
}
_gc.PerHeapMarkTimes[data.HeapNum].MarkTimes[(int)MarkRootType.MarkStack] = data.TimeStampRelativeMSec;
}
};
clrPrivate.GCMarkFinalizeQueueRoots += delegate (GCMarkTraceData data)
{
var stats = currentManagedProcess(data);
TraceGC _gc = TraceGarbageCollector.GetCurrentGC(stats);
if (_gc != null)
{
if ((_gc.PerHeapMarkTimes != null) && _gc.PerHeapMarkTimes.ContainsKey(data.HeapNum))
{
_gc.PerHeapMarkTimes[data.HeapNum].MarkTimes[(int)MarkRootType.MarkFQ] =
data.TimeStampRelativeMSec;
}
}
};
clrPrivate.GCMarkHandles += delegate (GCMarkTraceData data)
{
var stats = currentManagedProcess(data);
TraceGC _gc = TraceGarbageCollector.GetCurrentGC(stats);
if (_gc != null)
{
if ((_gc.PerHeapMarkTimes != null) && _gc.PerHeapMarkTimes.ContainsKey(data.HeapNum))
{
_gc.PerHeapMarkTimes[data.HeapNum].MarkTimes[(int)MarkRootType.MarkHandles] =
data.TimeStampRelativeMSec;
}
}
};
clrPrivate.GCMarkCards += delegate (GCMarkTraceData data)
{
var stats = currentManagedProcess(data);
TraceGC _gc = TraceGarbageCollector.GetCurrentGC(stats);
if (_gc != null)
{
if ((_gc.PerHeapMarkTimes != null) && _gc.PerHeapMarkTimes.ContainsKey(data.HeapNum))
{
_gc.PerHeapMarkTimes[data.HeapNum].MarkTimes[(int)MarkRootType.MarkOlder] =
data.TimeStampRelativeMSec;
}
}
};
clrPrivate.GCGlobalHeapHistory += delegate (GCGlobalHeapHistoryTraceData data)
{
var stats = currentManagedProcess(data);
GCStats.ProcessGlobalHistory(stats, data);
};
clrPrivate.GCPerHeapHistory += delegate (GCPerHeapHistoryTraceData data)
{
var stats = currentManagedProcess(data);
GCStats.ProcessPerHeapHistory(stats, data);
};
clrPrivate.GCBGCStart += delegate (GCNoUserDataTraceData data)
{
var stats = currentManagedProcess(data);
TraceGC _gc = stats.GC.m_stats.currentBGC;
if (_gc != null)
{
if (stats.GC.m_stats.backgroundGCThreads == null)
{
stats.GC.m_stats.backgroundGCThreads = new Dictionary<int, object>(16);
}
stats.GC.m_stats.backgroundGCThreads[data.ThreadID] = null;
_gc.BGCCurrentPhase = BGCPhase.BGC1stNonConcurrent;
}
};
clrPrivate.GCBGC1stNonCondStop += delegate (GCNoUserDataTraceData data)
{
var stats = currentManagedProcess(data);
TraceGC _gc = stats.GC.m_stats.currentBGC;
if (_gc != null)
{
_gc.BGCCurrentPhase = BGCPhase.BGC1stConcurrent;
}
};
clrPrivate.GCBGC2ndNonConStart += delegate (GCNoUserDataTraceData data)
{
var stats = currentManagedProcess(data);
TraceGC _gc = stats.GC.m_stats.currentBGC;
if (_gc != null)
{
_gc.BGCCurrentPhase = BGCPhase.BGC2ndNonConcurrent;
}
};
clrPrivate.GCBGC2ndConStart += delegate (GCNoUserDataTraceData data)
{
var stats = currentManagedProcess(data);
TraceGC _gc = stats.GC.m_stats.currentBGC;
if (_gc != null)
{
_gc.BGCCurrentPhase = BGCPhase.BGC2ndConcurrent;
}
};
clrPrivate.GCBGCRevisit += delegate (BGCRevisitTraceData data)
{
var stats = currentManagedProcess(data);
TraceGC _gc = TraceGarbageCollector.GetCurrentGC(stats);
if (_gc != null)
{
Debug.Assert(_gc.Type == GCType.BackgroundGC);
int iStateIndex = ((_gc.BGCCurrentPhase == BGCPhase.BGC1stConcurrent) ?
(int)TraceGC.BGCRevisitState.Concurrent :
(int)TraceGC.BGCRevisitState.NonConcurrent);
int iHeapTypeIndex = ((data.IsLarge == 1) ? (int)TraceGC.HeapType.LOH : (int)TraceGC.HeapType.SOH);
_gc.EnsureBGCRevisitInfoAlloc();
(_gc.BGCRevisitInfoArr[iStateIndex][iHeapTypeIndex]).PagesRevisited += data.Pages;
(_gc.BGCRevisitInfoArr[iStateIndex][iHeapTypeIndex]).ObjectsRevisited += data.Objects;
}
};
source.Clr.GCStop += delegate (GCEndTraceData data)
{
var stats = currentManagedProcess(data);
TraceGC _gc = TraceGarbageCollector.GetCurrentGC(stats);
if (_gc != null)
{
_gc.DurationMSec = data.TimeStampRelativeMSec - _gc.StartRelativeMSec;
Debug.Assert(_gc.Number == data.Count);
}
};
source.Clr.GCHeapStats += delegate (GCHeapStatsTraceData data)
{
var process = data.Process();
var stats = currentManagedProcess(data);
TraceGC _gc = TraceGarbageCollector.GetCurrentGC(stats);
var sizeAfterMB = (data.GenerationSize1 + data.GenerationSize2 + data.GenerationSize3 + data.GenerationSize4) / 1000000.0;
if (_gc != null)
{
_gc.HeapStats = new GCHeapStats()
{
Depth = data.Depth
,
FinalizationPromotedCount = data.FinalizationPromotedCount
,
FinalizationPromotedSize = data.FinalizationPromotedSize
,
GCHandleCount = data.GCHandleCount
,
GenerationSize0 = data.GenerationSize0
,
GenerationSize1 = data.GenerationSize1
,
GenerationSize2 = data.GenerationSize2
,
GenerationSize3 = data.GenerationSize3
,
GenerationSize4 = data.GenerationSize4
,
PinnedObjectCount = data.PinnedObjectCount
,
SinkBlockCount = data.SinkBlockCount
,
TotalHeapSize = data.TotalHeapSize
,
TotalPromoted = data.TotalPromoted
,
TotalPromotedSize0 = data.TotalPromotedSize0
,
TotalPromotedSize1 = data.TotalPromotedSize1
,
TotalPromotedSize2 = data.TotalPromotedSize2
,
TotalPromotedSize3 = data.TotalPromotedSize3
,
TotalPromotedSize4 = data.TotalPromotedSize4
};
if (_gc.Type == GCType.BackgroundGC)
{
_gc.ProcessCpuMSec = process.CPUMSec - _gc.ProcessCpuAtLastGC;
_gc.DurationSinceLastRestartMSec = data.TimeStampRelativeMSec - stats.GC.m_stats.lastRestartEndTimeRelativeMSec;
}
else
{
_gc.ProcessCpuMSec = process.CPUMSec - stats.GC.m_stats.ProcessCpuAtLastGC;
_gc.DurationSinceLastRestartMSec = _gc.PauseStartRelativeMSec - stats.GC.m_stats.lastRestartEndTimeRelativeMSec;
}
if (stats.GC.m_stats.HasAllocTickEvents)
{
_gc.HasAllocTickEvents = true;
_gc.AllocedSinceLastGCBasedOnAllocTickMB[0] = stats.GC.m_stats.allocTickCurrentMB[0] - stats.GC.m_stats.allocTickAtLastGC[0];
_gc.AllocedSinceLastGCBasedOnAllocTickMB[1] = stats.GC.m_stats.allocTickCurrentMB[1] - stats.GC.m_stats.allocTickAtLastGC[1];
}
// This is where a background GC ends.
if ((_gc.Type == GCType.BackgroundGC) && (stats.GC.m_stats.currentBGC != null))
{
stats.GC.m_stats.currentBGC.OnEnd(stats.GC); // set IsComplete = true;
stats.GC.m_stats.lastCompletedGC = stats.GC.m_stats.currentBGC;
stats.GC.m_stats.currentBGC = null;
// fire event
if (stats.GCEnd != null)
{
stats.GCEnd(process, stats.GC.m_stats.lastCompletedGC);
}
}
if (_gc.IsConcurrentGC)
{
Debug.Assert(_gc.is20Event);
_gc.OnEnd(stats.GC); // set IsComplete = true
stats.GC.m_stats.lastCompletedGC = _gc;
// fire event
if (stats.GCEnd != null)
{
stats.GCEnd(process, _gc);
}
}
}
stats.GC.m_stats.ProcessCpuAtLastGC = process.CPUMSec;
stats.GC.m_stats.allocTickAtLastGC[0] = stats.GC.m_stats.allocTickCurrentMB[0];
stats.GC.m_stats.allocTickAtLastGC[1] = stats.GC.m_stats.allocTickCurrentMB[1];
stats.GC.m_stats.lastRestartEndTimeRelativeMSec = data.TimeStampRelativeMSec;
};
source.Clr.GCTerminateConcurrentThread += delegate (GCTerminateConcurrentThreadTraceData data)
{
var stats = currentManagedProcess(data);
if (stats.GC.m_stats.backgroundGCThreads != null)
{
stats.GC.m_stats.backgroundGCThreads = null;
}
};
clrPrivate.GCBGCAllocWaitStart += delegate (BGCAllocWaitTraceData data)
{
var stats = currentManagedProcess(data);
Debug.Assert(stats.GC.m_stats.currentBGC != null);
if (stats.GC.m_stats.currentBGC != null)
{
stats.GC.m_stats.currentBGC.AddLOHWaitThreadInfo(data.ThreadID, data.TimeStampRelativeMSec, data.Reason, true);
}
};
clrPrivate.GCBGCAllocWaitStop += delegate (BGCAllocWaitTraceData data)
{
var stats = currentManagedProcess(data);
TraceGC _gc = GCStats.GetLastBGC(stats);
if (_gc != null)
{
_gc.AddLOHWaitThreadInfo(data.ThreadID, data.TimeStampRelativeMSec, data.Reason, false);
}
};
clrPrivate.GCJoin += delegate (GCJoinTraceData data)
{
var stats = currentManagedProcess(data);
TraceGC _gc = TraceGarbageCollector.GetCurrentGC(stats);
if (_gc != null)
{
_gc.AddGcJoin(data);
}
};
source.Clr.GCFinalizeObject += data =>
{
var stats = currentManagedProcess(data);
long finalizationCount;
stats.GC.m_stats.FinalizedObjects[data.TypeName] =
stats.GC.m_stats.FinalizedObjects.TryGetValue(data.TypeName, out finalizationCount) ?
finalizationCount + 1 :
1;
};
}
//
// Jit
//
bool backgroundJITEventsOn = false;
if (processJITEvents)
{
source.Clr.MethodJittingStarted += delegate (MethodJittingStartedTraceData data)
{
var process = data.Process();
var stats = currentManagedProcess(data);
var _method = stats.JIT.m_stats.LogJitStart(stats, data, JITStats.GetMethodName(data), data.MethodILSize, data.ModuleID, data.MethodID);
// fire event
if (stats.JITMethodStart != null)
{
stats.JITMethodStart(process, _method);
}
// check if we should apply a lifetime limit to the method cache
if (source.DataLifetimeEnabled() && data.TimeStampRelativeMSec >= stats.JIT.NextRelativeTimeStampMsec)
{
// note the next time that lifetime should be applied, to avoid cleaningup too frequently
stats.JIT.NextRelativeTimeStampMsec = data.TimeStampRelativeMSec + (source.DataLifetimeMsec / 2.0);
// trim the methods to only include those that were JITT'd after the lifetime timestamp
stats.JIT.m_methods = stats.JIT.m_methods.Where(meth => meth.StartTimeMSec >= (data.TimeStampRelativeMSec - source.DataLifetimeMsec)).ToList();
}
};
ClrRundownTraceEventParser parser = new ClrRundownTraceEventParser(source);
Action<ModuleLoadUnloadTraceData> moduleLoadAction = delegate (ModuleLoadUnloadTraceData data)
{
var stats = currentManagedProcess(data);
stats.JIT.m_stats.moduleNamesFromID[data.ModuleID] = data.ModuleILPath;
// fix-up methods that have been previously marked with incomplete module information
foreach (var _method in stats.JIT.Methods.Where(m => m.ModuleID == data.ModuleID))
{
if (string.IsNullOrWhiteSpace(_method.ModuleILPath))
{
_method.ModuleILPath = data.ModuleILPath;
}
}
};
source.Clr.LoaderModuleLoad += moduleLoadAction;
source.Clr.LoaderModuleUnload += moduleLoadAction;
parser.LoaderModuleDCStop += moduleLoadAction;
source.Clr.MethodLoadVerbose += delegate (MethodLoadUnloadVerboseTraceData data)
{
if (data.IsJitted)
{
var process = data.Process();
var stats = currentManagedProcess(data);
bool createdNewMethod;
var _method = JITStats.MethodComplete(stats, data, JITStats.GetMethodName(data), (int)data.ReJITID, out createdNewMethod);
// fire event - but only once
if (createdNewMethod && stats.JITMethodStart != null)
{
stats.JITMethodStart(process, _method);
}
if (stats.JITMethodEnd != null && _method.Completed == 1)
{
stats.JITMethodEnd(process, _method);
}
}
};
source.Clr.MethodLoad += delegate (MethodLoadUnloadTraceData data)
{
if (data.IsJitted)
{
var process = data.Process();
var stats = currentManagedProcess(data);
bool createdNewMethod;
var _method = JITStats.MethodComplete(stats, data, "", 0, out createdNewMethod);
// fire event - but only once
if (createdNewMethod && stats.JITMethodStart != null)
{
stats.JITMethodStart(process, _method);
}
if (stats.JITMethodEnd != null && _method.Completed == 1)
{
stats.JITMethodEnd(process, _method);
}
}
};
source.Clr.RuntimeStart += delegate (RuntimeInformationTraceData data)
{
var process = data.Process();
var stats = currentManagedProcess(data);
stats.JIT.m_stats.IsClr4 = true;
if (process.CommandLine == null)
{
process.CommandLine = data.CommandLine;
}
};
source.Clr.MethodMemoryAllocatedForJitCode += delegate(MethodJitMemoryAllocatedForCodeTraceData data)
{
var process = data.Process();
var stats = currentManagedProcess(data);
JITStats.LogJitMethodAllocation(stats, data);
};
clrPrivate.ClrMulticoreJitCommon += delegate (MulticoreJitPrivateTraceData data)
{
var process = data.Process();
var stats = currentManagedProcess(data);
if (!backgroundJITEventsOn)
{
stats.JIT.m_stats.LastBlockedReason = null;
}
backgroundJITEventsOn = true;
if (process.Name == null)
{
process.name = data.ProcessName;
}
if (stats.JIT.m_stats.BackgroundJitThread == 0 && (data.String1 == "GROUPWAIT" || data.String1 == "JITTHREAD"))
{
stats.JIT.m_stats.BackgroundJitThread = data.ThreadID;
}
if (data.String1 == "ADDMODULEDEPENDENCY")
{
// Add the blocked module to the list of recorded modules.
if (!stats.JIT.m_stats.RecordedModules.Contains(data.String2))
{
stats.JIT.m_stats.RecordedModules.Add(data.String2);
}
}
if (data.String1 == "BLOCKINGMODULE")
{
// Set the blocking module.
stats.JIT.m_stats.LastBlockedReason = data.String2;
// Add the blocked module to the list of recorded modules.
if (!stats.JIT.m_stats.RecordedModules.Contains(data.String2))
{
stats.JIT.m_stats.RecordedModules.Add(data.String2);
}
}
if (data.String1 == "GROUPWAIT" && data.String2 == "Leave")
{
if (data.Int2 == 0)
{
// Clear the last blocked reason, since we're no longer blocked on modules.
stats.JIT.m_stats.LastBlockedReason = null;
}
else
{
// If GroupWait returns and Int2 != 0, this means that not all of the module loads were satisifed
// and we have aborted playback.
stats.JIT.m_stats.LastBlockedReason = "Playback Aborted";
stats.JIT.m_stats.playbackAborted = true;
}
}
if (data.String1 == "ABORTPROFILE")
{
stats.JIT.m_stats.BackgroundJitAbortedAtMSec = data.TimeStampRelativeMSec;
}
};
clrPrivate.ClrMulticoreJitMethodCodeReturned += delegate (MulticoreJitMethodCodeReturnedPrivateTraceData data)
{
backgroundJITEventsOn = true;
var stats = currentManagedProcess(data);
// Get the associated JIT information
TraceJittedMethod backgroundJitInfo = null;
JITStats.MethodKey methodKey = new JITStats.MethodKey(data.ModuleID, data.MethodID);
if (stats.JIT.m_stats.backgroundJitEvents.TryGetValue(methodKey, out backgroundJitInfo))
{
if (backgroundJitInfo.ThreadID == stats.JIT.m_stats.BackgroundJitThread)
{
backgroundJitInfo.ForegroundMethodRequestTimeMSec = data.TimeStampRelativeMSec;
stats.JIT.m_stats.backgroundJitEvents.Remove(methodKey);
}
}
};
clrPrivate.BindingLoaderPhaseStart += delegate (BindingTraceData data)
{
// Keep track if the last assembly loaded before Background JIT aborts.
var stats = currentManagedProcess(data);
if (stats.JIT.m_stats.BackgroundJitAbortedAtMSec == 0)
{
stats.JIT.m_stats.LastAssemblyLoadNameBeforeAbort = data.AssemblyName;
stats.JIT.m_stats.LastAssemblyLoadBeforeAbortMSec = data.TimeStampRelativeMSec;
}
};
clrPrivate.BindingLoaderDeliverEventsPhaseStop += delegate (BindingTraceData data)
{
// If we hit this events, we assume assembly load is successful.
var stats = currentManagedProcess(data);
if (stats.JIT.m_stats.BackgroundJitAbortedAtMSec != 0)
{
if (stats.JIT.m_stats.LastAssemblyLoadNameBeforeAbort == data.AssemblyName)
{
stats.JIT.m_stats.LastAssemblyLoadBeforeAbortSuccessful = true;
}
}
};
clrPrivate.StartupPrestubWorkerStart += delegate (StartupTraceData data)
{
// TODO, we want to know if we have background JIT events. Today we don't have an event
// that says 'events are enabled, its just no one used the events' We want this.
// Today we turn on all CLRPrivate events to turn on listening to Backgroung JITTing and
// we use the fact that the PrestubWorker evnets are on as a proxy.
backgroundJITEventsOn = true;
};
source.Clr.AppDomainResourceManagementThreadTerminated += delegate (ThreadTerminatedOrTransitionTraceData data)
{
var stats = currentManagedProcess(data);
if (!stats.JIT.m_stats.playbackAborted)
{
stats.JIT.m_stats.LastBlockedReason = "Playback Completed";
}
};
source.Clr.MethodInliningSucceeded += delegate (MethodJitInliningSucceededTraceData data)
{
var stats = currentManagedProcess(data);
stats.JIT.m_stats.InliningSuccesses.Add(new InliningSuccessResult
{
MethodBeingCompiled = data.MethodBeingCompiledNamespace + "." + data.MethodBeingCompiledName,
Inliner = data.InlinerNamespace + "." + data.InlinerName,
Inlinee = data.InlineeNamespace + "." + data.InlineeName
});
};
source.Clr.MethodInliningFailedAnsi += delegate (MethodJitInliningFailedAnsiTraceData data)
{
var stats = currentManagedProcess(data);
stats.JIT.m_stats.InliningFailures.Add(new InliningFailureResult
{
MethodBeingCompiled = data.MethodBeingCompiledNamespace + "." + data.MethodBeingCompiledName,
Inliner = data.InlinerNamespace + "." + data.InlinerName,
Inlinee = data.InlineeNamespace + "." + data.InlineeName,
Reason = data.FailReason
});
};
source.Clr.MethodInliningFailed += delegate (MethodJitInliningFailedTraceData data)
{
var stats = currentManagedProcess(data);
stats.JIT.m_stats.InliningFailures.Add(new InliningFailureResult
{
MethodBeingCompiled = data.MethodBeingCompiledNamespace + "." + data.MethodBeingCompiledName,
Inliner = data.InlinerNamespace + "." + data.InlinerName,
Inlinee = data.InlineeNamespace + "." + data.InlineeName,
Reason = data.FailReason
});
};
}
Action<TieredCompilationSettingsTraceData> onTieredCompilationSettings = data =>
{
var stats = currentManagedProcess(data);
stats.IsTieredCompilationEnabled = true;
};
source.Clr.TieredCompilationSettings += onTieredCompilationSettings;
clrRundownParser.TieredCompilationRundownSettingsDCStart += onTieredCompilationSettings;
}