public static EventListener Create(Guid eventSourceGuid, string sessionName, double eventCounterIntervalSeconds)
{
var session = new TraceEventSession(sessionName);
TraceEventProviderOptions options = new TraceEventProviderOptions("EventCounterIntervalSec", eventCounterIntervalSeconds.ToString()); //I'm just guessing what the args should be...
session.EnableProvider(eventSourceGuid, providerLevel: TraceEventLevel.Verbose, matchAnyKeywords: ulong.MaxValue, options: options);
var source = new ETWTraceEventSource(sessionName, TraceEventSourceType.Session);
var e = new EventListener(session, source);
source.Dynamic.All += delegate(TraceEvent data)
{
if (data.ProviderGuid != eventSourceGuid)
{
throw new Exception();
}
if (data.EventName == "EventCounters")
{
string s = data.PayloadString(0).Replace("∞", "0");
EventCounterData ed = Parse <EventCounterData>(s);
e.EventCounterEvent?.Invoke(MsSinceUnixEpoch(data.TimeStamp), ed);
}
};
return(e);
}
static void RegisterEventListener(TraceEventSession userSession)
{
var options = new TraceEventProviderOptions();
options.AddArgument("EventCounterIntervalSec", _config.EventCounterIntervalInSeconds.ToString());
foreach (var eventSource in _config.EventSources)
{
userSession.EnableProvider(eventSource.Name, TraceEventLevel.Always, (ulong)EventKeywords.None, options);
// Create a stream of the 'EventCounters' event source events
IObservable <TraceEvent> eventStream = userSession.Source.Dynamic.Observe(eventSource.Name, "EventCounters");
eventStream.Subscribe(onNext: traceEvent =>
{
var payload = traceEvent.PayloadValue(0) as IDictionary <string, object>;
if (payload != null)
{
var key = $"{traceEvent.ProviderName}-{payload["Name"]}";
var eventCounterRow = _eventCounters[key];
for (var i = 0; i < _config.Columns.Count; i++)
{
var rowDataCell = eventCounterRow[i];
rowDataCell.UpdateData(payload[_config.Columns[i].Name]?.ToString());
}
}
});
}
// OK we are all set up, time to listen for events and pass them to the observers.
userSession.Source.Process();
}
/// <summary>
/// Dump the dot net Heap for process 'processID' to the etl file name 'etlFileName'. Send diagnostics to 'log'.
/// If 'memoryGraph is non-null also update it to contain the heap Dump. If null you get just the ETL file.
/// returns true if successful.
/// </summary>
static public bool DumpAsEtlFile(int processID, string etlFileName, TextWriter log, MemoryGraph memoryGraph = null, DotNetHeapInfo dotNetInfo = null)
{
bool success = false;
log.WriteLine("Starting ETW logging on File {0}", etlFileName);
using (var session = new TraceEventSession("PerfViewGCHeapETLSession", etlFileName))
{
session.EnableKernelProvider(KernelTraceEventParser.Keywords.Process | KernelTraceEventParser.Keywords.Thread | KernelTraceEventParser.Keywords.ImageLoad);
// Isolate this to a single process.
var options = new TraceEventProviderOptions()
{
ProcessIDFilter = new List <int>()
{
processID
}
};
// For non-project N we need module rundown to figure out the correct module name
session.EnableProvider(ClrRundownTraceEventParser.ProviderGuid, TraceEventLevel.Verbose,
(ulong)(ClrRundownTraceEventParser.Keywords.Loader | ClrRundownTraceEventParser.Keywords.ForceEndRundown), options);
session.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Informational,
(ulong)(ClrTraceEventParser.Keywords.GCHeapDump | ClrTraceEventParser.Keywords.GC | ClrTraceEventParser.Keywords.Type | ClrTraceEventParser.Keywords.Type | ClrTraceEventParser.Keywords.GCHeapAndTypeNames), options);
// Project N support.
session.EnableProvider(ClrTraceEventParser.NativeProviderGuid, TraceEventLevel.Informational,
(ulong)(ClrTraceEventParser.Keywords.GCHeapDump | ClrTraceEventParser.Keywords.GC | ClrTraceEventParser.Keywords.Type | ClrTraceEventParser.Keywords.Type | ClrTraceEventParser.Keywords.GCHeapAndTypeNames), options);
success = Dump(processID, memoryGraph, log, dotNetInfo);
log.WriteLine("Stopping ETW logging on {0}", etlFileName);
}
log.WriteLine("DumpAsETLFile returns. Success={0}", success);
return(success);
}
internal static void EnableProvider(
TraceEventSession session,
Guid providerId,
EventLevel level,
EventKeywords matchAnyKeyword,
IEnumerable <KeyValuePair <string, string> > arguments,
IEnumerable <string> processNamesToFilter,
bool sendManifest = true)
{
// Make explicit the invocation for requesting the manifest from the EventSource (Provider).
var argumentsDictionary = arguments.ToDictionary(kvp => kvp.Key, kvp => kvp.Value);
if (sendManifest)
{
argumentsDictionary["Command"] = "SendManifest";
}
var options =
new TraceEventProviderOptions
{
Arguments = argumentsDictionary,
ProcessNameFilter = processNamesToFilter.ToArray()
};
session.EnableProvider(providerId, (TraceEventLevel)level, (ulong)matchAnyKeyword, options);
}
internal static void EnableProvider(
TraceEventSession session,
Guid providerId,
EventLevel level,
EventKeywords matchAnyKeyword,
IEnumerable<KeyValuePair<string, string>> arguments,
IEnumerable<string> processNamesToFilter,
bool sendManifest = true)
{
// Make explicit the invocation for requesting the manifest from the EventSource (Provider).
var argumentsDictionary = arguments.ToDictionary(kvp => kvp.Key, kvp => kvp.Value);
if (sendManifest)
{
argumentsDictionary["Command"] = "SendManifest";
}
var options =
new TraceEventProviderOptions
{
Arguments = argumentsDictionary,
ProcessNameFilter = processNamesToFilter.ToArray()
};
session.EnableProvider(providerId, (TraceEventLevel)level, (ulong)matchAnyKeyword, options);
}
private void ProcessEtwEvents()
{
// setup process filter if any
TraceEventProviderOptions options = null;
if (_processId != -1)
{
options = new TraceEventProviderOptions()
{
ProcessIDFilter = new List <int>()
{
_processId
},
};
}
// register handlers for events on the session source
// --------------------------------------------------
RegisterListeners(_session.Source);
// decide which provider to listen to with filters if needed
_session.EnableProvider(
ClrTraceEventParser.ProviderGuid, // CLR provider
((_filter & EventFilter.AllocationTick) == EventFilter.AllocationTick) ?
TraceEventLevel.Verbose : TraceEventLevel.Informational,
GetKeywords(),
options
);
// this is a blocking call until the session is disposed
_session.Source.Process();
}
private void SetupSession()
{
session = new TraceEventSession("DelphiTestProvider");
// ETW buffers events and only delivers them after buffering up for some amount of time. Thus
// there is a small delay of about 2-4 seconds between the timestamp on the event (which is very
// accurate), and the time we actually get the event.
session.Source.Dynamic.All += delegate(TraceEvent data)
{
Interlocked.Increment(ref EventCounter);
var str = data.ToString();
Debug.WriteLine(string.Format("GOT Event {0} ", str));
OnEventAny?.Invoke(this, data.ToString());
};
session.Source.Dynamic.AddCallbackForProviderEvent("Delphi-Test-Provider", "Test/Random", delegate(TraceEvent data)
{
var index = Interlocked.Increment(ref EventCounter);
try
{
var obj = new TestEventData(index, data);
Debug.WriteLine(obj);
OnEvent?.Invoke(this, obj);
}
catch (Exception ex)
{
Debug.WriteLine("Exception while parsing event: " + ex);
}
});
session.Source.UnhandledEvents += delegate(TraceEvent data)
{
if ((int)data.ID != 0xFFFE) // The EventSource manifest events show up as unhanded, filter them out.
{
Debug.WriteLine("GOT UNHANDLED EVENT: " + data.Dump());
}
};
var traceOptions = new TraceEventProviderOptions
{
StacksEnabled = false
};
session.EnableProvider("Delphi-Test-Provider", options: traceOptions);
// go into a loop processing events can calling the callbacks. Because this is live data (not from a file)
// processing never completes by itself, but only because someone called 'source.Dispose()'.
Task.Run(() =>
{
session.Source.Process();
});
}
/// <summary>
/// Interface to enable user providers.
/// </summary>
/// <param name="providerGuid">The Guid that represents the event provider to be enabled.</param>
/// <param name="providerLevel">The verbosity to turn on.</param>
/// <param name="matchAnyKeywords">A bitvector representing the areas to turn on. Only the
/// low 32 bits are used by classic providers and passed as the 'flags' value. Zero
/// is a special value which is a provider defined default, which is usually 'everything'.
/// </param>
/// <param name="options">Additional options for the provider.</param>
public void EnableProvider(
Guid providerGuid,
TraceEventLevel providerLevel = TraceEventLevel.Verbose,
ulong matchAnyKeywords = ulong.MaxValue,
TraceEventProviderOptions options = null)
{
if (TraceEventSession.EnableProvider(providerGuid, providerLevel, matchAnyKeywords, options))
{
Debug.WriteLine("The session already existed and needed to be restarted.");
}
}
protected void EnabledDefaultProviders(TraceEventSession session, TraceEventProviderOptions options = null)
{
// This provider is required to get ActivityID support on TraceEvents.
session.EnableProvider(
TplEtwProviderTraceEventParser.ProviderGuid,
TraceEventLevel.Informational,
(ulong)TplEtwProviderTraceEventParser.Keywords.TasksFlowActivityIds,
options);
session.EnableProvider(DotNetRuntimeProviderGuid, options: options);
session.EnableProvider(XamlProviderGuid, options: options);
}
protected override void EnableProviders(TraceEventSession session)
{
var options = new TraceEventProviderOptions()
{
ProcessNameFilter = new string[] { "Quadrant.exe" }
};
Guid eventSource = TraceEventProviders.GetEventSourceGuidFromName(QuadrantProvider);
session.EnableProvider(eventSource, options: options);
EnabledDefaultProviders(session, options);
}
public static Task <bool> RealTimeTraceEventSessionAsync
(
string providerName
, string sessionName
, string tracingFileName = null
, string[] traceEvents = null
, Action
<
long
, TraceEventDispatcher
, TraceEventSession
, TraceEvent
> onOneEventTracedOnceProcessAction = null
, TraceEventProviderOptions traceEventProviderOptions = null
, TraceEventSessionOptions traceEventSessionOptions = TraceEventSessionOptions.Create
, TraceEventSourceType traceEventSourceType = TraceEventSourceType.MergeAll
, TraceEventLevel traceEventLevel = TraceEventLevel.Always
, ulong matchKeywords = ulong.MaxValue
, bool needCountHits = false
)
{
return
(Task
.Factory
.StartNew <bool>
(
() =>
{
return
RealTimeTraceEventSession
(
providerName
, sessionName
, tracingFileName
, traceEvents
, onOneEventTracedOnceProcessAction
, traceEventProviderOptions
, traceEventSessionOptions
, traceEventSourceType
, traceEventLevel
, matchKeywords
, needCountHits
);
}
,
TaskCreationOptions.LongRunning
|
TaskCreationOptions.DenyChildAttach
));
}
static void Main(string[] args)
{
using (var session = new TraceEventSession("MonitorKernelAndClrEventsSession"))
{
Console.CancelKeyPress += (object sender, ConsoleCancelEventArgs cancelArgs) =>
{
session.Dispose();
cancelArgs.Cancel = true;
};
//session.EnableKernelProvider(KernelTraceEventParser.Keywords.ImageLoad | KernelTraceEventParser.Keywords.Process | KernelTraceEventParser.Keywords.Thread);
var optionsWithStacks = new TraceEventProviderOptions()
{
StacksEnabled = true
};
//session.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Verbose, (ulong)ClrTraceEventParser.Keywords.Default);
//session.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Verbose, (ulong)ClrTraceEventParser.Keywords.Exception, optionsWithStacks);
//session.EnableProvider(ClrRundownTraceEventParser.ProviderGuid, TraceEventLevel.Verbose, (ulong)ClrRundownTraceEventParser.Keywords.Default);
session.EnableProvider("Microsoft-Windows-TCPIP", TraceEventLevel.Verbose);
#if TRACELOG
using (TraceLogEventSource traceLogSource = TraceLog.CreateFromTraceEventSession(session))
{
traceLogSource.Clr.ExceptionStart += ClrOnExceptionStart;
traceLogSource.Process();
}
#else
session.Source.Clr.GCStart += ClrOnGcStart;
session.Source.Clr.GCStop += ClrOnGcStop;
session.Source.Clr.GCHeapStats += ClrOnGcHeapStats;
session.Source.Dynamic.All += delegate(Microsoft.Diagnostics.Tracing.TraceEvent data)
{
// ETW buffers events and only delivers them after buffering up for some amount of time. Thus
// there is a small delay of about 2-4 seconds between the timestamp on the event (which is very
// accurate), and the time we actually get the event. We measure that delay here.
var delay = (DateTime.Now - data.TimeStamp).TotalSeconds;
//Console.WriteLine("GOT Event Delay={0:f1}sec: {1}/{2} ", delay, data.ProviderName, data.EventName);
};
session.Source.Dynamic.AddCallbackForProviderEvent("Microsoft-Windows-TCPIP", "TcpSendTransmitted",
data => Console.WriteLine($"PID {data.ProcessID} sent {data.PayloadByName("NumBytes")} B"));
//session.Source.Kernel.ProcessStart += KernelOnProcessStart;
//session.Source.Kernel.ProcessStop += KernelOnProcessStop;
session.Source.Process();
#endif
}
}
public bool RealTimeTraceEventSession
(
string providerName
, string sessionName
, string tracingFileName = null
, string[] traceEvents = null
, Action
<
long
, TraceEventDispatcher
, TraceEventSession
, TraceEvent
> onOneEventTracedOnceProcessAction = null
, TraceEventProviderOptions traceEventProviderOptions = null
, TraceEventSessionOptions traceEventSessionOptions = TraceEventSessionOptions.Create
, TraceEventSourceType traceEventSourceType = TraceEventSourceType.MergeAll
, TraceEventLevel traceEventLevel = TraceEventLevel.Always
, ulong matchKeywords = ulong.MaxValue
, bool needCountHits = false)
{
var r = false;
if
(
traceEvents != null
&&
traceEvents.Length > 0
&&
onOneEventTracedOnceProcessAction != null
)
{
r = TraceEventsHelper
.RealTimeTraceEventSession
(
providerName
, sessionName
, tracingFileName
, traceEvents
, onOneEventTracedOnceProcessAction
, traceEventProviderOptions
, traceEventSessionOptions
, traceEventSourceType
, traceEventLevel
, matchKeywords
, needCountHits
);
}
return(r);
}
public static void EnableEventSources(this TraceEventSession session, IEnumerable <EventSourceDefinition> eventSources)
{
foreach (var eventSource in eventSources)
{
TraceEventProviderOptions providerOptions = new TraceEventProviderOptions()
{
EventIDsToEnable = eventSource.Ids,
ProcessIDFilter = eventSource.ProcessIds,
ProcessNameFilter = eventSource.ProcessNames,
};
// If this API fails, it will throw an exception.
// https://github.com/Microsoft/perfview/blob/master/src/TraceEvent/TraceEventSession.cs
session.EnableProvider(eventSource.ProviderGuid, eventSource.TraceLevel, eventSource.Keywords, providerOptions);
}
}
private void RunAsync()
{
var elevated = TraceEventSession.IsElevated();
var eventSourceGuid = TraceEventProviders.GetProviderGuidByName(providerName);
session = new TraceEventSession(sessionName, "data.etl");
kernelSession = new TraceEventSession(KernelTraceEventParser.KernelSessionName, "data.kernel.etl");
kernelSession.EnableKernelProvider(KernelTraceEventParser.Keywords.ImageLoad | KernelTraceEventParser.Keywords.Process | KernelTraceEventParser.Keywords.Thread);
var optionsWithStacks = new TraceEventProviderOptions()
{
StacksEnabled = true
};
session.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Verbose, (ulong)ClrTraceEventParser.Keywords.Default);
session.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Verbose, (ulong)ClrTraceEventParser.Keywords.GC, optionsWithStacks);
}
/// <summary>
/// Dump the dot net Heap for process 'processID' to the etl file name 'etlFileName'. Send diagnostics to 'log'.
/// If 'memoryGraph is non-null also update it to contain the heap Dump. If null you get just the ETL file.
/// returns true if successful.
/// </summary>
static public bool DumpAsEtlFile(int processID, string etlFileName, TextWriter log, MemoryGraph memoryGraph = null, DotNetHeapInfo dotNetInfo = null)
{
bool success = false;
log.WriteLine("Starting ETW logging on File {0}", etlFileName);
using (var session = new TraceEventSession("PerfViewGCHeapETLSession", etlFileName))
{
session.BufferSizeMB = 256;
session.EnableKernelProvider(KernelTraceEventParser.Keywords.Process | KernelTraceEventParser.Keywords.Thread | KernelTraceEventParser.Keywords.ImageLoad);
// Isolate this to a single process.
var options = new TraceEventProviderOptions()
{
ProcessIDFilter = new List <int>()
{
processID
}
};
// There is a bug in the runtime 4.6.2 and earlier where we only clear the table of types we have already emitted when you ENABLE
// the Clr Provider WITHOUT the ClrTraceEventParser.Keywords.Type keyword. We achieve this by turning on just the GC events,
// (which clears the Type table) and then turn all the events we need on.
// Note we do this here, as well as in Dump() because it only works if the CLR Type keyword is off (and we turn it on below)
session.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Informational, (ulong)ClrTraceEventParser.Keywords.GC, options);
System.Threading.Thread.Sleep(50); // Wait for it to complete (it is async)
// For non-project N we need module rundown to figure out the correct module name
session.EnableProvider(ClrRundownTraceEventParser.ProviderGuid, TraceEventLevel.Verbose,
(ulong)(ClrRundownTraceEventParser.Keywords.Loader | ClrRundownTraceEventParser.Keywords.ForceEndRundown), options);
session.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Informational,
(ulong)(ClrTraceEventParser.Keywords.GCHeapDump | ClrTraceEventParser.Keywords.GC | ClrTraceEventParser.Keywords.Type | ClrTraceEventParser.Keywords.GCHeapAndTypeNames), options);
// Project N support.
session.EnableProvider(ClrTraceEventParser.NativeProviderGuid, TraceEventLevel.Informational,
(ulong)(ClrTraceEventParser.Keywords.GCHeapDump | ClrTraceEventParser.Keywords.GC | ClrTraceEventParser.Keywords.Type | ClrTraceEventParser.Keywords.GCHeapAndTypeNames), options);
success = Dump(processID, memoryGraph, log, dotNetInfo);
log.WriteLine("Stopping ETW logging on {0}", etlFileName);
}
log.WriteLine("DumpAsETLFile returns. Success={0}", success);
return(success);
}
public Task <bool> TraceETWTraceEventSourceAsync
(
string providerName
, string tracedFileName
, string[] traceEvents = null
, Action
<
long
, TraceEventDispatcher
, TraceEventSession
, TraceEvent
> onOneEventTracedOnceProcessAction = null
, TraceEventProviderOptions traceEventProviderOptions = null
, TraceEventSourceType traceEventSourceType = TraceEventSourceType.MergeAll
, TraceEventLevel traceEventLevel = TraceEventLevel.Always
, ulong matchKeywords = ulong.MaxValue
, bool needCountHits = false
)
{
return
(Task
.Factory
.StartNew <bool>
(
() =>
{
return
TraceETWTraceEventSource
(
providerName
, tracedFileName
, traceEvents
, onOneEventTracedOnceProcessAction
, traceEventProviderOptions
, traceEventSourceType
, traceEventLevel
, matchKeywords
, needCountHits
);
}
));
}
public override Task StartCollectingAsync()
{
// TODO: Allow a file name to be provided
var outputFile = _config.ProcessId == null?
Path.Combine(_config.OutputPath, "dotnet-collect.etl") :
Path.Combine(_config.OutputPath, $"dotnet-collect.{_config.ProcessId.Value}.etl");
if (File.Exists(outputFile))
{
throw new InvalidOperationException($"Target file already exists: {outputFile}");
}
_session = new TraceEventSession("dotnet-collect", outputFile);
if (_config.CircularMB is int circularMb)
{
_session.CircularBufferMB = circularMb;
}
var options = new TraceEventProviderOptions();
if (_config.ProcessId is int pid)
{
options.ProcessIDFilter = new List <int>()
{
pid
};
}
// Enable the providers requested
foreach (var provider in _config.Providers)
{
_session.EnableProvider(provider.Provider, ConvertLevel(provider.Level), provider.Keywords, options);
}
return(Task.CompletedTask);
}
/// <summary>
/// CollectData doe will turn on logging of data from 'eventSourceName' to the file 'dataFileName'.
/// It will then call EventGenerator.CreateEvents and wait 12 seconds for it to generate some data.
/// </summary>
static void CollectData(string eventSourceName, string dataFileName)
{
// Today you have to be Admin to turn on ETW events (anyone can write ETW events).
if (!(TraceEventSession.IsElevated() ?? false))
{
Out.WriteLine("To turn on ETW events you need to be Administrator, please run from an Admin process.");
Debugger.Break();
return;
}
// As mentioned below, sessions can outlive the process that created them. Thus you need a way of
// naming the session so that you can 'reconnect' to it from another process. This is what the name
// is for. It can be anything, but it should be descriptive and unique. If you expect multiple versions
// of your program to run simultaneously, you need to generate unique names (e.g. add a process ID suffix)
// however this is dangerous because you can leave data collection on if the program ends unexpectedly.
//
// In this case we tell the session to place the data in MonitorToFileData.etl.
var sessionName = "SimpleTraceLogSession";
Out.WriteLine("Creating a '{0}' session writing to {1}", sessionName, dataFileName);
Out.WriteLine("Use 'logman query -ets' to see active sessions.");
Out.WriteLine("Use 'logman stop {0} -ets' to manually stop orphans.", sessionName);
using (var session = new TraceEventSession(sessionName, dataFileName)) // Since we give it a file name, the data goes there.
using (var kernelSession = new TraceEventSession(KernelTraceEventParser.KernelSessionName, Path.ChangeExtension(dataFileName, ".kernel.etl")))
{
/* BY DEFAULT ETW SESSIONS SURVIVE THE DEATH OF THE PROESS THAT CREATES THEM! */
// Unlike most other resources on the system, ETW session live beyond the lifetime of the
// process that created them. This is very useful in some scenarios, but also creates the
// very real possibility of leaving 'orphan' sessions running.
//
// To help avoid this by default TraceEventSession sets 'StopOnDispose' so that it will stop
// the ETW session if the TraceEventSession dies. Thus executions that 'clean up' the TraceEventSession
// will clean up the ETW session. This covers many cases (including throwing exceptions)
//
// However if the process is killed manually (including control C) this cleanup will not happen.
// Thus best practices include
//
// * Add a Control C handler that calls session.Dispose() so it gets cleaned up in this common case
// * use the same session name run-to-run so you don't create many orphans.
//
// By default TraceEventSessions are in 'create' mode where it assumes you want to create a new session.
// In this mode if a session already exists, it is stopped and the new one is created.
//
// Here we install the Control C handler. It is OK if Dispose is called more than once.
Console.CancelKeyPress += delegate(object sender, ConsoleCancelEventArgs e) { session.Dispose(); kernelSession.Dispose(); };
// Enable kernel events.
kernelSession.EnableKernelProvider(KernelTraceEventParser.Keywords.ImageLoad | KernelTraceEventParser.Keywords.Process | KernelTraceEventParser.Keywords.Thread);
// Enable my provider, you can call many of these on the same session to get events from other providers
// Turn on the eventSource given its name.
// Note we turn on Verbose level all keywords (ulong.MaxValue == 0xFFF....) and turn on stacks for
// this provider (for all events, until Windows 8.1 you can only turn on stacks for every event
// for a particular provider or no stacks)
var options = new TraceEventProviderOptions()
{
StacksEnabled = true
};
var restarted = session.EnableProvider(eventSourceName, TraceEventLevel.Verbose, ulong.MaxValue, options);
if (restarted) // Generally you don't bother with this warning, but for the demo we do.
{
Out.WriteLine("The session {0} was already active, it has been restarted.", sessionName);
}
// We also turn on CLR events because we need them to decode Stacks and we also get exception events (and their stacks)
session.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Verbose, (ulong)ClrTraceEventParser.Keywords.Default);
// Start another thread that Causes MyEventSource to create some events
// Normally this code as well as the EventSource itself would be in a different process.
EventGenerator.CreateEvents();
// Also generate some exceptions so we have interesting stacks to look at
Thread.Sleep(100);
EventGenerator.GenerateExceptions();
Out.WriteLine("Waiting 12 seconds for events to come in.");
Thread.Sleep(12000);
// Because the process in question (this process) lives both before and after the time the events were
// collected, we don't have complete information about JIT compiled methods in that method. There are
// some methods that were JIT compiled before the session started (e.g. SimpleTraceLog.Main) for which
// we do not have information. We collect this by forcing a CLR 'rundown' which will dump method information
// for JIT compiled methods that were not present. If you know that the process of interest ends before
// data collection ended or that data collection started before the process started, then this is not needed.
Out.WriteLine("Forcing rundown of JIT methods.");
var rundownFileName = Path.ChangeExtension(dataFileName, ".clrRundown.etl");
using (var rundownSession = new TraceEventSession(sessionName + "Rundown", rundownFileName))
{
rundownSession.EnableProvider(ClrRundownTraceEventParser.ProviderGuid, TraceEventLevel.Verbose, (ulong)ClrRundownTraceEventParser.Keywords.Default);
// Poll until 2 second goes by without growth.
for (var prevLength = new FileInfo(rundownFileName).Length; ;)
{
Thread.Sleep(2000);
var newLength = new FileInfo(rundownFileName).Length;
if (newLength == prevLength)
{
break;
}
prevLength = newLength;
}
}
Out.WriteLine("Done with rundown.");
}
Out.WriteLine("Zipping the raw files into a single '{0}' file.", dataFileName);
// At this point you have multiple ETL files that don't have all the information
// inside them necessary for analysis off the currentn machine. To do analsysis
// of the machine you need to merge the ETL files (which can be done with
// TraceEventSession.MergeInPlace(dataFileName, Out);
// However this does not get the symbolic information (NGEN PDBS) needed to
// decode the stacks in the .NET managed framewrok on another machine.
// To do the merging AND generate these NGEN images it is best to us ethe
// ZipppedETLWriter that does all this (and compresses all the files in a ZIP archive).
ZippedETLWriter writer = new ZippedETLWriter(dataFileName, Out);
writer.WriteArchive();
Out.WriteLine("Zip complete, output file = {0}", writer.ZipArchivePath);
}
public static bool TraceETWTraceEventSource
(
string providerName
, string tracedFileName
, string[] traceEvents = null
, Action
<
long
, TraceEventDispatcher
, TraceEventSession
, TraceEvent
> onOneEventTracedOnceProcessAction = null
, TraceEventProviderOptions traceEventProviderOptions = null
, TraceEventSourceType traceEventSourceType = TraceEventSourceType.MergeAll
, TraceEventLevel traceEventLevel = TraceEventLevel.Always
, ulong matchKeywords = ulong.MaxValue
, bool needCountHits = false
)
{
var r = false;
if (!(TraceEventSession.IsElevated() ?? false))
{
Out.WriteLine("To turn on ETW events you need to be Administrator, please run from an Admin process.");
return(r);
}
if
(
traceEvents != null
&&
traceEvents.Length > 0
&&
onOneEventTracedOnceProcessAction != null
)
{
using (var source = new ETWTraceEventSource(tracedFileName, traceEventSourceType))
{
//闭包
long sequence = 0;
RegisterCallbacks
(
providerName
, traceEvents
, source
, null
, (x, y, z) =>
{
long id = 0;
if (needCountHits)
{
id = Interlocked.Increment(ref sequence);
}
onOneEventTracedOnceProcessAction
(
id
, x
, y
, z
);
}
);
source.Process(); // call the callbacks for each event
}
}
return(true);
}
static void Main(string[] args)
{
if (args.Length == 2 && args[0] == "--bodies" && System.IO.Directory.Exists(args[1]))
{
body_dir = args[1];
}
// read settings for custom ETW providers
if (File.Exists(customProvidersConfigPath))
{
try
{
customProviders = JsonConvert.DeserializeObject <Dictionary <string, CustomProvider> >(File.ReadAllText(customProvidersConfigPath));
}
catch (Exception e) {
Console.WriteLine("{0} Exception caught.", e);
}
}
// perf optimization - warm up the Json serializer to avoid a big perf hit serializing the first event while the test is running
// reduces the observer effect of the exe
var serializedWinInetEvents = JsonConvert.SerializeObject(WinInetEvents);
// create a real time user mode session
using (session = new TraceEventSession("wpt-etw"))
{
session.StopOnDispose = true;
// Set up Ctrl-C to stop the session
Console.CancelKeyPress += (object s, ConsoleCancelEventArgs cancel_args) => session.Stop();
session.Source.Dynamic.All += delegate(TraceEvent data)
{
try
{
int eventId = (int)data.ID;
string eventName = null;
bool keep = false;
if (data.ProviderName == "Microsoft-Windows-WinINet-Capture")
{
if (data.ActivityID != Guid.Empty && data.EventName == "EventID(2004)")
{
var raw = data.PayloadByName("Payload") as byte[];
if (raw != null && raw.Length > 0)
{
string activity = data.ActivityID.ToString("D");
string path = body_dir + "\\" + activity;
try
{
using (var stream = new FileStream(path, FileMode.Append))
{
stream.Write(raw, 0, raw.Length);
}
}
catch (Exception e) {
Console.WriteLine("{0} Exception caught.", e);
}
}
}
}
else if (data.ProviderName == "Microsoft-IE" &&
IEEvents.ContainsKey(eventId))
{
keep = true;
eventName = IEEvents[eventId];
}
else if (data.ProviderName == "Microsoft-Windows-WinINet" &&
WinInetEvents.ContainsKey(eventId))
{
keep = true;
eventName = WinInetEvents[eventId];
}
else if (customProviders.ContainsKey(data.ProviderName) &&
(customProviders[data.ProviderName].EventNames == null ||
customProviders[data.ProviderName].EventNames.Count() < 1 ||
customProviders[data.ProviderName].EventNames.Contains(data.EventName)))
{
keep = true;
}
if (keep)
{
Dictionary <string, dynamic> evt = new Dictionary <string, dynamic>();
evt["Provider"] = data.ProviderName;
evt["Event"] = eventName == null ? data.EventName : eventName;
evt["EID"] = eventId;
evt["ts"] = data.TimeStampRelativeMSec;
if (data.ActivityID != Guid.Empty)
{
evt["Activity"] = data.ActivityID.ToString("D");
}
if (data.RelatedActivityID != Guid.Empty)
{
evt["RelatedActivity"] = data.RelatedActivityID;
}
if (data.ProcessID >= 0)
{
evt["pid"] = data.ProcessID;
}
if (data.ThreadID >= 0)
{
evt["tid"] = data.ThreadID;
}
if (data.PayloadNames.Count() > 0)
{
Dictionary <string, dynamic> values = new Dictionary <string, dynamic>();
foreach (string name in data.PayloadNames)
{
values[name] = data.PayloadByName(name);
}
evt["data"] = values;
}
//evt["ascii"] = System.Text.Encoding.ASCII.GetString(data.EventData());
//evt["raw"] = data.EventData();
string json = JsonConvert.SerializeObject(evt);
mutex.WaitOne();
events.Append(json).Append("\n");
mutex.ReleaseMutex();
//Debug.WriteLine(json.Trim());
//Console.WriteLine(json.Trim());
}
}
catch (Exception e1) {
Console.WriteLine("{0} Exception caught.", e1);
}
};
if (body_dir.Length > 0)
{
session.EnableProvider("Microsoft-Windows-WinInet-Capture");
}
var WinInetProviderFilterOptions = new TraceEventProviderOptions()
{
EventIDsToEnable = new List <int>(WinInetEvents.Keys)
};
session.EnableProvider("Microsoft-Windows-WinINet", TraceEventLevel.Informational, ulong.MaxValue, WinInetProviderFilterOptions);
var IEProviderFilterOptions = new TraceEventProviderOptions()
{
EventIDsToEnable = new List <int>(IEEvents.Keys)
};
session.EnableProvider("Microsoft-IE", TraceEventLevel.Informational, 0x4001302, IEProviderFilterOptions);
if (customProviders.Count > 0)
{
foreach (var provider in customProviders)
{
if (provider.Value.EventIDs == null || provider.Value.EventIDs.Count() < 1)
{
continue;
}
var customProviderFilterOptions = new TraceEventProviderOptions()
{
EventIDsToEnable = new List <int>(provider.Value.EventIDs)
};
session.EnableProvider(provider.Key,
(TraceEventLevel)provider.Value.Verbosity,
provider.Value.Filter,
customProviderFilterOptions);
}
}
must_exit = false;
var thread = new Thread(ThreadProc);
thread.Start();
try
{
session.Source.Process(); // Listen (forever) for events
}
catch { }
must_exit = true;
thread.Join();
}
}
public static bool RealTimeTraceEventSession
(
string providerName
, string sessionName
, string tracingFileName = null
, string[] traceEvents = null
, Action
<
long
, TraceEventDispatcher
, TraceEventSession
, TraceEvent
> onOneEventTracedOnceProcessAction = null
, TraceEventProviderOptions traceEventProviderOptions = null
, TraceEventSessionOptions traceEventSessionOptions = TraceEventSessionOptions.Create
, TraceEventSourceType traceEventSourceType = TraceEventSourceType.MergeAll
, TraceEventLevel traceEventLevel = TraceEventLevel.Always
, ulong matchKeywords = ulong.MaxValue
, bool needCountHits = false
)
{
var r = false;
if (!(TraceEventSession.IsElevated() ?? false))
{
Out.WriteLine("To turn on ETW events you need to be Administrator, please run from an Admin process.");
return r;
}
var needTracingFile = !string.IsNullOrEmpty(tracingFileName);
if
(
traceEvents != null
&&
traceEvents.Length > 0
&&
onOneEventTracedOnceProcessAction != null
)
{
using
(
var session =
(
needTracingFile
?
new TraceEventSession
(
sessionName
, tracingFileName
, traceEventSessionOptions
)
{
StopOnDispose = true
}
:
new TraceEventSession
(
sessionName
, traceEventSessionOptions
)
{
StopOnDispose = true
}
)
)
{
using
(
var source =
(
needTracingFile
?
new ETWTraceEventSource(tracingFileName)
:
session.Source
)
)
{
long sequence = 0;
RegisterCallbacks
(
providerName
, traceEvents
, source
, session
, (x, y, z) =>
{
long id = 0;
if (needCountHits)
{
id = Interlocked.Increment(ref sequence);
}
onOneEventTracedOnceProcessAction
(
id
, x
, y
, z
);
}
);
var restarted = session
.EnableProvider
(
providerName
, traceEventLevel
, matchKeywords
, traceEventProviderOptions
);
source
.Process();
r = true;
}
}
}
return r;
}
public static bool TraceETWTraceEventSource
(
string providerName
, string tracedFileName
, string[] traceEvents = null
, Action
<
long
, TraceEventDispatcher
, TraceEventSession
, TraceEvent
> onOneEventTracedOnceProcessAction = null
, TraceEventProviderOptions traceEventProviderOptions = null
, TraceEventSourceType traceEventSourceType = TraceEventSourceType.MergeAll
, TraceEventLevel traceEventLevel = TraceEventLevel.Always
, ulong matchKeywords = ulong.MaxValue
, bool needCountHits = false
)
{
var r = false;
if (!(TraceEventSession.IsElevated() ?? false))
{
Out.WriteLine("To turn on ETW events you need to be Administrator, please run from an Admin process.");
return r;
}
if
(
traceEvents != null
&&
traceEvents.Length > 0
&&
onOneEventTracedOnceProcessAction != null
)
{
using (var source = new ETWTraceEventSource(tracedFileName, traceEventSourceType))
{
//闭包
long sequence = 0;
RegisterCallbacks
(
providerName
, traceEvents
, source
, null
, (x, y, z) =>
{
long id = 0;
if (needCountHits)
{
id = Interlocked.Increment(ref sequence);
}
onOneEventTracedOnceProcessAction
(
id
, x
, y
, z
);
}
);
source.Process(); // call the callbacks for each event
}
}
return true;
}
public Task<bool> TraceETWTraceEventSourceAsync
(
string providerName
, string tracedFileName
, string[] traceEvents = null
, Action
<
long
, TraceEventDispatcher
, TraceEventSession
, TraceEvent
> onOneEventTracedOnceProcessAction = null
, TraceEventProviderOptions traceEventProviderOptions = null
, TraceEventSourceType traceEventSourceType = TraceEventSourceType.MergeAll
, TraceEventLevel traceEventLevel = TraceEventLevel.Always
, ulong matchKeywords = ulong.MaxValue
, bool needCountHits = false
)
{
return
Task
.Factory
.StartNew<bool>
(
() =>
{
return
TraceETWTraceEventSource
(
providerName
, tracedFileName
, traceEvents
, onOneEventTracedOnceProcessAction
, traceEventProviderOptions
, traceEventSourceType
, traceEventLevel
, matchKeywords
, needCountHits
);
}
);
}
/// <summary>
/// Add the nodes of the .NET heap for the process 'processID' to 'memoryGraph' sending diagnostic
/// messages to 'log'. If 'memoryGraph' is null, the ETW providers are triggered by we obviously
/// don't update the memoryGraph. Thus it is only done for the side effect of triggering a .NET heap
/// dump. returns true if successful.
/// </summary>
static public bool Dump(int processID, MemoryGraph memoryGraph, TextWriter log, DotNetHeapInfo dotNetInfo = null)
{
var sw = Stopwatch.StartNew();
var dumper = new DotNetHeapDumpGraphReader(log);
dumper.DotNetHeapInfo = dotNetInfo;
bool dumpComplete = false;
bool listening = false;
TraceEventSession session = null;
Task readerTask = null;
try
{
bool etwDataPresent = false;
TimeSpan lastEtwUpdate = sw.Elapsed;
// Set up a separate thread that will listen for ETW events coming back telling us we succeeded.
readerTask = Task.Factory.StartNew(delegate
{
string sessionName = "PerfViewGCHeapSession";
session = new TraceEventSession(sessionName, null);
int gcNum = -1;
session.BufferSizeMB = 256; // Events come pretty fast, so make the buffer bigger.
// Start the providers and trigger the GCs.
log.WriteLine("{0,5:n1}s: Requesting a .NET Heap Dump", sw.Elapsed.TotalSeconds);
// Have to turn on Kernel provider first (before touching Source) so we do it here.
session.EnableKernelProvider(KernelTraceEventParser.Keywords.Process | KernelTraceEventParser.Keywords.ImageLoad);
session.Source.Clr.GCStart += delegate(GCStartTraceData data)
{
if (data.ProcessID != processID)
{
return;
}
etwDataPresent = true;
if (gcNum < 0 && data.Depth == 2 && data.Type != GCType.BackgroundGC)
{
gcNum = data.Count;
log.WriteLine("{0,5:n1}s: Dot Net Dump Started...", sw.Elapsed.TotalSeconds);
}
};
session.Source.Clr.GCStop += delegate(GCEndTraceData data)
{
if (data.ProcessID != processID)
{
return;
}
if (data.Count == gcNum)
{
log.WriteLine("{0,5:n1}s: DotNet GC Complete.", sw.Elapsed.TotalSeconds);
dumpComplete = true;
}
};
session.Source.Clr.GCBulkNode += delegate(GCBulkNodeTraceData data)
{
if (data.ProcessID != processID)
{
return;
}
etwDataPresent = true;
if ((sw.Elapsed - lastEtwUpdate).TotalMilliseconds > 500)
{
log.WriteLine("{0,5:n1}s: Making GC Heap Progress...", sw.Elapsed.TotalSeconds);
}
lastEtwUpdate = sw.Elapsed;
};
if (memoryGraph != null)
{
dumper.SetupCallbacks(memoryGraph, session.Source, processID.ToString());
}
listening = true;
session.Source.Process();
log.WriteLine("{0,5:n1}s: ETW Listener dieing", sw.Elapsed.TotalSeconds);
});
// Wait for thread above to start listening (should be very fast)
while (!listening)
{
readerTask.Wait(1);
}
Debug.Assert(session != null);
// Request the heap dump. We try to isolate this to a single process.
var options = new TraceEventProviderOptions()
{
ProcessIDFilter = new List <int>()
{
processID
}
};
// There is a bug in the runtime 4.6.2 and earlier where we only clear the table of types we have already emitted when you ENABLE
// the Clr Provider WITHOUT the ClrTraceEventParser.Keywords.Type keyword. we achive this by turning on just the GC events,
// (which clears the Type table) and then turn all the events we need on.
session.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Informational, (ulong)ClrTraceEventParser.Keywords.GC, options);
System.Threading.Thread.Sleep(50); // Wait for it to complete (it is async)
// For non-project N we need module rundown to figure out the correct module name
session.EnableProvider(ClrRundownTraceEventParser.ProviderGuid, TraceEventLevel.Verbose,
(ulong)(ClrRundownTraceEventParser.Keywords.Loader | ClrRundownTraceEventParser.Keywords.ForceEndRundown), options);
session.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Informational, (ulong)ClrTraceEventParser.Keywords.GCHeapSnapshot, options);
// Project N support.
session.EnableProvider(ClrTraceEventParser.NativeProviderGuid, TraceEventLevel.Informational, (ulong)ClrTraceEventParser.Keywords.GCHeapSnapshot, options);
for (;;)
{
if (readerTask.Wait(100))
{
break;
}
if (!etwDataPresent && sw.Elapsed.TotalSeconds > 5) // Assume it started within 5 seconds.
{
log.WriteLine("{0,5:n1}s: Assume no Dot Heap", sw.Elapsed.TotalSeconds);
break;
}
if (sw.Elapsed.TotalSeconds > 100) // Time out after 100 seconds.
{
log.WriteLine("{0,5:n1}s: Timed out after 100 seconds", sw.Elapsed.TotalSeconds);
break;
}
// TODO FIX NOW, time out faster if we seek to be stuck
if (dumpComplete)
{
break;
}
}
if (etwDataPresent)
{
dumper.ConvertHeapDataToGraph(); // Finish the conversion.
}
}
finally
{
// Stop the ETW providers
log.WriteLine("{0,5:n1}s: Shutting down ETW session", sw.Elapsed.TotalSeconds);
if (session != null)
{
session.Dispose();
}
}
if (readerTask != null)
{
log.WriteLine("{0,5:n1}s: Waiting for shutdown to complete.", sw.Elapsed.TotalSeconds);
if (!readerTask.Wait(2000))
{
log.WriteLine("{0,5:n1}s: Shutdown wait timed out after 2 seconds.", sw.Elapsed.TotalSeconds);
}
}
log.WriteLine("[{0,5:n1}s: Done Dumping .NET heap success={1}]", sw.Elapsed.TotalSeconds, dumpComplete);
return(dumpComplete);
}
public static string Start(string etlPath, IEnumerable<ProviderInfo> providerInfo, int bufferSizeMB = 64, bool stacksEnabled = false)
{
EnsureUnloadHandlerRegistered();
var userSessionName = "xunit.performance.logger." + Guid.NewGuid().ToString();
Sessions sessions = new Sessions();
sessions.UserFileName = Path.ChangeExtension(etlPath, ".user.etl");
sessions.KernelFileName = Path.ChangeExtension(etlPath, ".kernel.etl");
sessions.MergedFileName = etlPath;
var mergedProviderInfo = ProviderInfo.Merge(providerInfo);
try
{
sessions.UserSession = new TraceEventSession(userSessionName, sessions.UserFileName);
sessions.UserSession.BufferSizeMB = bufferSizeMB;
if (IsWin8OrGreater)
{
var availableCpuCounters = TraceEventProfileSources.GetInfo();
var cpuCounterIds = new List<int>();
var cpuCounterIntervals = new List<int>();
foreach (var cpuInfo in mergedProviderInfo.OfType<CpuCounterInfo>())
{
ProfileSourceInfo profInfo;
if (availableCpuCounters.TryGetValue(cpuInfo.CounterName, out profInfo))
{
cpuCounterIds.Add(profInfo.ID);
cpuCounterIntervals.Add(Math.Min(profInfo.MaxInterval, Math.Max(profInfo.MinInterval, cpuInfo.Interval)));
}
}
if (cpuCounterIds.Count > 0)
TraceEventProfileSources.Set(cpuCounterIds.ToArray(), cpuCounterIntervals.ToArray());
}
var kernelInfo = mergedProviderInfo.OfType<KernelProviderInfo>().FirstOrDefault();
if (kernelInfo != null && NeedSeparateKernelSession(kernelInfo.Keywords))
{
sessions.KernelSession = new TraceEventSession(KernelTraceEventParser.KernelSessionName, sessions.KernelFileName);
sessions.KernelSession.BufferSizeMB = bufferSizeMB;
}
else
{
sessions.KernelFileName = sessions.UserFileName;
sessions.KernelSession = sessions.UserSession;
}
if (kernelInfo != null)
{
var kernelKeywords = (KernelTraceEventParser.Keywords)kernelInfo.Keywords;
var kernelStackKeywords = stacksEnabled ? (KernelTraceEventParser.Keywords)kernelInfo.StackKeywords : KernelTraceEventParser.Keywords.None;
sessions.KernelSession.EnableKernelProvider(kernelKeywords, kernelStackKeywords);
}
ulong profilerKeywords = 0;
var stacksEnabledOptions = new TraceEventProviderOptions() { StacksEnabled = true };
foreach (var userInfo in mergedProviderInfo.OfType<UserProviderInfo>())
{
if (userInfo.StacksEnabled == true && stacksEnabled)
sessions.UserSession.EnableProvider(userInfo.ProviderGuid, userInfo.Level, userInfo.Keywords, stacksEnabledOptions);
else
sessions.UserSession.EnableProvider(userInfo.ProviderGuid, userInfo.Level, userInfo.Keywords);
if (userInfo.ProviderGuid == ETWClrProfilerTraceEventParser.ProviderGuid)
profilerKeywords |= userInfo.Keywords;
}
if (profilerKeywords != 0)
InstallETWClrProfiler((int)profilerKeywords);
s_sessions[userSessionName] = sessions;
}
catch
{
sessions.Close();
throw;
}
return userSessionName;
}
public static void Run(bool workAround)
{
Console.WriteLine("");
Console.WriteLine($"Running {nameof(Repro)} with {nameof(Repro)}={workAround}");
var eventSourceName = EventSource.GetName(typeof(ReproEventSource));
var sessionName = eventSourceName;
Console.WriteLine("Creating a '{0}' session", sessionName);
using (var session = new TraceEventSession(sessionName))
{
bool isProcessing = false;
Console.CancelKeyPress += (object sender, ConsoleCancelEventArgs e) => { session.Dispose(); };
// Write events received and stop on StopEvent
session.Source.Dynamic.All += (TraceEvent data) =>
{
Console.WriteLine($"RECEIVED event {data.ID}");
if ((ushort)data.ID == ReproEventSource.Events.StopEvent)
{
Console.WriteLine($"End of {nameof(Repro)} - disposing session");
session.Dispose();
}
};
void EnableWithoutOptions()
{
Console.WriteLine("Enabling provider WITHOUT options");
session.EnableProvider(eventSourceName);
Console.WriteLine("Provider enabled WITHOUT options");
}
void LoadEventSource()
{
var dummy = ReproEventSource.Log;
}
void EnableWithOptions()
{
Console.WriteLine("Enabling provider WITH options");
var options = new TraceEventProviderOptions();
options.EventIDsToEnable =
new int[] {
ReproEventSource.Events.Event1,
ReproEventSource.Events.StopEvent
};
session.EnableProvider(eventSourceName, options: options);
Console.WriteLine("Provider enabled WITH options");
}
void GenerateEvents()
{
Task.Factory.StartNew(() =>
{
Console.WriteLine($"WRITING event {ReproEventSource.Events.Event1}");
ReproEventSource.Log.Event1();
Console.WriteLine($"WRITING event {ReproEventSource.Events.Event2}");
ReproEventSource.Log.Event2();
Console.WriteLine($"WRITING event {ReproEventSource.Events.StopEvent}");
ReproEventSource.Log.StopEvent();
});
}
void WaitALittle(TimeSpan timeSpan, string message)
{
Console.WriteLine($"WAITING {timeSpan.ToString()} - {message}");
Thread.Sleep(timeSpan);
Console.WriteLine($"END WAITING {timeSpan.ToString()} - {message}");
}
void EnsureProcessing()
{
if (!isProcessing)
{
Task.Factory.StartNew(() =>
{
WaitALittle(TimeSpan.FromMilliseconds(100), "before processing");
Console.WriteLine("Starting processing");
isProcessing = true;
session.Source.Process();
});
}
}
if (workAround)
{
LoadEventSource();
EnableWithoutOptions();
EnsureProcessing();
WaitALittle(TimeSpan.FromSeconds(4), "processing warmup");
}
EnableWithOptions();
EnsureProcessing();
WaitALittle(TimeSpan.FromSeconds(4), "before generating events");
GenerateEvents();
WaitALittle(TimeSpan.FromSeconds(4), "processing events");
}
}
public void ProcessEvents()
{
// setup process filter if any
TraceEventProviderOptions options = null;
if (_processId != -1)
{
options = new TraceEventProviderOptions()
{
ProcessIDFilter = new List <int>()
{
_processId
},
};
}
// register handlers for events on the session source
// --------------------------------------------------
// get exceptions
_session.Source.Clr.ExceptionStart += OnExceptionStart;
// get finalizers
_session.Source.Clr.TypeBulkType += OnTypeBulkType;
_session.Source.Clr.GCFinalizeObject += OnGCFinalizeObject;
// get thread contention time
_session.Source.Clr.ContentionStart += OnContentionStart;
_session.Source.Clr.ContentionStop += OnContentionStop;
// get GC details
_session.Source.Clr.GCHeapStats += OnGCHeapStats;
_session.Source.Clr.GCStop += OnGCStop;
_session.Source.Clr.GCAllocationTick += ClrOnGcAllocationTick;
// thread creation and run (but no exit)
_session.Source.Clr.ThreadCreating += ClrOnThreadCreating;
_session.Source.Clr.ThreadRunning += ClrOnThreadRunning;
// thread pool
_session.Source.Clr.ThreadPoolWorkingThreadCountStart += ClrOnThreadPoolWorkingThreadCountStart;
_session.Source.Clr.ThreadPoolWorkerThreadStart += ClrOnThreadPoolWorkerThreadStart;
_session.Source.Clr.ThreadPoolWorkerThreadStop += ClrOnThreadPoolWorkerThreadStop;
_session.Source.Clr.ThreadPoolEnqueue += ClrOnThreadPoolEnqueue;
_session.Source.Clr.ThreadPoolDequeue += ClrOnThreadPoolDequeue;
// decide which provider to listen to with filters if needed
_session.EnableProvider(
ClrTraceEventParser.ProviderGuid, // CLR provider
TraceEventLevel.Verbose,
(ulong)(
ClrTraceEventParser.Keywords.Contention | // thread contention timing
ClrTraceEventParser.Keywords.Threading | // threadpool events
ClrTraceEventParser.Keywords.Exception | // get the first chance exceptions
ClrTraceEventParser.Keywords.GCHeapAndTypeNames | // for finalizer type names
ClrTraceEventParser.Keywords.Type | // for TypeBulkType definition of types
ClrTraceEventParser.Keywords.GC // garbage collector details
),
options
);
// this is a blocking call until the session is disposed
_session.Source.Process();
}
public bool EnableProvider(string providerName, TraceEventLevel providerLevel = TraceEventLevel.Verbose, ulong matchAnyKeywords = ulong.MaxValue, TraceEventProviderOptions options = null)
{
if (this.isFakeAccessDenied)
{
throw new UnauthorizedAccessException("Access Denied.");
}
this.EnabledProviderNames.Add(providerName);
return(true);
}
public bool EnableProvider(TraceEventLevel level = TraceEventLevel.Verbose, ulong matchAnyKeywords = ulong.MaxValue, TraceEventProviderOptions options = null)
{
return(session.EnableProvider(WinINetProviderId, TraceEventLevel.Verbose, matchAnyKeywords, options));
}
public bool EnableProvider(string providerName, TraceEventLevel providerLevel = TraceEventLevel.Verbose, ulong matchAnyKeywords = ulong.MaxValue, TraceEventProviderOptions options = null)
{
return(this.session.EnableProvider(providerName, providerLevel, matchAnyKeywords, options));
}
public void ProcessEvents()
{
// setup process filter if any
TraceEventProviderOptions options = null;
if (_processId != -1)
{
options = new TraceEventProviderOptions()
{
ProcessIDFilter = new List <int>()
{
_processId
},
};
}
// register handlers for events on the session source
// --------------------------------------------------
if ((_filter & EventFilter.Exception) == EventFilter.Exception)
{
// get exceptions
_session.Source.Clr.ExceptionStart += OnExceptionStart;
}
if ((_filter & EventFilter.Finalizer) == EventFilter.Finalizer)
{
// get finalizers
_session.Source.Clr.TypeBulkType += OnTypeBulkType;
_session.Source.Clr.GCFinalizeObject += OnGCFinalizeObject;
}
if ((_filter & EventFilter.Contention) == EventFilter.Contention)
{
// get thread contention time
_session.Source.Clr.ContentionStart += OnContentionStart;
_session.Source.Clr.ContentionStop += OnContentionStop;
}
if ((_filter & EventFilter.ThreadStarvation) == EventFilter.ThreadStarvation)
{
// detect ThreadPool starvation
_session.Source.Clr.ThreadPoolWorkerThreadAdjustmentAdjustment += OnThreadPoolWorkerAdjustment;
}
if ((_filter & EventFilter.GC) == EventFilter.GC)
{
var source = _session.Source;
source.NeedLoadedDotNetRuntimes();
source.AddCallbackOnProcessStart((TraceProcess proc) =>
{
if (proc.ProcessID != _processId)
{
return;
}
proc.AddCallbackOnDotNetRuntimeLoad((TraceLoadedDotNetRuntime runtime) =>
{
runtime.GCEnd += (TraceProcess p, TraceGC gc) =>
{
NotifyCollection(gc);
};
});
});
}
if ((_filter & EventFilter.AllocationTick) == EventFilter.AllocationTick)
{
// sample every ~100 KB of allocations
_session.Source.Clr.GCAllocationTick += OnGCAllocationTick;
}
// decide which provider to listen to with filters if needed
_session.EnableProvider(
ClrTraceEventParser.ProviderGuid, // CLR provider
((_filter & EventFilter.AllocationTick) == EventFilter.AllocationTick) ?
TraceEventLevel.Verbose : TraceEventLevel.Informational,
(ulong)(
ClrTraceEventParser.Keywords.Contention | // thread contention timing
ClrTraceEventParser.Keywords.Threading | // threadpool events
ClrTraceEventParser.Keywords.Exception | // get the first chance exceptions
ClrTraceEventParser.Keywords.GCHeapAndTypeNames | // for finalizer type names
ClrTraceEventParser.Keywords.Type | // for TypeBulkType definition of types
ClrTraceEventParser.Keywords.GC // garbage collector details
),
options
);
// this is a blocking call until the session is disposed
_session.Source.Process();
}
public bool TraceETWTraceEventSource
(
string providerName
, string tracedFileName
, string[] traceEvents = null
, Action
<
long
, TraceEventDispatcher
, TraceEventSession
, TraceEvent
> onOneEventTracedOnceProcessAction = null
, TraceEventProviderOptions traceEventProviderOptions = null
, TraceEventSourceType traceEventSourceType = TraceEventSourceType.MergeAll
, TraceEventLevel traceEventLevel = TraceEventLevel.Always
, ulong matchKeywords = ulong.MaxValue
, bool needCountHits = false
)
{
var r = false;
if
(
traceEvents != null
&&
traceEvents.Length > 0
&&
onOneEventTracedOnceProcessAction != null
)
{
r = TraceEventsHelper
.TraceETWTraceEventSource
(
providerName
, tracedFileName
, traceEvents
, onOneEventTracedOnceProcessAction
, traceEventProviderOptions
, traceEventSourceType
, traceEventLevel
, matchKeywords
, needCountHits
);
}
return r;
}
public static bool EnableProviderForOperationalChannel(this TraceEventSession session, TraceEventProviderOptions options = null)
{
return(session.EnableProvider(ProviderName, TraceEventLevel.Informational, Operational.Keyword, options));
}
public static Task<bool> RealTimeTraceEventSessionAsync
(
string providerName
, string sessionName
, string tracingFileName = null
, string[] traceEvents = null
, Action
<
long
, TraceEventDispatcher
, TraceEventSession
, TraceEvent
> onOneEventTracedOnceProcessAction = null
, TraceEventProviderOptions traceEventProviderOptions = null
, TraceEventSessionOptions traceEventSessionOptions = TraceEventSessionOptions.Create
, TraceEventSourceType traceEventSourceType = TraceEventSourceType.MergeAll
, TraceEventLevel traceEventLevel = TraceEventLevel.Always
, ulong matchKeywords = ulong.MaxValue
, bool needCountHits = false
)
{
return
Task
.Factory
.StartNew<bool>
(
() =>
{
return
RealTimeTraceEventSession
(
providerName
, sessionName
, tracingFileName
, traceEvents
, onOneEventTracedOnceProcessAction
, traceEventProviderOptions
, traceEventSessionOptions
, traceEventSourceType
, traceEventLevel
, matchKeywords
, needCountHits
);
}
,
TaskCreationOptions.LongRunning
|
TaskCreationOptions.DenyChildAttach
);
}
public static bool RealTimeTraceEventSession
(
string providerName
, string sessionName
, string tracingFileName = null
, string[] traceEvents = null
, Action
<
long
, TraceEventDispatcher
, TraceEventSession
, TraceEvent
> onOneEventTracedOnceProcessAction = null
, TraceEventProviderOptions traceEventProviderOptions = null
, TraceEventSessionOptions traceEventSessionOptions = TraceEventSessionOptions.Create
, TraceEventSourceType traceEventSourceType = TraceEventSourceType.MergeAll
, TraceEventLevel traceEventLevel = TraceEventLevel.Always
, ulong matchKeywords = ulong.MaxValue
, bool needCountHits = false
)
{
var r = false;
if (!(TraceEventSession.IsElevated() ?? false))
{
Out.WriteLine("To turn on ETW events you need to be Administrator, please run from an Admin process.");
return(r);
}
var needTracingFile = !string.IsNullOrEmpty(tracingFileName);
if
(
traceEvents != null
&&
traceEvents.Length > 0
&&
onOneEventTracedOnceProcessAction != null
)
{
using
(
var session =
(
needTracingFile
?
new TraceEventSession
(
sessionName
, tracingFileName
, traceEventSessionOptions
)
{
StopOnDispose = true
}
:
new TraceEventSession
(
sessionName
, traceEventSessionOptions
)
{
StopOnDispose = true
}
)
)
{
using
(
var source =
(
needTracingFile
?
new ETWTraceEventSource(tracingFileName)
:
session.Source
)
)
{
long sequence = 0;
RegisterCallbacks
(
providerName
, traceEvents
, source
, session
, (x, y, z) =>
{
long id = 0;
if (needCountHits)
{
id = Interlocked.Increment(ref sequence);
}
onOneEventTracedOnceProcessAction
(
id
, x
, y
, z
);
}
);
var restarted = session
.EnableProvider
(
providerName
, traceEventLevel
, matchKeywords
, traceEventProviderOptions
);
source
.Process();
r = true;
}
}
}
return(r);
}
/// <summary>
/// CollectData doe will turn on logging of data from 'eventSourceName' to the file 'dataFileName'.
/// It will then call EventGenerator.CreateEvents and wait 12 seconds for it to generate some data.
/// </summary>
static void CollectData(string eventSourceName, string dataFileName)
{
// Today you have to be Admin to turn on ETW events (anyone can write ETW events).
if (!(TraceEventSession.IsElevated() ?? false))
{
Out.WriteLine("To turn on ETW events you need to be Administrator, please run from an Admin process.");
Debugger.Break();
return;
}
// As mentioned below, sessions can outlive the process that created them. Thus you need a way of
// naming the session so that you can 'reconnect' to it from another process. This is what the name
// is for. It can be anything, but it should be descriptive and unique. If you expect multiple versions
// of your program to run simultaneously, you need to generate unique names (e.g. add a process ID suffix)
// however this is dangerous because you can leave data collection on if the program ends unexpectedly.
//
// In this case we tell the session to place the data in MonitorToFileData.etl.
var sessionName = "SimpleTraceLogSession";
Out.WriteLine("Creating a '{0}' session writing to {1}", sessionName, dataFileName);
Out.WriteLine("Use 'logman query -ets' to see active sessions.");
Out.WriteLine("Use 'logman stop {0} -ets' to manually stop orphans.", sessionName);
using (var session = new TraceEventSession(sessionName, dataFileName)) // Since we give it a file name, the data goes there.
using (var kernelSession = new TraceEventSession(KernelTraceEventParser.KernelSessionName, Path.ChangeExtension(dataFileName, ".kernel.etl")))
{
/* BY DEFAULT ETW SESSIONS SURVIVE THE DEATH OF THE PROESS THAT CREATES THEM! */
// Unlike most other resources on the system, ETW session live beyond the lifetime of the
// process that created them. This is very useful in some scenarios, but also creates the
// very real possibility of leaving 'orphan' sessions running.
//
// To help avoid this by default TraceEventSession sets 'StopOnDispose' so that it will stop
// the ETW session if the TraceEventSession dies. Thus executions that 'clean up' the TraceEventSession
// will clean up the ETW session. This covers many cases (including throwing exceptions)
//
// However if the process is killed manually (including control C) this cleanup will not happen.
// Thus best practices include
//
// * Add a Control C handler that calls session.Dispose() so it gets cleaned up in this common case
// * use the same session name run-to-run so you don't create many orphans.
//
// By default TraceEventSessions are in 'create' mode where it assumes you want to create a new session.
// In this mode if a session already exists, it is stopped and the new one is created.
//
// Here we install the Control C handler. It is OK if Dispose is called more than once.
Console.CancelKeyPress += delegate(object sender, ConsoleCancelEventArgs e) { session.Dispose(); kernelSession.Dispose(); };
// Enable kernel events.
kernelSession.EnableKernelProvider(KernelTraceEventParser.Keywords.ImageLoad | KernelTraceEventParser.Keywords.Process | KernelTraceEventParser.Keywords.Thread);
// Enable my provider, you can call many of these on the same session to get events from other providers
// Turn on the eventSource given its name.
// Note we turn on Verbose level all keywords (ulong.MaxValue == 0xFFF....) and turn on stacks for
// this provider (for all events, until Windows 8.1 you can only turn on stacks for every event
// for a particular provider or no stacks)
var options = new TraceEventProviderOptions() { StacksEnabled = true };
var restarted = session.EnableProvider(eventSourceName, TraceEventLevel.Verbose, ulong.MaxValue, options);
if (restarted) // Generally you don't bother with this warning, but for the demo we do.
Out.WriteLine("The session {0} was already active, it has been restarted.", sessionName);
// We also turn on CLR events because we need them to decode Stacks and we also get exception events (and their stacks)
session.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Verbose, (ulong)ClrTraceEventParser.Keywords.Default);
// Start another thread that Causes MyEventSource to create some events
// Normally this code as well as the EventSource itself would be in a different process.
EventGenerator.CreateEvents();
// Also generate some exceptions so we have interesting stacks to look at
Thread.Sleep(100);
EventGenerator.GenerateExceptions();
Out.WriteLine("Waiting 12 seconds for events to come in.");
Thread.Sleep(12000);
// Because the process in question (this process) lives both before and after the time the events were
// collected, we don't have complete information about JIT compiled methods in that method. There are
// some methods that were JIT compiled before the session started (e.g. SimpleTraceLog.Main) for which
// we do not have information. We collect this by forcing a CLR 'rundown' which will dump method information
// for JIT compiled methods that were not present. If you know that the process of interest ends before
// data collection ended or that data collection started before the process started, then this is not needed.
Out.WriteLine("Forcing rundown of JIT methods.");
var rundownFileName = Path.ChangeExtension(dataFileName, ".clrRundown.etl");
using (var rundownSession = new TraceEventSession(sessionName + "Rundown", rundownFileName))
{
rundownSession.EnableProvider(ClrRundownTraceEventParser.ProviderGuid, TraceEventLevel.Verbose, (ulong)ClrRundownTraceEventParser.Keywords.Default);
// Poll until 2 second goes by without growth.
for (var prevLength = new FileInfo(rundownFileName).Length; ; )
{
Thread.Sleep(2000);
var newLength = new FileInfo(rundownFileName).Length;
if (newLength == prevLength) break;
prevLength = newLength;
}
}
Out.WriteLine("Done with rundown.");
}
Out.WriteLine("Merging the raw files into a single '{0}' file.", dataFileName);
TraceEventSession.MergeInPlace(dataFileName, Out);
Out.WriteLine("Merge complete.");
}
public static void ForceGC(string prefix, int processId, TextWriter tw, int completeTimeout = -1)
{
tw.WriteLine("{0}: proc {1}: starting", prefix, processId);
const int startTimeout = 15000;
completeTimeout = completeTimeout <= 0 ? 60000 : completeTimeout;
bool interrupted = false;
using (var startedEvent = new ManualResetEventSlim())
using (var session = new TraceEventSession("TriggerGC-" + processId))
{
session.Source.NeedLoadedDotNetRuntimes();
session.Source.AddCallbackOnProcessStart((TraceProcess proc) =>
{
proc.AddCallbackOnDotNetRuntimeLoad((TraceLoadedDotNetRuntime runtime) =>
{
runtime.GCStart += (TraceProcess p, TraceGC gc) =>
{
if (p.ProcessID == processId && gc.Reason.ToString().Contains("Induced"))
{
string xprefix = $"{prefix}: proc {p.ProcessID}: ";
tw.WriteLine("{0} GC #{1} {2} start at {3:N2}ms",
xprefix,
gc.Number,
gc.Reason,
gc.PauseStartRelativeMSec);
}
};
runtime.GCEnd += (TraceProcess p, TraceGC gc) =>
{
if (p.ProcessID == processId && gc.Reason.ToString().Contains("Induced"))
{
string xprefix = $"{prefix}: proc {p.ProcessID}: ";
tw.WriteLine("{0} GC #{1} {2} end, paused for {3:N2}ms",
xprefix,
gc.Number,
gc.Reason,
gc.PauseDurationMSec);
WriteFormattedTraceGC(tw, xprefix, gc);
WriteFormattedHeapStats(tw, xprefix, gc.HeapStats);
session.Source.StopProcessing();
}
};
});
});
var options = new TraceEventProviderOptions
{
ProcessIDFilter = new List <int> {
processId
}
};
session.EnableProvider(
ClrTraceEventParser.ProviderGuid,
TraceEventLevel.Informational,
(ulong)(ClrTraceEventParser.Keywords.GC | ClrTraceEventParser.Keywords.GCHeapCollect),
options);
// Sample: direct invocation of GCHeapCollect with a specific Process ID.
// Not used here, since we also need GC-events to listen to.
//session.CaptureState(ClrTraceEventParser.ProviderGuid,
// (long)(ClrTraceEventParser.Keywords.GCHeapCollect),
// filterType: unchecked((int)0x80000004),
// data: processId);
var eventReader = Task.Run(() =>
{
if (!Console.IsInputRedirected)
{
// Ensure we are cleanly detaching from victim process; otherwise it will be left hanging dormant.
Console.TreatControlCAsInput = false;
Console.CancelKeyPress += (sender, args) =>
{
args.Cancel = true;
// session.Stop(), not source.StopProcessing(), because the former is immediate, while the later is not.
interrupted = true;
session.Stop();
};
}
startedEvent.Set();
session.Source.Process();
});
if (!startedEvent.Wait(startTimeout))
{
tw.WriteLine("{0}: proc {1}: event reader did not start within {2:N2} seconds. Giving up.",
prefix, processId, startTimeout / 1000);
session.Stop();
return;
}
if (!eventReader.Wait(completeTimeout))
{
tw.WriteLine("{0}: proc {1}: garbage collection did not finish within {2:N2} seconds. Giving up.",
prefix, processId, completeTimeout / 1000);
session.Stop();
}
else if (interrupted)
{
tw.WriteLine("{0}: proc {1}: interrupted.", prefix, processId);
}
else
{
tw.WriteLine("{0}: proc {1}: complete.", prefix, processId);
}
}
}
