public GCEvent(GCProcess owningProcess) { Parent = owningProcess; heapCount = owningProcess.heapCount; if (heapCount > 1) { GCCpuServerGCThreads = new float[heapCount]; } pinnedObjectSizes = -1; totalPinnedPlugSize = -1; totalUserPinnedPlugSize = -1; duplicatedPinningReports = 0; }
internal static IDictionary<int, GCProcess> Collect( TraceEventSource source, float sampleIntervalMSec, IDictionary<int, GCProcess> perProc = null, MutableTraceEventStackSource stackSource = null, Predicate<TraceEvent> filterFunc = null) { if (perProc == null) { perProc = new Dictionary<int, GCProcess>(); } source.Kernel.AddCallbackForEvents(delegate (ProcessCtrTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } var stats = perProc.GetOrCreate(data.ProcessID); stats.PeakVirtualMB = ((double)data.PeakVirtualSize) / 1000000.0; stats.PeakWorkingSetMB = ((double)data.PeakWorkingSetSize) / 1000000.0; }); Action<RuntimeInformationTraceData> doAtRuntimeStart = delegate (RuntimeInformationTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } var stats = perProc.GetOrCreate(data.ProcessID); stats.RuntimeVersion = "V " + data.VMMajorVersion.ToString() + "." + data.VMMinorVersion + "." + data.VMBuildNumber + "." + data.VMQfeNumber; stats.StartupFlags = data.StartupFlags; stats.Bitness = (data.RuntimeDllPath.ToLower().Contains("framework64") ? 64 : 32); if (stats.CommandLine == null) stats.CommandLine = data.CommandLine; }; // log at both startup and rundown //var clrRundown = new ClrRundownTraceEventParser(source); //clrRundown.RuntimeStart += doAtRuntimeStart; source.Clr.AddCallbackForEvent("Runtime/Start", doAtRuntimeStart); Action<ProcessTraceData> processStartCallback = data => { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } var stats = perProc.GetOrCreate(data.ProcessID); if (!string.IsNullOrEmpty(data.KernelImageFileName)) { // When we just have an EventSource (eg, the source was created by // ETWTraceEventSource), we don't necessarily have the process names // decoded - it all depends on whether we have seen a ProcessStartGroup // event or not. When the trace was taken after the process started we // know we didn't see such an event. string name = GetImageName(data.KernelImageFileName); // Strictly speaking, this is not really fixing it 'cause // it doesn't handle when a process with the same name starts // with the same pid. The chance of that happening is really small. if (stats.isDead == true) { stats = new GCProcess(); stats.Init(data); perProc[data.ProcessID] = stats; } } var commandLine = data.CommandLine; if (!string.IsNullOrEmpty(commandLine)) stats.CommandLine = commandLine; }; source.Kernel.AddCallbackForEvent("Process/Start", processStartCallback); source.Kernel.AddCallbackForEvent("Process/DCStart", processStartCallback); Action<ProcessTraceData> processEndCallback = delegate (ProcessTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } var stats = perProc.GetOrCreate(data.ProcessID); if (string.IsNullOrEmpty(stats.ProcessName)) { stats.ProcessName = GetImageName(data.KernelImageFileName); } if (data.OpcodeName == "Stop") { stats.isDead = true; } }; source.Kernel.AddCallbackForEvent("Process/Stop", processEndCallback); source.Kernel.AddCallbackForEvent("Process/DCStop", processEndCallback); #if (!CAP) CircularBuffer<ThreadWorkSpan> RecentThreadSwitches = new CircularBuffer<ThreadWorkSpan>(10000); source.Kernel.AddCallbackForEvent("Thread/CSwitch", delegate (CSwitchTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } RecentThreadSwitches.Add(new ThreadWorkSpan(data)); GCProcess stats; if (perProc.TryGetValue(data.ProcessID, out stats)) { stats.ThreadId2Priority[data.NewThreadID] = data.NewThreadPriority; if (stats.IsServerGCThread(data.ThreadID) > -1) { stats.ServerGcHeap2ThreadId[data.ProcessorNumber] = data.ThreadID; } } foreach (var gcProcess in perProc.Values) { GCEvent _event = gcProcess.GetCurrentGC(); // If we are in the middle of a GC. if (_event != null) { if ((_event.Type != GCType.BackgroundGC) && (gcProcess.isServerGCUsed == 1)) { _event.AddServerGcThreadSwitch(new ThreadWorkSpan(data)); } } } }); CircularBuffer<ThreadWorkSpan> RecentCpuSamples = new CircularBuffer<ThreadWorkSpan>(1000); StackSourceSample sample = new StackSourceSample(stackSource); source.Kernel.AddCallbackForEvent("PerfInfo/Sample", delegate (SampledProfileTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } RecentCpuSamples.Add(new ThreadWorkSpan(data)); GCProcess processWithGc = null; foreach (var gcProcess in perProc.Values) { GCEvent e = gcProcess.GetCurrentGC(); // If we are in the middle of a GC. if (e != null) { if ((e.Type != GCType.BackgroundGC) && (gcProcess.isServerGCUsed == 1)) { e.AddServerGcSample(new ThreadWorkSpan(data)); processWithGc = gcProcess; } } } if (stackSource != null && processWithGc != null) { GCEvent e = processWithGc.GetCurrentGC(); sample.Metric = 1; sample.TimeRelativeMSec = data.TimeStampRelativeMSec; var nodeName = string.Format("Server GCs #{0} in {1} (PID:{2})", e.GCNumber, processWithGc.ProcessName, processWithGc.ProcessID); var nodeIndex = stackSource.Interner.FrameIntern(nodeName); sample.StackIndex = stackSource.Interner.CallStackIntern(nodeIndex, stackSource.GetCallStack(data.CallStackIndex(), data)); stackSource.AddSample(sample); } GCProcess stats; if (perProc.TryGetValue(data.ProcessID, out stats)) { if (stats.IsServerGCThread(data.ThreadID) > -1) { stats.ServerGcHeap2ThreadId[data.ProcessorNumber] = data.ThreadID; } var cpuIncrement = sampleIntervalMSec; stats.ProcessCpuMSec += cpuIncrement; GCEvent _event = stats.GetCurrentGC(); // If we are in the middle of a GC. if (_event != null) { bool isThreadDoingGC = false; if ((_event.Type != GCType.BackgroundGC) && (stats.isServerGCUsed == 1)) { int heapIndex = stats.IsServerGCThread(data.ThreadID); if (heapIndex != -1) { _event.AddServerGCThreadTime(heapIndex, cpuIncrement); isThreadDoingGC = true; } } else if (data.ThreadID == stats.suspendThreadIDGC) { _event.GCCpuMSec += cpuIncrement; isThreadDoingGC = true; } else if (stats.IsBGCThread(data.ThreadID)) { Debug.Assert(stats.currentBGC != null); if (stats.currentBGC != null) stats.currentBGC.GCCpuMSec += cpuIncrement; isThreadDoingGC = true; } if (isThreadDoingGC) { stats.GCCpuMSec += cpuIncrement; } } } }); #endif source.Clr.AddCallbackForEvent("GC/SuspendEEStart", delegate (GCSuspendEETraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } var stats = perProc.GetOrCreate(data.ProcessID); switch (data.Reason) { case GCSuspendEEReason.SuspendForGC: stats.suspendThreadIDGC = data.ThreadID; break; case GCSuspendEEReason.SuspendForGCPrep: stats.suspendThreadIDBGC = data.ThreadID; break; default: stats.suspendThreadIDOther = data.ThreadID; break; } stats.suspendTimeRelativeMSec = data.TimeStampRelativeMSec; }); // In 2.0 we didn't have this event. source.Clr.AddCallbackForEvent("GC/SuspendEEStop", delegate (GCNoUserDataTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); if ((stats.suspendThreadIDBGC > 0) && (stats.currentBGC != null)) { stats.currentBGC._SuspendDurationMSec += data.TimeStampRelativeMSec - stats.suspendTimeRelativeMSec; } stats.suspendEndTimeRelativeMSec = data.TimeStampRelativeMSec; }); source.Clr.AddCallbackForEvent("GC/RestartEEStop", delegate (GCNoUserDataTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); GCEvent _event = stats.GetCurrentGC(); if (_event != null) { if (_event.Type == GCType.BackgroundGC) { stats.AddConcurrentPauseTime(_event, data.TimeStampRelativeMSec); } else { Debug.Assert(_event.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 (_event.GCDurationMSec == 0) { Debug.Assert(_event.is20Event); _event.isConcurrentGC = true; stats.AddConcurrentPauseTime(_event, data.TimeStampRelativeMSec); } else { _event.PauseDurationMSec = data.TimeStampRelativeMSec - _event.PauseStartRelativeMSec; if (_event.HeapStats != null) { _event.isComplete = true; stats.lastCompletedGC = _event; } } } } // 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.suspendTimeRelativeMSec = -1; stats.suspendThreadIDOther = -1; stats.suspendThreadIDBGC = -1; stats.suspendThreadIDGC = -1; }); source.Clr.AddCallbackForEvent("GC/AllocationTick", delegate (GCAllocationTickTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); if (stats.HasAllocTickEvents == false) { stats.HasAllocTickEvents = true; } double valueMB = data.GetAllocAmount(ref 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.allocTickCurrentMB[0] += valueMB; } else { stats.allocTickCurrentMB[1] += valueMB; } }); source.Clr.AddCallbackForEvent("GC/Start", delegate (GCStartTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); // We need to filter the scenario where we get 2 GCStart events for each GC. if ((stats.suspendThreadIDGC > 0) && !((stats.events.Count > 0) && stats.events[stats.events.Count - 1].GCNumber == data.Count)) { GCEvent _event = new GCEvent(stats); Debug.Assert(0 <= data.Depth && data.Depth <= 2); // _event.GCGeneration = data.Depth; Old style events only have this in the GCStop event. _event.Reason = data.Reason; _event.GCNumber = data.Count; _event.Type = data.Type; _event.Index = stats.events.Count; _event.is20Event = data.IsClassicProvider; bool isEphemeralGCAtBGCStart = false; // Detecting the ephemeral GC that happens at the beginning of a BGC. if (stats.events.Count > 0) { GCEvent lastGCEvent = stats.events[stats.events.Count - 1]; if ((lastGCEvent.Type == GCType.BackgroundGC) && (!lastGCEvent.isComplete) && (data.Type == GCType.NonConcurrentGC)) { isEphemeralGCAtBGCStart = true; } } Debug.Assert(stats.suspendTimeRelativeMSec != -1); if (isEphemeralGCAtBGCStart) { _event.PauseStartRelativeMSec = data.TimeStampRelativeMSec; } else { _event.PauseStartRelativeMSec = stats.suspendTimeRelativeMSec; if (stats.suspendEndTimeRelativeMSec == -1) { stats.suspendEndTimeRelativeMSec = data.TimeStampRelativeMSec; } _event._SuspendDurationMSec = stats.suspendEndTimeRelativeMSec - stats.suspendTimeRelativeMSec; } _event.GCStartRelativeMSec = data.TimeStampRelativeMSec; stats.events.Add(_event); if (_event.Type == GCType.BackgroundGC) { stats.currentBGC = _event; _event.ProcessCpuAtLastGC = stats.ProcessCpuAtLastGC; } #if (!CAP) if ((_event.Type != GCType.BackgroundGC) && (stats.isServerGCUsed == 1)) { _event.SetUpServerGcHistory(); foreach (var s in RecentCpuSamples) _event.AddServerGcSample(s); foreach (var s in RecentThreadSwitches) _event.AddServerGcThreadSwitch(s); } #endif } }); source.Clr.AddCallbackForEvent("GC/PinObjectAtGCTime", delegate (PinObjectAtGCTimeTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); GCEvent _event = stats.GetCurrentGC(); if (_event != null) { if (!_event.PinnedObjects.ContainsKey(data.ObjectID)) { _event.PinnedObjects.Add(data.ObjectID, data.ObjectSize); } else { _event.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.AddCallbackForEvent("GC/PinPlugAtGCTime", delegate (PinPlugAtGCTimeTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); GCEvent _event = stats.GetCurrentGC(); if (_event != null) { // ObjectID is supposed to be an IntPtr. But "Address" is defined as UInt64 in // TraceEvent. _event.PinnedPlugs.Add(new GCEvent.PinnedPlug(data.PlugStart, data.PlugEnd)); } }); source.Clr.AddCallbackForEvent("GC/Mark", delegate (GCMarkWithTypeTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); stats.AddServerGCThreadFromMark(data.ThreadID, data.HeapNum); GCEvent _event = stats.GetCurrentGC(); if (_event != null) { if (_event.PerHeapMarkTimes == null) { _event.PerHeapMarkTimes = new Dictionary<int, GCEvent.MarkInfo>(); } if (!_event.PerHeapMarkTimes.ContainsKey(data.HeapNum)) { _event.PerHeapMarkTimes.Add(data.HeapNum, new GCEvent.MarkInfo()); } _event.PerHeapMarkTimes[data.HeapNum].MarkTimes[(int)data.Type] = data.TimeStampRelativeMSec; _event.PerHeapMarkTimes[data.HeapNum].MarkPromoted[(int)data.Type] = data.Promoted; } }); source.Clr.AddCallbackForEvent("GC/GlobalHeapHistory", delegate (GCGlobalHeapHistoryTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); stats.ProcessGlobalHistory(data); }); source.Clr.AddCallbackForEvent("GC/PerHeapHistory", delegate (GCPerHeapHistoryTraceData3 data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); stats.ProcessPerHeapHistory(data); }); #if HAS_PRIVATE_GC_EVENTS // See if the source knows about the CLR Private provider, if it does, then var gcPrivate = new ClrPrivateTraceEventParser(source); gcPrivate.GCPinPlugAtGCTime += delegate (PinPlugAtGCTimeTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; GCEvent _event = stats.GetCurrentGC(); if (_event != null) { // ObjectID is supposed to be an IntPtr. But "Address" is defined as UInt64 in // TraceEvent. _event.PinnedPlugs.Add(new GCEvent.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. gcPrivate.GCMarkStackRoots += delegate (GCMarkTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; stats.AddServerGCThreadFromMark(data.ThreadID, data.HeapNum); GCEvent _event = stats.GetCurrentGC(); if (_event != null) { if (_event.PerHeapMarkTimes == null) { _event.PerHeapMarkTimes = new Dictionary<int, GCEvent.MarkInfo>(); } if (!_event.PerHeapMarkTimes.ContainsKey(data.HeapNum)) { _event.PerHeapMarkTimes.Add(data.HeapNum, new GCEvent.MarkInfo(false)); } _event.PerHeapMarkTimes[data.HeapNum].MarkTimes[(int)MarkRootType.MarkStack] = data.TimeStampRelativeMSec; } }; gcPrivate.GCMarkFinalizeQueueRoots += delegate (GCMarkTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; GCEvent _event = stats.GetCurrentGC(); if (_event != null) { if ((_event.PerHeapMarkTimes != null) && _event.PerHeapMarkTimes.ContainsKey(data.HeapNum)) { _event.PerHeapMarkTimes[data.HeapNum].MarkTimes[(int)MarkRootType.MarkFQ] = data.TimeStampRelativeMSec; } } }; gcPrivate.GCMarkHandles += delegate (GCMarkTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; GCEvent _event = stats.GetCurrentGC(); if (_event != null) { if ((_event.PerHeapMarkTimes != null) && _event.PerHeapMarkTimes.ContainsKey(data.HeapNum)) { _event.PerHeapMarkTimes[data.HeapNum].MarkTimes[(int)MarkRootType.MarkHandles] = data.TimeStampRelativeMSec; } } }; gcPrivate.GCMarkCards += delegate (GCMarkTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; GCEvent _event = stats.GetCurrentGC(); if (_event != null) { if ((_event.PerHeapMarkTimes != null) && _event.PerHeapMarkTimes.ContainsKey(data.HeapNum)) { _event.PerHeapMarkTimes[data.HeapNum].MarkTimes[(int)MarkRootType.MarkOlder] = data.TimeStampRelativeMSec; } } }; gcPrivate.GCGlobalHeapHistory += delegate (GCGlobalHeapHistoryTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; stats.ProcessGlobalHistory(data); }; gcPrivate.GCPerHeapHistory += delegate (GCPerHeapHistoryTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; stats.ProcessPerHeapHistory(data); }; gcPrivate.GCBGCStart += delegate (GCNoUserDataTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; if (stats.currentBGC != null) { if (stats.backgroundGCThreads == null) { stats.backgroundGCThreads = new Dictionary<int, object>(16); } stats.backgroundGCThreads[data.ThreadID] = null; } }; #endif source.Clr.AddCallbackForEvent("GC/Stop", delegate (GCEndTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); GCEvent _event = stats.GetCurrentGC(); if (_event != null) { _event.GCDurationMSec = data.TimeStampRelativeMSec - _event.GCStartRelativeMSec; _event.GCGeneration = data.Depth; _event.GCEnd(); } }); source.Clr.AddCallbackForEvent("GC/HeapStats", delegate (GCHeapStatsTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); GCEvent _event = stats.GetCurrentGC(); var sizeAfterMB = (data.GenerationSize1 + data.GenerationSize2 + data.GenerationSize3) / 1000000.0; if (_event != null) { _event.HeapStats = (GCHeapStatsTraceData)data.Clone(); if (_event.Type == GCType.BackgroundGC) { _event.ProcessCpuMSec = stats.ProcessCpuMSec - _event.ProcessCpuAtLastGC; _event.DurationSinceLastRestartMSec = data.TimeStampRelativeMSec - stats.lastRestartEndTimeRelativeMSec; } else { _event.ProcessCpuMSec = stats.ProcessCpuMSec - stats.ProcessCpuAtLastGC; _event.DurationSinceLastRestartMSec = _event.PauseStartRelativeMSec - stats.lastRestartEndTimeRelativeMSec; } if (stats.HasAllocTickEvents) { _event.HasAllocTickEvents = true; _event.AllocedSinceLastGCBasedOnAllocTickMB[0] = stats.allocTickCurrentMB[0] - stats.allocTickAtLastGC[0]; _event.AllocedSinceLastGCBasedOnAllocTickMB[1] = stats.allocTickCurrentMB[1] - stats.allocTickAtLastGC[1]; } // This is where a background GC ends. if ((_event.Type == GCType.BackgroundGC) && (stats.currentBGC != null)) { stats.currentBGC.isComplete = true; stats.lastCompletedGC = stats.currentBGC; stats.currentBGC = null; } if (_event.isConcurrentGC) { Debug.Assert(_event.is20Event); _event.isComplete = true; stats.lastCompletedGC = _event; } } stats.ProcessCpuAtLastGC = stats.ProcessCpuMSec; stats.allocTickAtLastGC[0] = stats.allocTickCurrentMB[0]; stats.allocTickAtLastGC[1] = stats.allocTickCurrentMB[1]; stats.lastRestartEndTimeRelativeMSec = data.TimeStampRelativeMSec; }); source.Clr.AddCallbackForEvent("GC/TerminateConcurrentThread", delegate (GCTerminateConcurrentThreadTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); if (stats.backgroundGCThreads != null) { stats.backgroundGCThreads = null; } }); #if HAS_PRIVATE_GC_EVENTS gcPrivate.GCBGCAllocWaitStart += delegate (BGCAllocWaitTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; Debug.Assert(stats.currentBGC != null); if (stats.currentBGC != null) { stats.currentBGC.AddLOHWaitThreadInfo(data.ThreadID, data.TimeStampRelativeMSec, data.Reason, true); } }; gcPrivate.GCBGCAllocWaitStop += delegate (BGCAllocWaitTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; GCEvent _event = stats.GetLastBGC(); if (_event != null) { _event.AddLOHWaitThreadInfo(data.ThreadID, data.TimeStampRelativeMSec, data.Reason, false); } }; gcPrivate.GCJoin += delegate (GCJoinTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess gcProcess = perProc[data]; GCEvent _event = gcProcess.GetCurrentGC(); if (_event != null) { _event.AddGcJoin(data); } }; source.Process(); #endif return perProc; }