public static int Main(string[] args)
{
// Additional assemblies will be seen, but these are ones we must see
string[] AssembliesExpected = new string[] {
"rundown", // this assembly
"System.Runtime",
"Microsoft.Diagnostics.Tracing.TraceEvent",
"System.Diagnostics.Tracing",
"System.Private.CoreLib"
};
using (var netPerfFile = NetPerfFile.Create(args))
{
Console.WriteLine("\tStart: Enable tracing.");
TraceControl.EnableDefault(netPerfFile.Path);
Console.WriteLine("\tEnd: Enable tracing.\n");
// Since all we care about is rundown, there is nothing to do there
Console.WriteLine("\tStart: Disable tracing.");
TraceControl.Disable();
Console.WriteLine("\tEnd: Disable tracing.\n");
Console.WriteLine("\tStart: Process the trace file.");
var assembliesLoaded = new HashSet <string>();
int nonMatchingEventCount = 0;
using (var trace = TraceEventDispatcher.GetDispatcherFromFileName(netPerfFile.Path))
{
var rundownParser = new ClrRundownTraceEventParser(trace);
rundownParser.LoaderAssemblyDCStop += delegate(AssemblyLoadUnloadTraceData data)
{
var nameIndex = Array.IndexOf(data.PayloadNames, ("FullyQualifiedAssemblyName"));
if (nameIndex >= 0)
{
// Add the assembly name to a set to verify later
assembliesLoaded.Add(((string)data.PayloadValue(nameIndex)).Split(',')[0]);
}
else
{
nonMatchingEventCount++;
}
};
trace.Process();
}
Console.WriteLine("\tEnd: Processing events from file.\n");
foreach (var name in AssembliesExpected)
{
Assert.True($"Assembly {name} in loaded assemblies", assembliesLoaded.Contains(name));
}
Assert.Equal(nameof(nonMatchingEventCount), nonMatchingEventCount, 0);
}
return(100);
}
private void Run()
{
m_session = new TraceEventSession("AppDomains-" + m_processId);
m_parser = new ClrRundownTraceEventParser(m_session.Source);
m_session.EnableProvider("Microsoft-Windows-DotNETRuntimeRundown", TraceEventLevel.Verbose,
(ulong)(ClrRundownTraceEventParser.Keywords.StartEnumeration | ClrRundownTraceEventParser.Keywords.Loader),
new TraceEventProviderOptions
{
ProcessIDFilter = new List <int> {
m_processId
}
});
RegisterEvents();
m_elapsed.Start();
StartTimeoutHandler();
// This is blocking, and will be stopped by "m_session.Stop()"
m_session.Source.Process();
}
public void Streaming(string eventPipeFileName)
{
// Initialize
PrepareTestData();
string eventPipeFilePath = Path.Combine(UnZippedDataDir, eventPipeFileName);
Output.WriteLine(string.Format("Processing the file {0}", Path.GetFullPath(eventPipeFilePath)));
var eventStatistics = new SortedDictionary <string, EventRecord>(StringComparer.Ordinal);
long curStreamPosition = 0;
using (MockStreamingOnlyStream s = new MockStreamingOnlyStream(new FileStream(eventPipeFilePath, FileMode.Open, FileAccess.Read, FileShare.Read)))
{
using (var traceSource = new EventPipeEventSource(s))
{
Action <TraceEvent> handler = delegate(TraceEvent data)
{
long newStreamPosition = s.TestOnlyPosition;
// Empirically these files have event blocks of no more than 103K bytes each
// The streaming code should never need to read ahead beyond the end of the current
// block to read the events
Assert.InRange(newStreamPosition, curStreamPosition, curStreamPosition + 103_000);
curStreamPosition = newStreamPosition;
string eventName = data.ProviderName + "/" + data.EventName;
// For whatever reason the parse filtering below produces a couple extra events
// that TraceLog managed to filter out:
// Microsoft-Windows-DotNETRuntime/Method, 2,
// Microsoft-Windows-DotNETRuntimeRundown/Method, 26103, ...
// I haven't had an oportunity to investigate and its probably not a big
// deal so just hacking around it for the moment
if (eventName == "Microsoft-Windows-DotNETRuntimeRundown/Method" ||
eventName == "Microsoft-Windows-DotNETRuntime/Method")
{
return;
}
if (eventStatistics.ContainsKey(eventName))
{
eventStatistics[eventName].TotalCount++;
}
else
{
eventStatistics[eventName] = new EventRecord()
{
TotalCount = 1,
FirstSeriazliedSample = new String(data.ToString().Replace("\n", "\\n").Replace("\r", "\\r").Take(1000).ToArray())
};
}
};
// this is somewhat arbitrary looking set of parser event callbacks empirically
// produces the same set of events as TraceLog.Events.GetSource().AllEvents so
// that the baseline files can be reused from the Basic test
var rundown = new ClrRundownTraceEventParser(traceSource);
rundown.LoaderAppDomainDCStop += handler;
rundown.LoaderAssemblyDCStop += handler;
rundown.LoaderDomainModuleDCStop += handler;
rundown.LoaderModuleDCStop += handler;
rundown.MethodDCStopComplete += handler;
rundown.MethodDCStopInit += handler;
var sampleProfiler = new SampleProfilerTraceEventParser(traceSource);
sampleProfiler.All += handler;
var privateClr = new ClrPrivateTraceEventParser(traceSource);
privateClr.All += handler;
traceSource.Clr.All += handler;
traceSource.Clr.MethodILToNativeMap -= handler;
traceSource.Dynamic.All += handler;
// Process
traceSource.Process();
}
}
// Validate
ValidateEventStatistics(eventStatistics, eventPipeFileName);
}
/// <summary>
/// Sets up the callbacks needed to do a heap dump (work need before processing the events()
/// </summary>
internal void SetupCallbacks(MemoryGraph memoryGraph, TraceEventDispatcher source, string processNameOrId = null, double startTimeRelativeMSec = 0)
{
m_graph = memoryGraph;
m_typeID2TypeIndex = new Dictionary <Address, NodeTypeIndex>(1000);
m_moduleID2Name = new Dictionary <Address, string>(16);
m_arrayNametoIndex = new Dictionary <string, NodeTypeIndex>(32);
m_objectToRCW = new Dictionary <Address, RCWInfo>(100);
m_nodeBlocks = new Queue <GCBulkNodeTraceData>();
m_edgeBlocks = new Queue <GCBulkEdgeTraceData>();
m_typeBlocks = new Queue <GCBulkTypeTraceData>();
m_staticVarBlocks = new Queue <GCBulkRootStaticVarTraceData>();
m_ccwBlocks = new Queue <GCBulkRootCCWTraceData>();
m_typeIntern = new Dictionary <string, NodeTypeIndex>();
m_root = new MemoryNodeBuilder(m_graph, "[.NET Roots]");
m_typeStorage = m_graph.AllocTypeNodeStorage();
// We also keep track of the loaded modules in the target process just in case it is a project N scenario.
// (Not play for play but it is small).
m_modules = new Dictionary <Address, Module>(32);
m_ignoreEvents = true;
m_ignoreUntilMSec = startTimeRelativeMSec;
m_processId = 0; // defaults to a wildcard.
if (processNameOrId != null)
{
if (!int.TryParse(processNameOrId, out m_processId))
{
m_processId = -1; // an illegal value.
m_processName = processNameOrId;
}
}
// Remember the module IDs too.
Action <ModuleLoadUnloadTraceData> moduleCallback = delegate(ModuleLoadUnloadTraceData data)
{
if (data.ProcessID != m_processId)
{
return;
}
if (!m_moduleID2Name.ContainsKey((Address)data.ModuleID))
{
m_moduleID2Name[(Address)data.ModuleID] = data.ModuleILPath;
}
m_log.WriteLine("Found Module {0} ID 0x{1:x}", data.ModuleILFileName, (Address)data.ModuleID);
};
source.Clr.AddCallbackForEvents <ModuleLoadUnloadTraceData>(moduleCallback); // Get module events for clr provider
// TODO should not be needed if we use CAPTURE_STATE when collecting.
var clrRundown = new ClrRundownTraceEventParser(source);
clrRundown.AddCallbackForEvents <ModuleLoadUnloadTraceData>(moduleCallback); // and its rundown provider.
DbgIDRSDSTraceData lastDbgData = null;
var symbolParser = new SymbolTraceEventParser(source);
symbolParser.ImageIDDbgID_RSDS += delegate(DbgIDRSDSTraceData data)
{
if (data.ProcessID != m_processId)
{
return;
}
lastDbgData = (DbgIDRSDSTraceData)data.Clone();
};
source.Kernel.ImageGroup += delegate(ImageLoadTraceData data)
{
if (m_processId == 0)
{
return;
}
if (data.ProcessID != m_processId)
{
return;
}
Module module = new Module(data.ImageBase);
module.Path = data.FileName;
module.Size = data.ImageSize;
module.BuildTime = data.BuildTime;
if (lastDbgData != null && data.TimeStampRelativeMSec == lastDbgData.TimeStampRelativeMSec)
{
module.PdbGuid = lastDbgData.GuidSig;
module.PdbAge = lastDbgData.Age;
module.PdbName = lastDbgData.PdbFileName;
}
m_modules[module.ImageBase] = module;
};
// TODO this does not work in the circular case
source.Kernel.ProcessGroup += delegate(ProcessTraceData data)
{
if (0 <= m_processId || m_processName == null)
{
return;
}
if (string.Compare(data.ProcessName, processNameOrId, StringComparison.OrdinalIgnoreCase) == 0)
{
m_log.WriteLine("Found process id {0} for process Name {1}", processNameOrId, data.ProcessName);
m_processId = data.ProcessID;
}
else
{
m_log.WriteLine("Found process {0} but does not match {1}", data.ProcessName, processNameOrId);
}
};
source.Clr.GCStart += delegate(GCStartTraceData data)
{
// If this GC is not part of a heap dump, ignore it.
// TODO FIX NOW if (data.ClientSequenceNumber == 0)
// return;
if (data.TimeStampRelativeMSec < m_ignoreUntilMSec)
{
return;
}
if (m_processId == 0)
{
m_processId = data.ProcessID;
m_log.WriteLine("Process wildcard selects process id {0}", m_processId);
}
if (data.ProcessID != m_processId)
{
m_log.WriteLine("GC Start found but Process ID {0} != {1} desired ID", data.ProcessID, m_processId);
return;
}
if (!IsProjectN && data.ProviderGuid == ClrTraceEventParser.NativeProviderGuid)
{
IsProjectN = true;
}
if (data.Depth < 2 || data.Type != GCType.NonConcurrentGC)
{
m_log.WriteLine("GC Start found but not a Foreground Gen 2 GC");
return;
}
if (data.Reason != GCReason.Induced)
{
m_log.WriteLine("GC Start not induced. Skipping.");
return;
}
if (!m_seenStart)
{
m_gcID = data.Count;
m_log.WriteLine("Found a Gen2 Induced non-background GC Start at {0:n3} msec GC Count {1}", data.TimeStampRelativeMSec, m_gcID);
m_ignoreEvents = false;
m_seenStart = true;
memoryGraph.Is64Bit = (data.PointerSize == 8);
}
};
source.Clr.GCStop += delegate(GCEndTraceData data)
{
if (m_ignoreEvents || data.ProcessID != m_processId)
{
return;
}
if (data.Count == m_gcID)
{
m_log.WriteLine("Found a GC Stop at {0:n3} for GC {1}, ignoring events from now on.", data.TimeStampRelativeMSec, m_gcID);
m_ignoreEvents = true;
if (m_nodeBlocks.Count == 0 && m_typeBlocks.Count == 0 && m_edgeBlocks.Count == 0)
{
m_log.WriteLine("Found no node events, looking for another GC");
m_seenStart = false;
return;
}
// TODO we have to continue processing to get the module rundown events.
// If we could be sure to get these early, we could optimized this.
// source.StopProcessing();
}
else
{
m_log.WriteLine("Found a GC Stop at {0:n3} but id {1} != {2} Target ID", data.TimeStampRelativeMSec, data.Count, m_gcID);
}
};
source.Clr.TypeBulkType += delegate(GCBulkTypeTraceData data)
{
// Don't check m_ignoreEvents here, as BulkType events can be emitted by other events...such as the GC allocation event.
// This means that when setting m_processId to 0 in the command line may still lose type events.
if (data.ProcessID != m_processId)
{
return;
}
m_typeBlocks.Enqueue((GCBulkTypeTraceData)data.Clone());
};
source.Clr.GCBulkNode += delegate(GCBulkNodeTraceData data)
{
if (m_ignoreEvents || data.ProcessID != m_processId)
{
return;
}
m_nodeBlocks.Enqueue((GCBulkNodeTraceData)data.Clone());
};
source.Clr.GCBulkEdge += delegate(GCBulkEdgeTraceData data)
{
if (m_ignoreEvents || data.ProcessID != m_processId)
{
return;
}
m_edgeBlocks.Enqueue((GCBulkEdgeTraceData)data.Clone());
};
source.Clr.GCBulkRootEdge += delegate(GCBulkRootEdgeTraceData data)
{
if (m_ignoreEvents || data.ProcessID != m_processId)
{
return;
}
MemoryNodeBuilder staticRoot = m_root.FindOrCreateChild("[static vars]");
for (int i = 0; i < data.Count; i++)
{
var value = data.Values(i);
var flags = value.GCRootFlag;
if ((flags & GCRootFlags.WeakRef) == 0) // ignore weak references. they are not roots.
{
GCRootKind kind = value.GCRootKind;
MemoryNodeBuilder root = m_root;
string name;
if (kind == GCRootKind.Stack)
{
name = "[local vars]";
}
else
{
root = m_root.FindOrCreateChild("[other roots]");
if ((flags & GCRootFlags.RefCounted) != 0)
{
name = "[COM/WinRT Objects]";
}
else if (kind == GCRootKind.Finalizer)
{
name = "[finalizer Handles]";
}
else if (kind == GCRootKind.Handle)
{
if (flags == GCRootFlags.Pinning)
{
name = "[pinning Handles]";
}
else
{
name = "[strong Handles]";
}
}
else
{
name = "[other Handles]";
}
// Remember the root for later processing.
if (value.RootedNodeAddress != 0)
{
Address gcRootId = value.GCRootID;
if (gcRootId != 0 && IsProjectN)
{
Module gcRootModule = GetModuleForAddress(gcRootId);
if (gcRootModule != null)
{
var staticRva = (int)(gcRootId - gcRootModule.ImageBase);
var staticTypeIdx = m_graph.CreateType(staticRva, gcRootModule, 0, " (static var)");
var staticNodeIdx = m_graph.CreateNode();
m_children.Clear();
m_children.Add(m_graph.GetNodeIndex(value.RootedNodeAddress));
m_graph.SetNode(staticNodeIdx, staticTypeIdx, 0, m_children);
staticRoot.AddChild(staticNodeIdx);
Trace.WriteLine("Got Static 0x" + gcRootId.ToString("x") + " pointing at 0x" + value.RootedNodeAddress.ToString("x") + " kind " + value.GCRootKind + " flags " + value.GCRootFlag);
continue;
}
}
Trace.WriteLine("Got GC Root 0x" + gcRootId.ToString("x") + " pointing at 0x" + value.RootedNodeAddress.ToString("x") + " kind " + value.GCRootKind + " flags " + value.GCRootFlag);
}
}
root = root.FindOrCreateChild(name);
Address objId = value.RootedNodeAddress;
root.AddChild(m_graph.GetNodeIndex(objId));
}
}
};
source.Clr.GCBulkRCW += delegate(GCBulkRCWTraceData data)
{
if (m_ignoreEvents || data.ProcessID != m_processId)
{
return;
}
for (int i = 0; i < data.Count; i++)
{
GCBulkRCWValues comInfo = data.Values(i);
m_objectToRCW[comInfo.ObjectID] = new RCWInfo(comInfo);
}
};
source.Clr.GCBulkRootCCW += delegate(GCBulkRootCCWTraceData data)
{
if (m_ignoreEvents || data.ProcessID != m_processId)
{
return;
}
m_ccwBlocks.Enqueue((GCBulkRootCCWTraceData)data.Clone());
};
source.Clr.GCBulkRootStaticVar += delegate(GCBulkRootStaticVarTraceData data)
{
if (m_ignoreEvents || data.ProcessID != m_processId)
{
return;
}
m_staticVarBlocks.Enqueue((GCBulkRootStaticVarTraceData)data.Clone());
};
source.Clr.GCBulkRootConditionalWeakTableElementEdge += delegate(GCBulkRootConditionalWeakTableElementEdgeTraceData data)
{
if (m_ignoreEvents || data.ProcessID != m_processId)
{
return;
}
var otherRoots = m_root.FindOrCreateChild("[other roots]");
var dependentHandles = otherRoots.FindOrCreateChild("[Dependent Handles]");
for (int i = 0; i < data.Count; i++)
{
var value = data.Values(i);
// TODO fix this so that they you see this as an arc from source to target.
// The target is alive only if the source ID (which is a weak handle) is alive (non-zero)
if (value.GCKeyNodeID != 0)
{
dependentHandles.AddChild(m_graph.GetNodeIndex(value.GCValueNodeID));
}
}
};
source.Clr.GCGenerationRange += delegate(GCGenerationRangeTraceData data)
{
if (m_ignoreEvents || data.ProcessID != m_processId)
{
return;
}
if (m_dotNetHeapInfo == null)
{
return;
}
// We want the 'after' ranges so we wait
if (m_nodeBlocks.Count == 0)
{
return;
}
Address start = data.RangeStart;
Address end = start + data.RangeUsedLength;
if (m_dotNetHeapInfo.Segments == null)
{
m_dotNetHeapInfo.Segments = new List <GCHeapDumpSegment>();
}
GCHeapDumpSegment segment = new GCHeapDumpSegment();
segment.Start = start;
segment.End = end;
switch (data.Generation)
{
case 0:
segment.Gen0End = end;
break;
case 1:
segment.Gen1End = end;
break;
case 2:
segment.Gen2End = end;
break;
case 3:
segment.Gen3End = end;
break;
default:
throw new Exception("Invalid generation in GCGenerationRangeTraceData");
}
m_dotNetHeapInfo.Segments.Add(segment);
};
}
