public void Start()
{
if (!(TraceEventSession.IsElevated() ?? false))
{
Trace.TraceWarning("WARNING! To turn on ETW events you need to be Administrator, please run from an Admin process.");
return;
}
// Same session name is reused to prevent multiple orphaned sessions in case if dispose is not done when test stopped in debug
// Important! Note that session can leave longer that the process and it is important to dispose it
session = new TraceEventSession(SessionName, null);
foreach (var provider in this.providers)
{
this.session.EnableProvider(provider);
}
this.session.StopOnDispose = true;
this.session.Source.Dynamic.All += Process;
this.session.Source.UnhandledEvents += Process;
Task.Run(() =>
{
// Blocking call. Will end when session is disposed
this.session.Source.Process();
});
Trace.TraceInformation("Etw session started");
}
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);
}
public CollectTraceEventsHelper(CommandLineOptions options)
{
if (TraceEventSession.IsElevated() != true)
throw new InvalidOperationException("Collecting perf events requires administrative privileges.");
if (options.ClrEvents.Events == ClrTraceEventParser.Keywords.None && options.KernelEvents == KernelTraceEventParser.Keywords.None)
throw new PowerArgs.ArgException("Must specify at least one CLR or kernel event.");
// verify session name
var existingSessions = TraceEventSession.GetActiveSessionNames();
if (options.Mode == ExecutionMode.Start && existingSessions.Contains(options.TestName))
throw new InvalidOperationException(string.Format("The session name '{0}' is already in use.", options.TestName));
else if (options.Mode == ExecutionMode.Stop && !existingSessions.Contains(options.TestName))
throw new InvalidOperationException(string.Format("The session name '{0}' does not exist.", options.TestName));
m_traceSession = new TraceEventSession(options.TestName, options.DataFile);
if (options.Mode == ExecutionMode.Start)
{
m_traceSession.BufferSizeMB = 512;
// starting a new session, enable providers
m_traceSession.EnableKernelProvider(options.KernelEvents);
m_traceSession.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Informational, (ulong)options.ClrEvents.Events);
// keep the session active after the process terminates
m_traceSession.StopOnDispose = false;
}
}
public void Dispose()
{
this.ReleaseProcessingSession();
if ( this.bufferSession != null ) {
this.bufferSession.Dispose();
this.bufferSession = null;
}
this.eventProviders = null;
}
public void Dispose()
{
if (this.session != null)
{
this.session.Dispose();
this.session = null;
}
Trace.TraceInformation("Etw session stopped");
}
private static void Main()
{
var session = new TraceEventSession("CHROMETRACE");
var source = new ETWTraceEventSource("CHROMETRACE", TraceEventSourceType.Session);
session.EnableProvider(ChromeEventParser.ProviderGuid, TraceEventLevel.Informational);
using (new ChromeEventParser(source))
{
source.Process();
}
}
/// <summary>
/// Turning on providers and creating files
/// </summary>
static void DataCollection(string dataFileName)
{
Out.WriteLine("Collecting 10 seconds of kernel and CLR events to a file, and then printing.");
Out.WriteLine();
Out.WriteLine("Start a .NET program while monitoring to see some events!");
Out.WriteLine();
if (TraceEventSession.IsElevated() != true)
{
Out.WriteLine("Must be elevated (Admin) to run this program.");
Debugger.Break();
return;
}
string kernelDataFileName = Path.ChangeExtension(dataFileName, ".kernel.etl");
// Create one user mode session and one kernel mode session
Out.WriteLine("Creating two raw files, one with kernel events and one with clr events.");
using (var userSession = new TraceEventSession("MonitorKernelAndClrEventsSession", dataFileName))
using (var kernelSession = new TraceEventSession(KernelTraceEventParser.KernelSessionName, kernelDataFileName))
{
// Set up Ctrl-C to stop both user mode and kernel mode sessions
Console.CancelKeyPress += delegate(object sender, ConsoleCancelEventArgs cancelArgs)
{
Out.WriteLine("Insuring all ETW sessions are stopped.");
kernelSession.Stop(true); // true means don't throw on error
userSession.Stop(true); // true means don't throw on error
// Since we don't cancel the Ctrl-C we will terminate the process as normal for Ctrl-C
Out.WriteLine("OnCtrl C handler ending.");
};
// Enable the events we care about for the kernel in the kernel session
// For this instant the session will buffer any incoming events.
kernelSession.EnableKernelProvider(
KernelTraceEventParser.Keywords.ImageLoad |
KernelTraceEventParser.Keywords.Process |
KernelTraceEventParser.Keywords.Thread);
// Enable the events we care about for the CLR (in the user session).
// unlike the kernel session, you can call EnableProvider on other things too.
// For this instant the session will buffer any incoming events.
userSession.EnableProvider(
ClrTraceEventParser.ProviderGuid,
TraceEventLevel.Informational,
(ulong)(ClrTraceEventParser.Keywords.Default));
Out.WriteLine("Collecting data for 10 seconds (run a .Net program to generate events).");
Thread.Sleep(10000);
Out.WriteLine("Stopping sessions");
} // Using clauses will insure that session are disposed (and thus stopped) before Main returns.
Out.WriteLine("Merging the raw files into a single '{0}' file.", dataFileName);
TraceEventSession.MergeInPlace(dataFileName, Out);
Out.WriteLine("Merge complete.");
}
private void CreateBufferSession()
{
this.currentFilename = Path.Combine(this.traceFolder, Guid.NewGuid() + ".etl");
this.bufferSession = new TraceEventSession(
SessionName, this.currentFilename, TraceEventSessionOptions.Create
);
foreach (var provider in eventProviders) {
provider.EnableProvider(this.bufferSession);
}
Trace.WriteLine(String.Format("Starting buffering on: {0}", this.currentFilename));
}
private void StartListening()
{
Console.WriteLine( "Starting Listening for events" );
_session = new TraceEventSession( "MyRealTimeSession" ); // Create a session to listen for events
_session.Source.Dynamic.All += delegate(TraceEvent data) // Set Source (stream of events) from session.
{ // Get dynamic parser (knows about EventSources)
// Subscribe to all EventSource events
//OutputEvent( data.Dump() );
if (data.EventName != "JobStart" && data.EventName != "JobEnd" && data.EventName != "Step") return;
if (_hubConnection != null && _hubConnection.State == ConnectionState.Connected)
{
string jsonData = data.PayloadByName( "jsonData" ) as string;
object jobId = data.PayloadByName( "jobId" );
object jobRunId = data.PayloadByName( "jobRunId" );
Stopwatch watch = new Stopwatch();
watch.Restart();
if (string.IsNullOrEmpty( jsonData ))
{
if (data.EventName == "JobStart")
{
object jobName = data.PayloadByName( "jobName" ) as string;
_centralLogHubProxy.Invoke( data.EventName, jobId, jobName, jobRunId ).Wait();
}
else
{
_centralLogHubProxy.Invoke( data.EventName, jobId, jobRunId ).Wait();
}
}
else
{
_centralLogHubProxy.Invoke( data.EventName, jobId, jobRunId, jsonData ).Wait();
}
watch.Stop();
//Console.WriteLine( "sending took {0}ms",watch.ElapsedMilliseconds);
}
};
_session.StopOnDispose = true;
var eventSourceGuid = TraceEventProviders.GetEventSourceGuidFromName( GlobalDefines.EVENT_SOURCE_NAME ); // Get the unique ID for the eventSouce.
_session.EnableProvider( eventSourceGuid ); // Enable MyEventSource.
_session.Source.Process(); // Wait for incoming events (forever).
}
protected override void AttachToEvents(TraceEventSession session, Benchmark benchmark)
{
var expected = benchmark.Target.Method.DeclaringType.Namespace + "." +
benchmark.Target.Method.DeclaringType.Name;
Logger.WriteLine();
Logger.WriteLineHeader(LogSeparator);
Logger.WriteLineInfo($"{benchmark.DisplayInfo}");
Logger.WriteLineHeader(LogSeparator);
session.Source.Clr.MethodInliningSucceeded += jitData =>
{
// Inliner = the parent method (the inliner calls the inlinee)
// Inlinee = the method that is going to be "inlined" inside the inliner (it's caller)
object ignored;
if (StatsPerProcess.TryGetValue(jitData.ProcessID, out ignored))
{
var shouldPrint = jitData.InlinerNamespace == expected ||
jitData.InlineeNamespace == expected;
if (shouldPrint)
{
Logger.WriteLineHelp($"Inliner: {jitData.InlinerNamespace}.{jitData.InlinerName} - {jitData.InlinerNameSignature}");
Logger.WriteLineHelp($"Inlinee: {jitData.InlineeNamespace}.{jitData.InlineeName} - {jitData.InlineeNameSignature}");
Logger.WriteLineHeader(LogSeparator);
}
}
};
session.Source.Clr.MethodInliningFailed += jitData =>
{
object ignored;
if (StatsPerProcess.TryGetValue(jitData.ProcessID, out ignored))
{
var shouldPrint = jitData.InlinerNamespace == expected ||
jitData.InlineeNamespace == expected;
if (shouldPrint)
{
Logger.WriteLineError($"Inliner: {jitData.InlinerNamespace}.{jitData.InlinerName} - {jitData.InlinerNameSignature}");
Logger.WriteLineError($"Inlinee: {jitData.InlineeNamespace}.{jitData.InlineeName} - {jitData.InlineeNameSignature}");
// See https://blogs.msdn.microsoft.com/clrcodegeneration/2009/10/21/jit-etw-inlining-event-fail-reasons/
Logger.WriteLineError($"Fail Reason: {jitData.FailReason}");
Logger.WriteLineHeader(LogSeparator);
}
}
};
}
public void Start(Benchmark benchmark)
{
ProcessIdsUsedInRuns.Clear();
statsPerProcess.Clear();
var sessionName = GetSessionName("GC", benchmark, benchmark.Parameters);
session = new TraceEventSession(sessionName);
session.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Verbose,
(ulong)(ClrTraceEventParser.Keywords.GC));
// The ETW collection thread starts receiving events immediately, but we only
// start aggregating them after ProcessStarted is called and we know which process
// (or processes) we should be monitoring. Communication between the benchmark thread
// and the ETW collection thread is through the statsPerProcess concurrent dictionary
// and through the TraceEventSession class, which is thread-safe.
Task.Factory.StartNew(StartProcessingEvents, TaskCreationOptions.LongRunning);
}
static void Main(string[] args)
{
// create a new real-time ETW trace session
using ( var session = new TraceEventSession(SessionName) ) {
// enable IIS ETW provider and set up a new trace source on it
session.EnableProvider(IISLogTraceEventParser.ProviderName, TraceEventLevel.Verbose);
using ( var traceSource = new ETWTraceEventSource(SessionName, TraceEventSourceType.Session) ) {
Console.WriteLine("Session started, listening for events...");
var parser = new IISLogTraceEventParser(traceSource);
parser.IISLog += OnIISRequest;
traceSource.Process();
Console.ReadLine();
traceSource.StopProcessing();
}
}
}
public void Writing_Message_To_Etw() {
var fpath = Path.Combine(Path.GetTempPath(), "_etwnlogtest.etl");
using (var session = new TraceEventSession("SimpleMonitorSession", fpath)) {
//var eventSourceGuid = TraceEventProviders.GetEventSourceGuidFromName("MyEventSource");
var eventSourceGuid = TraceEventProviders.GetEventSourceGuidFromName("LowLevelDesign-NLogEtwSource");
session.EnableProvider(eventSourceGuid);
// send events to session
var logger = LogManager.GetLogger("A");
logger.Debug("test-debug");
logger.Info("test-info");
logger.Warn("test-warn");
logger.Error("test-error");
logger.Fatal("test-fatal");
Thread.Sleep(5000);
}
var collectedEvents = new List<ExtendedEtwEvent>(5);
using (var source = new ETWTraceEventSource(fpath)) {
var parser = new DynamicTraceEventParser(source);
parser.All += delegate(TraceEvent data) {
collectedEvents.Add(new ExtendedEtwEvent {
EventId = (int)data.ID,
Level = data.Level,
LoggerName = (String)data.PayloadByName("LoggerName"),
Message = (String)data.PayloadByName("Message")
});
};
source.Process();
}
File.Delete(fpath);
// assert collected events
var expectedEvents = new ExtendedEtwEvent[] {
new ExtendedEtwEvent { EventId = 1, LoggerName = "A", Level = TraceEventLevel.Verbose, Message = "DEBUG|A|test-debug" },
new ExtendedEtwEvent { EventId = 2, LoggerName = "A", Level = TraceEventLevel.Informational, Message = "INFO|A|test-info" },
new ExtendedEtwEvent { EventId = 3, LoggerName = "A", Level = TraceEventLevel.Warning, Message = "WARN|A|test-warn" },
new ExtendedEtwEvent { EventId = 4, LoggerName = "A", Level = TraceEventLevel.Error, Message = "ERROR|A|test-error" },
new ExtendedEtwEvent { EventId = 5, LoggerName = "A", Level = TraceEventLevel.Critical, Message = "FATAL|A|test-fatal" }
};
Assert.Equal(collectedEvents, expectedEvents);
}
private static void Main(string[] args)
{
string sessionName = "mySession";
using (MyEventSource source = new MyEventSource())
using (TraceEventSession session = new TraceEventSession(sessionName, null)) // the null second parameter means 'real time session'
using (ETWTraceEventSource eventSource = new ETWTraceEventSource(sessionName, TraceEventSourceType.Session))
{
DynamicTraceEventParser parser = new DynamicTraceEventParser(eventSource);
parser.All += delegate(TraceEvent data)
{
Console.WriteLine("Event name:{0}. Payload:{1}.", data.EventName, data.PayloadValue(0));
};
session.EnableProvider(source.Guid);
source.String("Hello world");
source.Int(123);
eventSource.Process();
}
}
public void Start()
{
using (var session = new TraceEventSession("netric"))
{
session.EnableProvider(NetricInterceptWebRequestTraceEventParser.ProviderName);
session.EnableProvider(NetricInterceptClrTraceEventParser.ProviderName);
using (var source = new ETWTraceEventSource("netric", TraceEventSourceType.Session))
{
var requestTraceEventParser = new NetricInterceptWebRequestTraceEventParser(source);
requestTraceEventParser.OnBegin+= x => _receiverActor.Tell(new EtwEventProcessingActor.RequestBegin(x));
requestTraceEventParser.OnEnd += x => _receiverActor.Tell(new EtwEventProcessingActor.RequestEnd(x));
var clrTraceEventParser = new NetricInterceptClrTraceEventParser(source);
clrTraceEventParser.OnEnter += x => _receiverActor.Tell(new EtwEventProcessingActor.MethodEnter(x));
clrTraceEventParser.OnLeave += x => _receiverActor.Tell(new EtwEventProcessingActor.MethodLeave(x));
source.Process();
}
}
}
public void Writing_Message_To_Etw()
{
var resetEvent = new ManualResetEvent(false);
var fpath = Path.Combine(Path.GetTempPath(), "_etwnlogtest.etl");
using (var session = new TraceEventSession("SimpleMonitorSession", fpath)) {
session.EnableProvider(providerId);
// send events to session
var logger = LogManager.GetLogger("A");
logger.Debug("test-debug");
logger.Info("test-info");
logger.Warn("test-warn");
logger.Error("test-error");
logger.Fatal("test-fatal");
}
var collectedEvents = new List<SimpleEtwEvent>(5);
using (var source = new ETWTraceEventSource(fpath)) {
source.UnhandledEvents += delegate(TraceEvent data) {
collectedEvents.Add(new SimpleEtwEvent { Level = data.Level, Message = data.FormattedMessage });
if (collectedEvents.Count == 5)
{
resetEvent.Set();
}
};
source.Process();
}
File.Delete(fpath);
// assert collected events
var expectedEvents = new SimpleEtwEvent[] {
new SimpleEtwEvent { Level = TraceEventLevel.Verbose, Message = "DEBUG|A|test-debug" },
new SimpleEtwEvent { Level = TraceEventLevel.Informational, Message = "INFO|A|test-info" },
new SimpleEtwEvent { Level = TraceEventLevel.Warning, Message = "WARN|A|test-warn" },
new SimpleEtwEvent { Level = TraceEventLevel.Error, Message = "ERROR|A|test-error" },
new SimpleEtwEvent { Level = TraceEventLevel.Critical, Message = "FATAL|A|test-fatal" }
};
resetEvent.WaitOne(20000);
Assert.Equal(expectedEvents.Length, collectedEvents.Count);
Assert.Equal(expectedEvents, collectedEvents);
}
public void Dispose()
{
if (!this.disposed)
{
this.disposing = true;
if (this.eventsLost > 0)
{
this.logger.TraceEventServiceProcessEventsLost(this.sessionName, this.eventsLost);
}
// By disposing source we force this.source.Process() to exit and end workerTask
// Note that source reference is not released rigth after Dispose() to avoid 'CallbackOnCollectedDelegate'exception
// that might be thrown before Process() ends.
this.source.Dispose();
this.workerTask.Wait();
this.session.Dispose();
this.session = null;
this.source = null;
this.disposed = true;
}
}
static void Main(string[] args)
{
Console.WriteLine("\n FedAuth Debugger\n\n");
using (var session = new TraceEventSession("FedAuthDebuggerApp"))
{
session.Source.Dynamic.All += delegate(TraceEvent data)
{
if (!String.IsNullOrEmpty(data.FormattedMessage))
{
Console.WriteLine(" {0} - {1}", data.TimeStamp.ToString("HH:mm:ss"), data.FormattedMessage);
}
};
session.EnableProvider(
TraceEventProviders.GetEventSourceGuidFromName("FedAuthDebugger-Session"));
session.EnableProvider(
TraceEventProviders.GetEventSourceGuidFromName("FedAuthDebugger-Federation"));
session.Source.Process();
}
Console.ReadLine();
}
static void Main(string[] args)
{
using (var session = new TraceEventSession("TelemetrySession"))
{
session.EnableProvider("ETW-Insturmentation-Events");
session.Source.Dynamic.AddCallbackForProviderEvent("ETW-Insturmentation-Events", "StartTelemetry/Start", (data) =>
{
Console.WriteLine(data.ToString());
});
session.Source.Dynamic.AddCallbackForProviderEvent("ETW-Insturmentation-Events", "StartTelemetry/Stop", (data) =>
{
Console.WriteLine(data.ToString());
});
session.Source.Dynamic.AddCallbackForProviderEvent("ETW-Insturmentation-Events", "Info", (data) =>
{
Console.WriteLine(data.ToString());
});
session.Source.Process();
}
}
public void CreateETWLogger()
{
const string config = @"
<loggers>
<log name=""etwLogger"" type=""etl"">
<source name=""Microsoft-Diagnostics-Tracing-Logging"" />
</log>
</loggers>";
LogManager.AllowEtwLogging = AllowEtwLoggingValues.Enabled;
LogManager.Start();
Assert.IsTrue(LogManager.SetConfiguration(config));
Assert.AreEqual(1, LogManager.singleton.fileLoggers.Count);
var theLogger = LogManager.GetFileLogger("etwLogger") as ETLFileLogger;
Assert.IsNotNull(theLogger);
string filename = Path.GetFileName(theLogger.Filename);
Assert.AreEqual(filename, "etwLogger.etl");
var session = new TraceEventSession(ETLFileLogger.SessionPrefix + "etwLogger",
TraceEventSessionOptions.Attach);
Assert.IsNotNull(session);
Assert.AreEqual(LogManager.DefaultFileBufferSizeMB, session.BufferSizeMB);
session.Dispose();
LogManager.Shutdown();
}
public static void Run()
{
var monitoringTimeSec = 10;
Out.WriteLine("******************** KernelAndClrMonitor DEMO (Win7) ********************");
Out.WriteLine("Printing both Kernel and CLR (user mode) events simultaneously");
Out.WriteLine("The monitor will run for a maximum of {0} seconds", monitoringTimeSec);
Out.WriteLine("Press Ctrl-C to stop monitoring early.");
Out.WriteLine();
Out.WriteLine("Start a .NET program to see some events!");
Out.WriteLine();
if (TraceEventSession.IsElevated() != true)
{
Out.WriteLine("Must be elevated (Admin) to run this program.");
Debugger.Break();
return;
}
// Set up Ctrl-C to stop both user mode and kernel mode sessions
Console.CancelKeyPress += (object sender, ConsoleCancelEventArgs cancelArgs) =>
{
StopSessions();
cancelArgs.Cancel = true;
};
// Note that because there are different sessions, the events may not be printed
// in time order since the different sessions may flush their buffers at different
// times. If you care, you must buffer the events and order them by event
// timestamp. Note that the timestamps however ARE accurate.
Out.WriteLine("Setup up threads to process the events");
// start processing kernel events on a thread pool thread
var task1 = Task.Run(() =>
{
// Note that TraceEventSession and EtwTraceEventParser are IN GENERAL NOT THREADSAFE,
// Normally this is not a hardship you just set up the session TraceDispacher on one
// thread. It is OK to call a session's Dispose() and 'Enable and Disable provider APIS
// from another thread, but things associated with ETWTraceEventSource and TraceEventParsers
// should all be on the same thread.
Out.WriteLine("Kernel event Thread Starting");
Out.WriteLine("Enabling Image load, thread and process kernel events.");
using (s_kernelSession = new TraceEventSession(KernelTraceEventParser.KernelSessionName))
{
// Enable the events we care about for the kernel in the kernel session
// For this instant the session will buffer any incoming events.
// If you only have to run on Win8 systems you can use one session for both.
// Here we turn in process, thread and Image load events.
s_kernelSession.EnableKernelProvider(
KernelTraceEventParser.Keywords.ImageLoad |
KernelTraceEventParser.Keywords.Process |
KernelTraceEventParser.Keywords.Thread);
// You should do all processing from a single source on a single thread.
// Thus call calls to .Source, or Process() should be on the same thread.
s_kernelSession.Source.Kernel.All += Print;
#if DEBUG
// in debug builds it is useful to see any unhandled events because they could be bugs.
s_kernelSession.Source.UnhandledEvents += Print;
#endif
// process events until Ctrl-C is pressed
Out.WriteLine("Waiting on kernel events.");
s_kernelSession.Source.Process();
}
Out.WriteLine("Thread 1 dieing");
});
// start processing CLR events on a thread pool thread
var task2 = Task.Run(() =>
{
// Note that TraceEventSession and EtwTraceEventParser are IN GENERAL NOT THREADSAFE,
// Normally this is not a hardship you just set up the session TraceDispacher on one
// thread. It is OK to call a session's Dispose() and 'Enable and Disable provider APIS
// from another thread, but things associated with ETWTraceEventSource and TraceEventParsers
// should all be on the same thread.
using (s_userSession = new TraceEventSession("MonitorKernelAndClrEventsSession"))
{
Out.WriteLine("Enabling CLR GC and Exception events.");
// Enable the events we care about for the CLR (in the user session).
// unlike the kernel session, you can call EnableProvider on other things too.
// For this instant the ;session will buffer any incoming events.
s_userSession.EnableProvider(
ClrTraceEventParser.ProviderGuid,
TraceEventLevel.Informational,
(ulong)(ClrTraceEventParser.Keywords.GC | ClrTraceEventParser.Keywords.Exception));
// s_userSession.Source.Clr.GCHeapStats += (GCHeapStatsTraceData data) => Out.WriteLine(" ", data.GenerationSize0);
Out.WriteLine("User event Thread Starting");
s_userSession.Source.Clr.All += Print;
#if DEBUG
// in debug builds it is useful to see any unhandled events because they could be bugs.
s_userSession.Source.UnhandledEvents += Print;
#endif
// process events until Ctrl-C is pressed or timeout expires
Out.WriteLine("Waiting on user events.");
s_userSession.Source.Process();
}
Out.WriteLine("Thread 2 dieing");
});
// Set up a timer to stop processing after monitoringTimeSec
var timer = new Timer(delegate(object state)
{
Out.WriteLine("Stopped Monitoring after {0} sec", monitoringTimeSec);
StopSessions();
}, null, monitoringTimeSec * 1000, Timeout.Infinite);
// Wait until tasks are complete
Out.WriteLine("Waiting for processing tasks to complete");
Task.WaitAll(task1, task2);
Out.WriteLine("Monitoring stopped");
timer.Dispose();
}
public static void Run()
{
int monitoringTimeSec = 10;
if (Environment.OSVersion.Version.Major * 10 + Environment.OSVersion.Version.Minor < 62)
{
Out.WriteLine("This demo only works on Win8 / Win 2012 an above)");
return;
}
// 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;
}
string outputFileName = "ReloggerMonitorOutput.etl";
if (File.Exists(outputFileName))
File.Delete(outputFileName);
Out.WriteLine("******************** Simple Relogger DEMO ********************");
Out.WriteLine("This program shows how you can monitor an ETW stream in real time.");
Out.WriteLine("And conditionally pass the events on to a ETL file");
Out.WriteLine("Ctrl-C will end earlier");
Out.WriteLine();
Out.WriteLine("Please run some managed code while collection is happening...");
Out.WriteLine();
// To listen to ETW events you need a session, which allows you to control which events will be produced
// Note that it is the session and not the source that buffers events, and by default sessions will buffer
// 64MB of events before dropping events. Thus even if you don't immediately connect up the source and
// read the events you should not lose them.
//
// As mentioned below, sessions can outlive the process that created them. Thus you may 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.
var sessionName = "SimpleMontitorSession";
Out.WriteLine("Creating a '{0}' session", sessionName);
using (var session = new TraceEventSession(sessionName))
{
// Enable the events we care about for the kernel in the kernel session
// For this instant the session will buffer any incoming events.
// This has to be first, and it will fail if you are not on Win8.
session.EnableKernelProvider(
KernelTraceEventParser.Keywords.ImageLoad |
KernelTraceEventParser.Keywords.Process |
KernelTraceEventParser.Keywords.Thread);
// A relogger is a TraceEventSource and acts much like an ETWTraceEventSource, with extra Write APIS.
// Thus you get a callback on any event you want.
// Only things that you call 'WriteEvent' on will end up in the output file.
var relogger = new ETWReloggerTraceEventSource(sessionName, TraceEventSourceType.Session, outputFileName);
// Here we set up the callbacks we want in the output file. In this case all GC allocation Tick
// events for 'String' as well as any ExceptionStart events.
relogger.Clr.GCAllocationTick += delegate(GCAllocationTickTraceData data)
{
if (data.TypeName == "System.String")
relogger.WriteEvent(data);
};
relogger.Clr.ExceptionStart += delegate(ExceptionTraceData data)
{
relogger.WriteEvent(data);
};
// We also keep the image load events for DLL with 'clr' in their name.
relogger.Kernel.ImageGroup += delegate(ImageLoadTraceData data)
{
if (0 <= data.FileName.IndexOf("clr", StringComparison.OrdinalIgnoreCase))
relogger.WriteEvent(data);
};
#if false // Turn on to get debugging on unhandled events.
relogger.UnhandledEvents += delegate(TraceEvent data)
{
Console.WriteLine("Unknown Event " + data);
};
#endif
// Allow the test to be terminated with Ctrl-C cleanly.
Console.CancelKeyPress += delegate(object sender, ConsoleCancelEventArgs e) { session.Dispose(); };
// Set up a timer to stop processing after monitoringTimeSec
var timer = new Timer(delegate(object state)
{
Out.WriteLine("Stopped after {0} sec", monitoringTimeSec);
session.Dispose();
}, null, monitoringTimeSec * 1000, Timeout.Infinite);
// Turn on the events to the provider. In this case most CLR events
Out.WriteLine("**** Turn on CLR Etw Providers. Run managed code to see events.");
session.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Verbose, (ulong)ClrTraceEventParser.Keywords.Default);
// 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()'.
Out.WriteLine("**** Start listening for events from the Microsoft-Demos-SimpleMonitor provider.");
Out.WriteLine("The monitor will run for a maximum of {0} seconds. Run managed code for more output.", monitoringTimeSec);
relogger.Process();
Out.WriteLine();
Out.WriteLine("Stopping the collection of events.");
timer.Dispose(); // Turn off the timer.
}
Out.WriteLine("Monitoring complete, only certain CLR events put in the output file.");
Out.WriteLine("The output ETL file: {0}", Path.GetFullPath(outputFileName));
Out.WriteLine();
if (!File.Exists(outputFileName))
{
Out.WriteLine("Error: No output file was generated (did you run anything during the collection?");
return;
}
// Show what was actually produced in the filtered file.
DataProcessing(outputFileName);
}
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 { }
}
// 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
{
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 { }
}
}
}
else if (data.ProviderName == "Microsoft-IE" &&
IEEvents.ContainsKey(data.EventName))
{
keep = true;
}
else if (data.ProviderName == "Microsoft-Windows-WinINet" &&
WinInetEvents.ContainsKey(data.EventName))
{
keep = true;
}
else if (customProviders.ContainsKey(data.ProviderName) &&
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"] = data.EventName;
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 { }
};
if (body_dir.Length > 0)
{
session.EnableProvider("Microsoft-Windows-WinInet-Capture");
}
var WinInetProviderFilterOptions = new TraceEventProviderOptions()
{
EventIDsToEnable = new List <int>(WinInetEvents.Values)
};
session.EnableProvider("Microsoft-Windows-WinINet", TraceEventLevel.Informational, ulong.MaxValue, WinInetProviderFilterOptions);
var IEProviderFilterOptions = new TraceEventProviderOptions()
{
EventIDsToEnable = new List <int>(IEEvents.Values)
};
session.EnableProvider("Microsoft-IE", TraceEventLevel.Informational, 0x4001302, IEProviderFilterOptions);
if (customProviders.Count > 0)
{
foreach (var provider in customProviders)
{
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 void Run()
{
Out.WriteLine("******************** ObserveEventSource DEMO ********************");
Out.WriteLine("This program Demos using the reactive framework (IObservable) to monitor");
Out.WriteLine("EventSource events in real time, parsing their payloads dynamically.");
Out.WriteLine();
Out.WriteLine("The program has an EventSource that generates two kinds of events for 10 secs.");
Out.WriteLine("while another part of the program reads them using IObservables and prints");
Out.WriteLine("their parsed payload values. ");
Out.WriteLine();
if (TraceEventSession.IsElevated() != true)
{
Out.WriteLine("Must be elevated (Admin) to run this method.");
Debugger.Break();
return;
}
var monitoringTimeSec = 15;
Out.WriteLine("The monitor will run for a maximum of {0} seconds", monitoringTimeSec);
Out.WriteLine("Press Ctrl-C to stop monitoring.");
// create a real time user mode session
using (var userSession = new TraceEventSession("ObserveEventSource"))
{
// Set up Ctrl-C to stop both user mode and kernel mode sessions
SetupCtrlCHandler(() => { if (userSession != null) userSession.Stop(); });
// Turn on the Microsoft-Demos-SimpleMonitor provider
userSession.EnableProvider("Microsoft-Demos-SimpleMonitor");
// Create a stream of the 'MyFirstEvent' event source events and print their payloads
IObservable<TraceEvent> firstEventStream = userSession.Source.Dynamic.Observe("Microsoft-Demos-SimpleMonitor", "MyFirstEvent");
firstEventStream.Subscribe(onNext: ev => Out.WriteLine("FIRST_EVENTS : MyName: '{0}' MyId: {1}", ev.PayloadByName("MyName"), ev.PayloadByName("MyId")));
// Create a stream of the 'MySecond'Event' event source events and print their payloads
IObservable<TraceEvent> secondEventStream = userSession.Source.Dynamic.Observe("Microsoft-Demos-SimpleMonitor", "MySecondEvent");
secondEventStream.Subscribe(onNext: ev => Out.WriteLine("SECOND_EVENTS : MyId: {0}", ev.PayloadByName("MyId")));
// For debugging purposes, print every event from the SimpleMonitor stream
IObservable<TraceEvent> allEventStream = userSession.Source.Dynamic.Observe(null);
allEventStream.Subscribe(onNext: ev => Out.WriteLine("FROM_EVENTSOURCE: {0}/{1} ", ev.ProviderName, ev.EventName));
// It is also useful for debugging purposes to see any events that entered by were not handled by any parser. These can be bugs.
IObservable<TraceEvent> unhandledEventStream = userSession.Source.ObserveUnhandled();
unhandledEventStream.Subscribe(onNext: ev => Out.WriteLine("UNHANDLED : {0}/{1} ", ev.ProviderName, ev.EventName));
// Start Generate some events so we have something to see
Producer.EventGenerator.CreateEvents();
// Set up a timer to stop processing after monitoringTimeSec
IObservable<long> timer = Observable.Timer(new TimeSpan(0, 0, monitoringTimeSec));
timer.Subscribe(delegate
{
Out.WriteLine("Stopped after {0} sec", monitoringTimeSec);
userSession.Dispose();
});
// OK we are all set up, time to listen for events and pass them to the observers.
userSession.Source.Process();
}
Out.WriteLine("Done with program.");
}
/// <summary>
/// Listens the asynchronous.
/// </summary>
/// <param name="ct">The ct.</param>
/// <returns></returns>
private async Task ListenAsync(CancellationToken ct)
{
#region Log
Log(LogLevel.Information, $@"Creating a '{EtwConstants.SessionName}' session
Use 'logman query -ets' to see active sessions.
Use 'logman query -ets ""{EtwConstants.SessionName}""' for details
Use 'logman stop {EtwConstants.SessionName} -ets' to manually stop orphans.", null);
#endregion // Log
#region Documentation
/*****************************************************
* To listen to ETW events you need a session,
* which allows you to control which events will be produced
* Note that it is the session and not the source
* that buffers events, and by default sessions will buffer
* 64MB of events before dropping events.
* Thus even if you don't immediately connect up the source and
* read the events you should not lose them.
*
* As mentioned below, sessions can outlive the process that created them.
* Thus you may 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.
*****************************************************/
#endregion // Documentation
_session = new TraceEventSession(EtwConstants.SessionName);
_session.StopOnDispose = true;
#region Documentation
/*****************************************************
* 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 (say your program 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.
*****************************************************/
#endregion // Documentation
Console.CancelKeyPress += (sender, e) => _session.Dispose();
#region UnhandledEvents
_session.Source.UnhandledEvents += (TraceEvent data) =>
{
if ((int)data.ID != 0xFFFE) // The EventSource manifest events show up as unhanded, filter them out.
Log(LogLevel.Warning, $"Unhandled {data.ToString()}", null);
};
#endregion // UnhandledEvents
#region _session.EnableProvider(...)
#region Documentation
/*****************************************************
* At this point we have created a TraceEventSession,
* hooked it up to a TraceEventSource, and hooked the
* TraceEventSource to a TraceEventParser
* (you can do several of these), and then hooked up callbacks
* up to the TraceEventParser (again you can have several).
* However we have NOT actually told any
* provider (EventSources) to actually send any events
* to our TraceEventSession.
* We do that now.
* Enable my provider, you can call many of these
* on the same session to get events from other providers.
* Because this EventSource did not define any keywords,
* I can only turn on all events or none.
* var restarted = session.EnableProvider(ETW_PROVIDER_NAME);
*****************************************************/
#endregion // Documentation
var restarted = _session.EnableProvider(
VisualRxEventSource.ProviderGuid,
TraceEventLevel.Always);
#region Validation
if (restarted) // Generally you don't bother with this warning.
{
Log(LogLevel.Warning,
$@"The session {EtwConstants.SessionName} was already active,
it has been restarted.", null);
}
#endregion // Validation
#endregion // _session.EnableProvider(...)
#region IObservable<TraceEvent> sending = ...
IObservable<TraceEvent> sending =
_session.Source.Dynamic.Observe(
VisualRxEventSource.ProviderName,
nameof(VisualRxEventSource.Send));
sending.Select(m =>
{
var json = m.FormattedMessage;
var marble = JsonConvert.DeserializeObject<Marble>(json, _setting);
return marble;
})
.Subscribe(_subject);
#endregion // IObservable<TraceEvent> sending = ...
// cancel the session
ct.Register(() => _session.Source.Dispose());
// 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 t = Task.Factory.StartNew(() =>
{
try
{
_session.Source.Process();
}
catch (ThreadAbortException) { }
Log(LogLevel.Information, $"Session [{EtwConstants.SessionName}] Stopped.", null);
}, TaskCreationOptions.LongRunning);
await Task.Delay(10); // make sure that session.Source.Process() is listening (avoid racing)
}
internal static void EnsureStopped()
{
using (var session = new TraceEventSession("EventSourceTestSession", "EventSourceTestData.etl"))
session.Stop();
}
/// <summary>
/// This is a demo of using TraceEvent to activate a 'real time' provider that is listening to
/// the MyEventSource above. Normally this event source would be in a different process, but
/// it also works if this process generate the events and I do that here for simplicity.
/// </summary>
public static int Run()
{
Out.WriteLine("******************** SimpleEventSourceMonitor DEMO ********************");
Out.WriteLine("This program generates processes and displays EventSource events");
Out.WriteLine("using the ETW REAL TIME pipeline. (thus no files are created)");
Out.WriteLine();
// 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(-1);
}
// To listen to ETW events you need a session, which allows you to control which events will be produced
// Note that it is the session and not the source that buffers events, and by default sessions will buffer
// 64MB of events before dropping events. Thus even if you don't immediately connect up the source and
// read the events you should not lose them.
//
// As mentioned below, sessions can outlive the process that created them. Thus you may 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.
var sessionName = "SimpleMonitorSession";
Out.WriteLine("Creating a '{0}' session", sessionName);
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))
{
/* 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 (say your program 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(); };
// To demonstrate non-trivial event manipulation, we calculate the time delta between 'MyFirstEvent and 'MySecondEvent'
// firstEventTimeMSec remembers all the 'MyFirstEvent' arrival times (indexed by their ID)
var firstEventTimeMSec = new Dictionary <int, double>();
/*****************************************************************************************************/
// Hook up events. To so this first we need a 'Parser. which knows how to part the events of a particular Event Provider.
// In this case we get a DynamicTraceEventSource, which knows how to parse any EventSource provider. This parser
// is so common, that TraceEventSource as a shortcut property called 'Dynamic' that fetches this parsers.
// For debugging, and demo purposes, hook up a callback for every event that 'Dynamic' knows about (this is not EVERY
// event only those know about by DynamiceTraceEventParser). However the 'UnhandledEvents' handler below will catch
// the other ones.
session.Source.Dynamic.All += delegate(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;
Out.WriteLine("GOT Event Delay={0:f1}sec: {1} ", delay, data.ToString());
};
// Add logic on what to do when we get "MyFirstEvent"
session.Source.Dynamic.AddCallbackForProviderEvent("Microsoft-Demos-SimpleMonitor", "MyFirstEvent", delegate(TraceEvent data)
{
// On First Events, simply remember the ID and time of the event
firstEventTimeMSec[(int)data.PayloadByName("MyId")] = data.TimeStampRelativeMSec;
});
// Add logic on what to do when we get "MySecondEvent"
session.Source.Dynamic.AddCallbackForProviderEvent("Microsoft-Demos-SimpleMonitor", "MySecondEvent", delegate(TraceEvent data)
{
// On Second Events, if the ID matches, compute the delta and display it.
var myID = (int)data.PayloadByName("MyId");
if (firstEventTimeMSec.TryGetValue(myID, out var firstEventTime))
{
firstEventTimeMSec.Remove(myID); // We are done with the ID after matching it, so remove it from the table.
Out.WriteLine(" >>> Time Delta from first Event = {0:f3} MSec", data.TimeStampRelativeMSec - firstEventTime);
}
else
{
Out.WriteLine(" >>> WARNING, Found a 'SecondEvent' without a corresponding 'FirstEvent'");
}
});
// Add logic on what to do when we get "Stop"
session.Source.Dynamic.AddCallbackForProviderEvent("Microsoft-Demos-SimpleMonitor", "MyStopEvent", delegate(TraceEvent data)
{
Out.WriteLine(" >>> Got a stop message");
// Stop processing after we we see the 'Stop' event, this will 'Process() to return. It is OK to call Dispose twice
session.Source.Dispose();
});
#if DEBUG
// The callback above will only be called for events the parser recognizes (in the case of DynamicTraceEventParser, EventSources)
// It is sometimes useful to see the other events that are not otherwise being handled. The source knows about these and you
// can ask the source to send them to you like this.
session.Source.UnhandledEvents += delegate(TraceEvent data)
{
if ((int)data.ID != 0xFFFE) // The EventSource manifest events show up as unhanded, filter them out.
{
Out.WriteLine("GOT UNHANDLED EVENT: " + data.Dump());
}
};
#endif
// At this point we have created a TraceEventSession, hooked it up to a TraceEventSource, and hooked the
// TraceEventSource to a TraceEventParser (you can do several of these), and then hooked up callbacks
// up to the TraceEventParser (again you can have several). However we have NOT actually told any
// provider (EventSources) to actually send any events to our TraceEventSession.
// We do that now.
// Enable my provider, you can call many of these on the same session to get events from other providers.
// Because this EventSource did not define any keywords, I can only turn on all events or none.
var restarted = session.EnableProvider("Microsoft-Demos-SimpleMonitor");
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);
}
// 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();
Out.WriteLine("**** Start listening for events from the Microsoft-Demos-SimpleMonitor provider.");
// 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()'.
session.Source.Process();
Out.WriteLine();
Out.WriteLine("Stopping the collection of events.");
}
return(0);
}
static int Main(string[] args)
{
int exitCode = StatusTestErrorBadInput;
ArgumentSyntax syntax = ParseCommandLine(args);
if (_help)
{
ShowUsage();
return(0);
}
if (!File.Exists(_coreRunExePath))
{
Console.WriteLine($"Error: {_coreRunExePath} is an invalid path.");
ShowUsage();
return(exitCode);
}
if (!File.Exists(_testExe))
{
Console.WriteLine($"Error: {_testExe} is an invalid path.");
ShowUsage();
return(exitCode);
}
string passThroughArguments = "";
if (_testargs.Count > 0)
{
passThroughArguments = string.Join(' ', _testargs);
}
var testModules = new HashSet <string>();
var testFolders = new HashSet <string>();
testModules.Add(_testExe.ToLower());
foreach (string reference in _referenceFilenames)
{
// CoreCLR generates ETW events with all lower case native image files that break our string comparison.
testModules.Add(reference.ToLower());
}
foreach (string reference in _referenceFolders)
{
string absolutePath = reference.ToAbsoluteDirectoryPath();
if (!Directory.Exists(reference))
{
Console.WriteLine($"Error: {reference} does not exist.");
ShowUsage();
return(exitCode);
}
testFolders.Add(reference.ToLower());
}
if (_noEtl)
{
RunTest(null, null, passThroughArguments, out exitCode);
}
else
{
using (var session = new TraceEventSession("ReadyToRunTestSession"))
{
var r2rMethodFilter = new ReadyToRunJittedMethods(session, testModules, testFolders);
session.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Verbose, (ulong)(ClrTraceEventParser.Keywords.Jit | ClrTraceEventParser.Keywords.Loader));
Task.Run(() => RunTest(session, r2rMethodFilter, passThroughArguments, out exitCode));
// Block, processing callbacks for events we subscribed to
session.Source.Process();
Console.WriteLine("Test execution " + (exitCode == StatusTestPassed ? "PASSED" : "FAILED"));
int analysisResult = AnalyzeResults(r2rMethodFilter, _whitelistFilename);
Console.WriteLine("Test jitted method analysis " + (analysisResult == StatusTestPassed ? "PASSED" : "FAILED"));
// If the test passed, return the Jitted method analysis result
// If the test failed, return its execution exit code
exitCode = exitCode == StatusTestPassed ? analysisResult : exitCode;
}
}
Console.WriteLine($"Final test result: {exitCode}");
return(exitCode);
}
public EtwTracingInterceptorTest()
{
_eventSession = new TraceEventSession(Guid.NewGuid().ToString());
var eventSourceGuid = TraceEventProviders.GetEventSourceGuidFromName("Microsoft-WindowsAzure");
_eventSession.EnableProvider(eventSourceGuid);
}
public void Dispose() => TraceEventSession.Dispose();
protected override void AttachToEvents(TraceEventSession traceEventSession, BenchmarkCase benchmarkCase)
{
traceEventSession.Source.Kernel.PerfInfoCollectionStart += _ => { }; // we must subscribe to this event, otherwise the PerfInfoPMCSample is not raised ;)
traceEventSession.Source.Kernel.PerfInfoPMCSample += OnPerfInfoPmcSample;
}
internal static void EnsureStopped()
{
using (var session = new TraceEventSession("EventSourceTestSession", "EventSourceTestData.etl"))
session.Stop();
}
public EtwListener(string dataFileName = "EventSourceTestData.etl", string sessionName = "EventSourceTestSession")
{
_dataFileName = dataFileName;
// Today you have to be Admin to turn on ETW events (anyone can write ETW events).
if (TraceEventSession.IsElevated() != true)
{
throw new ApplicationException("Need to be elevated to run. ");
}
if (dataFileName == null)
{
Debug.WriteLine("Creating a real time session " + sessionName);
Task.Factory.StartNew(delegate ()
{
var session = new TraceEventSession(sessionName, dataFileName);
session.Source.AllEvents += OnEventHelper;
Debug.WriteLine("Listening for real time events");
_session = session; // Indicate that we are alive.
_session.Source.Process();
Debug.WriteLine("Real time listening stopping.");
});
SpinWait.SpinUntil(() => _session != null); // Wait for real time thread to wake up.
}
else
{
// Normalize to a full path name.
dataFileName = Path.GetFullPath(dataFileName);
Debug.WriteLine("Creating ETW data file " + Path.GetFullPath(dataFileName));
_session = new TraceEventSession(sessionName, dataFileName);
}
}
private int StartListen()
{
// This is the name of the event source.
var providerName = textBox1.Text;
//Debug.Assert(providerName == MyEventSource.Log.Name);
// Given just the name of the eventSource you can get the GUID for the evenSource by calling this API.
// From a ETW perspective, the GUID is the 'true name' of the EventSource.
//var providerGuid = TraceEventSession.GetEventSourceGuidFromName(providerName);
//Debug.Assert(providerGuid == MyEventSource.Log.Guid);
// Today you have to be Admin to turn on ETW events (anyone can write ETW events).
if (!(TraceEventSession.IsElevated() ?? false))
{
Console.WriteLine("To turn on ETW events you need to be Administrator, please run from an Admin process.");
return(-1);
}
// 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 mulitple versions
// of your program to run simultaneously, you need to generate unique names (e.g. add a process ID suffix)
Console.WriteLine("Creating a 'My Session' session");
var sessionName = "My Session";
using (var session = new TraceEventSession(sessionName, null)) // the null second parameter means 'real time session'
{
// Note that sessions create a OS object (a session) that lives beyond the lifetime of the process
// that created it (like Filles), thus you have to be more careful about always cleaning them up.
// An importanty way you can do this is to set the 'StopOnDispose' property which will cause the session to
// stop (and thus the OS object will die) when the TraceEventSession dies. Because we used a 'using'
// statement, this means that any exception in the code below will clean up the OS object.
session.StopOnDispose = true;
// By default, if you hit Ctrl-C your .NET objects may not be disposed, so force it to. It is OK if dispose is called twice.
Console.CancelKeyPress += delegate(object sender, ConsoleCancelEventArgs e) { session.Dispose(); };
// prepare to read from the session, connect the ETWTraceEventSource to the session
using (var source = new ETWTraceEventSource(sessionName, TraceEventSourceType.Session))
{
// To demonstrate non-trivial event manipuation, we calculate the time delta between 'MyFirstEvent and 'MySecondEvent'
// These variables are used in this calculation
int lastMyEventID = int.MinValue; // an illegal value to start with.
double lastMyEventMSec = 0;
// Hook up the parser that knows about EventSources
var parser = new DynamicTraceEventParser(source);
parser.All += delegate(TraceEvent data)
{
Console.WriteLine("GOT EVENT: " + data.ToString());
//if (data.ProviderGuid == providerGuid) // We don't actually need this since we only turned one one provider.
//{
// Note that this is the inefficient way of parsing events (there are string comparisions on the
// event Name and every payload value), however it is fine for events that occur less than 100 times
// a second. For more volumous events, you should consider making a parser for you eventSource
// (covered in another demo). This makes your code fare less 'reflection-like' where you have lots
// of strings (e.g. "MyFirstEvent", "MyId" ...) which is better even ignoring the performance benefit.
if (data.EventName == "MyFirstEvent")
{
// On First Events, simply remember the ID and time of the event
lastMyEventID = (int)data.PayloadByName("MyId");
lastMyEventMSec = data.TimeStampRelativeMSec;
}
else if (data.EventName == "MySecondEvent")
{
// On Second Events, if the ID matches, compute the delta and display it.
if (lastMyEventID == (int)data.PayloadByName("MyId"))
{
Console.WriteLine(" > Time Delta from first Event = {0:f3} MSec", data.TimeStampRelativeMSec - lastMyEventMSec);
}
}
else if (data.EventName == "Stop")
{
// Stop processing after we we see the 'Stop' event
//source.DisposeClose();
}
//}
};
// Enable my provider, you can call many of these on the same session to get other events.
session.EnableProvider(providerName, TraceEventLevel.Always);
// 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.
Console.WriteLine("Staring Listing for events");
// 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.Close()'.
source.Process();
Console.WriteLine();
Console.WriteLine("Stopping the collection of events.");
}
}
return(0);
}
/// <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 void EnableProvider(TraceEventSession session)
{
session.EnableProvider(IISLogTraceEventParser.ProviderName);
}
public GcMetricsProvider(IApmLogger logger, bool collectGcCount = true, bool collectGcGen0Size = true, bool collectGcGen1Size = true,
bool collectGcGen2Size = true, bool collectGcGen3Size = true
)
{
_collectGcCount = collectGcCount;
_collectGcGen0Size = collectGcGen0Size;
_collectGcGen1Size = collectGcGen1Size;
_collectGcGen2Size = collectGcGen2Size;
_collectGcGen3Size = collectGcGen3Size;
_logger = logger.Scoped(nameof(SystemTotalCpuProvider));
if (PlatformDetection.IsDotNetFullFramework)
{
var sessionName = SessionNamePrefix + Guid.NewGuid();
using (_traceEventSession = new TraceEventSession(sessionName))
{
Task.Run(() =>
{
try
{
_traceEventSession.EnableProvider(
ClrTraceEventParser.ProviderGuid,
TraceEventLevel.Informational,
(ulong)
ClrTraceEventParser.Keywords.GC // garbage collector details
);
}
catch (Exception e)
{
_logger.Warning()?.LogException(e, "TraceEventSession initialization failed - GC metrics won't be collected");
return;
}
_traceEventSession.Source.Clr.GCStop += (a) =>
{
if (a.ProcessID == Process.GetCurrentProcess().Id)
{
if (!_isMetricAlreadyCaptured)
{
lock (_lock)
_isMetricAlreadyCaptured = true;
}
_gcCount = (uint)a.Count;
}
};
_traceEventSession.Source.Clr.GCHeapStats += (a) =>
{
if (a.ProcessID == Process.GetCurrentProcess().Id)
{
if (!_isMetricAlreadyCaptured)
{
lock (_lock)
_isMetricAlreadyCaptured = true;
}
_gen0Size = (ulong)a.GenerationSize0;
_gen1Size = (ulong)a.GenerationSize1;
_gen2Size = (ulong)a.GenerationSize2;
_gen3Size = (ulong)a.GenerationSize3;
}
};
_traceEventSession.Source.Process();
});
}
}
if (PlatformDetection.IsDotNetCore)
{
_eventListener = new GcEventListener(this, logger);
}
}
/// <summary>
/// Execute a given set of mutually independent build commands with given degree of
/// parallelism.
/// </summary>
/// <param name="processesToRun">Processes to execute in parallel</param>
/// <param name="degreeOfParallelism">Maximum number of processes to execute in parallel</param>
public static void Run(IEnumerable <ProcessInfo> processesToRun, int degreeOfParallelism)
{
int processCount = processesToRun.Count();
if (processCount < degreeOfParallelism)
{
// We never need a higher DOP than the number of process to execute
degreeOfParallelism = processCount;
}
bool collectEtwTraces = processesToRun.Any(processInfo => processInfo.CollectJittedMethods);
if (collectEtwTraces)
{
using (TraceEventSession traceEventSession = new TraceEventSession("ReadyToRunTestSession"))
{
traceEventSession.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Verbose, (ulong)(ClrTraceEventParser.Keywords.Jit | ClrTraceEventParser.Keywords.Loader));
ReadyToRunJittedMethods jittedMethods = new ReadyToRunJittedMethods(traceEventSession, processesToRun);
Task.Run(() =>
{
BuildProjects(processesToRun, jittedMethods, degreeOfParallelism);
traceEventSession.Stop();
});
traceEventSession.Source.Process();
}
// Append jitted method info to the logs
foreach (ProcessInfo processInfo in processesToRun)
{
if (processInfo.CollectJittedMethods)
{
using (StreamWriter logWriter = new StreamWriter(processInfo.LogPath, append: true))
{
logWriter.WriteLine($"Jitted methods ({processInfo.JittedMethods.Count} total):");
foreach (KeyValuePair <string, HashSet <string> > jittedMethodAndModules in processInfo.JittedMethods)
{
logWriter.Write(jittedMethodAndModules.Key);
logWriter.Write(": ");
bool first = true;
foreach (string module in jittedMethodAndModules.Value)
{
if (first)
{
first = false;
}
else
{
logWriter.Write(", ");
}
logWriter.Write(module);
}
logWriter.WriteLine();
}
}
}
}
}
else
{
BuildProjects(processesToRun, null, degreeOfParallelism);
}
}
/// <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 Run()
{
Out.WriteLine("******************** ObserveGCEvents DEMO ********************");
Out.WriteLine("This program Demos using the reactive framework (IObservable) to monitor");
Out.WriteLine(".NET Garbage collector (GC) events.");
Out.WriteLine();
Out.WriteLine("The program will print a line every time 100K of memory was allocated");
Out.WriteLine("on the GC heap along with the type of the object that 'tripped' the 100K");
Out.WriteLine("sample. It will also print a line every time a GC happened and show ");
Out.WriteLine("the sizes of each generation after the GC.");
Out.WriteLine();
Out.WriteLine("Run a .NET Program while the monitoring is active to see GC events.");
Out.WriteLine();
if (TraceEventSession.IsElevated() != true)
{
Out.WriteLine("Must be elevated (Admin) to run this method.");
Debugger.Break();
return;
}
var monitoringTimeSec = 10;
Out.WriteLine("The monitor will run for a maximum of {0} seconds", monitoringTimeSec);
Out.WriteLine("Press Ctrl-C to stop monitoring of GC Allocs");
// create a real time user mode session
using (var userSession = new TraceEventSession("ObserveGCAllocs"))
{
// Set up Ctrl-C to stop the session
SetupCtrlCHandler(() => { userSession.Stop(); });
// enable the CLR provider with default keywords (minus the rundown CLR events)
userSession.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Verbose,
(ulong)(ClrTraceEventParser.Keywords.GC));
// Create a stream of GC Allocation events (happens every time 100K of allocations happen)
IObservable <GCAllocationTickTraceData> gcAllocStream = userSession.Source.Clr.Observe <GCAllocationTickTraceData>();
// Print the outgoing stream to the console
gcAllocStream.Subscribe(allocData =>
Out.WriteLine("GC Alloc : Proc: {0,10} Amount: {1,6:f1}K TypeSample: {2}", GetProcessName(allocData.ProcessID), allocData.AllocationAmount / 1000.0, allocData.TypeName));
// Create a stream of GC Collection events
IObservable <GCHeapStatsTraceData> gcCollectStream = userSession.Source.Clr.Observe <GCHeapStatsTraceData>();
// Print the outgoing stream to the console
gcCollectStream.Subscribe(collectData =>
Out.WriteLine("GC Collect: Proc: {0,10} Gen0: {1,6:f1}M Gen1: {2,6:f1}M Gen2: {3,6:f1}M LargeObj: {4,6:f1}M",
GetProcessName(collectData.ProcessID),
collectData.GenerationSize0 / 1000000.0,
collectData.GenerationSize1 / 1000000.0,
collectData.GenerationSize2 / 1000000.0,
collectData.GenerationSize3 / 1000000.0));
IObservable <long> timer = Observable.Timer(new TimeSpan(0, 0, monitoringTimeSec));
timer.Subscribe(delegate
{
Out.WriteLine("Stopped after {0} sec", monitoringTimeSec);
userSession.Dispose();
});
// OK we are all set up, time to listen for events and pass them to the observers.
userSession.Source.Process();
}
Out.WriteLine("Done with program.");
}
private static void RegisterCallbacks
(
string providerName
, string[] traceEvents
, TraceEventDispatcher source
, TraceEventSession session
, Action
<
TraceEventDispatcher
, TraceEventSession
, TraceEvent
> onOneEventTracedOnceProcessAction
)
{
int l = traceEvents.Length;
for (int i = 0; i < l; i++)
{
var eventName = traceEvents[i];
var action = onOneEventTracedOnceProcessAction;
if (action != null)
{
if (string.Compare(eventName, "*") == 0)
{
source
.Dynamic
.All +=
delegate (TraceEvent data)
{
action(source, session, data);
};
}
else if (string.Compare(eventName, "UnhandledEvents") == 0)
{
source
.UnhandledEvents
+= delegate (TraceEvent data)
{
action(source, session, data);
};
}
else
{
source
.Dynamic
.AddCallbackForProviderEvent
(
providerName
, eventName
, delegate (TraceEvent data)
{
action(source, session, data);
}
);
}
}
}
}
private static void RunTest(TraceEventSession session, ReadyToRunJittedMethods r2rMethodFilter, string testArguments, out int exitCode)
{
exitCode = -100;
try
{
using (var process = new Process())
{
process.StartInfo.FileName = _coreRunExePath;
process.StartInfo.Arguments = _testExe + " " + testArguments;
process.StartInfo.UseShellExecute = false;
process.Start();
if (r2rMethodFilter != null)
{
r2rMethodFilter.SetProcessId(process.Id);
}
process.OutputDataReceived += delegate(object sender, DataReceivedEventArgs args)
{
Console.WriteLine(args.Data);
};
process.ErrorDataReceived += delegate(object sender, DataReceivedEventArgs args)
{
Console.WriteLine(args.Data);
};
if (process.WaitForExit(DefaultTestTimeOut))
{
exitCode = process.ExitCode;
}
else
{
// Do our best to kill it if there's a timeout, but if it fails, not much we can do
try
{
process.Kill();
}
catch
{
}
Console.WriteLine("Test execution timed out.");
exitCode = StatusTestErrorTimeOut;
}
Console.WriteLine($"Test exited with code {process.ExitCode}");
if (session != null && session.EventsLost > 0)
{
exitCode = StatusTestErrorEventsLost;
Console.WriteLine($"Error - {session.EventsLost} got lost in the nether.");
return;
}
}
}
finally
{
// Stop ETL collection on the main thread
session?.Stop();
}
}
