static void Main(string[] args)
{
Out = Console.Out;
Out.WriteLine("Hello World!");
using (var session = new TraceEventSession("pri"))
{
void ConsoleOnCancelKeyPress(object sender, ConsoleCancelEventArgs e)
{
Console.CancelKeyPress -= ConsoleOnCancelKeyPress;
session?.Dispose();
}
Console.CancelKeyPress += ConsoleOnCancelKeyPress;
session.EnableKernelProvider(KernelTraceEventParser.Keywords.Registry);
session.Source.Kernel.RegistryCreate += KernelParser_RegistryCreate;
session.Source.Kernel.RegistrySetValue += KernelParser_RegistrySetValue;
session.Source.Kernel.RegistryDeleteValue += KernelParser_RegistryDeleteValue;
session.Source.Kernel.RegistryDelete += KernelParser_RegistryDelete;
session.Source.Kernel.RegistryKCBCreate += KernelParser_RegistryKCBCreate;
session.Source.Kernel.RegistryKCBDelete += KernelParser_RegistryKCBDelete;
session.Source.Kernel.RegistryKCBRundownBegin += Kernel_RegistryKCBRundownBegin;
session.Source.Kernel.RegistryKCBRundownEnd += Kernel_RegistryKCBRundownEnd;
Out.WriteLine("Collecting events");
session.Source.Process();
Out.WriteLine("Stopping collection of events");
}
}
private void Dispose(bool disposing)
{
if (disposing)
{
// session.StopOnDispose = true; //default
// By calling dispose the session will stop.
// this is the way to stop the realtime session
// in a timely manner
output("disposing of etw wacher");
session?.Dispose();
}
}
public void Stop()
{
using (var rundownSession = new TraceEventSession(sessionName + "Rundown", "data.clrRundown.etl"))
{
rundownSession.EnableProvider(ClrRundownTraceEventParser.ProviderGuid, TraceEventLevel.Verbose,
(ulong)ClrRundownTraceEventParser.Keywords.Default);
// Poll until 2 second goes by without growth.
for (var prevLength = new FileInfo("data.clrRundown.etl").Length;;)
{
Thread.Sleep(2000);
var newLength = new FileInfo("data.clrRundown.etl").Length;
if (newLength == prevLength)
{
break;
}
prevLength = newLength;
}
}
// TODO: Currenty not aware of any more sophisticated control, when hosting sub-process it will wait for timeout without new events after sub-process ends
//Thread.Sleep(4000);
stopped = true;
session?.Dispose();
kernelSession?.Dispose();
TraceEventSession.MergeInPlace("data.etl", TextWriter.Null);
//var traceLog = TraceLog.OpenOrConvert("data.etl");
//var simpleTraceLogProcess = traceLog.Processes.LastProcessWithID(Process.GetCurrentProcess().Id);
//foreach (var data in simpleTraceLogProcess.EventsInProcess)
//{
//}
using (var source = new ETWTraceEventSource("data.etl"))
{
source.Clr.GCHeapStats += ClrOnGcHeapStats;
source.Clr.GCStart += ClrOnGcStart;
source.Clr.GCStop += ClrOnGcStop;
source.Clr.GCGenerationRange += ClrOnGcGenerationRange;
source.Process();
}
}
/// <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 = "SimpleMontitorSession";
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");
double firstEventTime;
if (firstEventTimeMSec.TryGetValue(myID, out 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);
}
public void Dispose()
{
m_EtwSession?.Dispose();
}
void IDisposable.Dispose()
{
m_session?.Dispose();
m_session = null;
m_cts.Dispose();
}
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()
{
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);
}
/// <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 override void Finished()
{
session?.Dispose();
all.Remove(this);
}
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.");
}
static void Main(string[] args)
{
_session = new TraceEventSession("exceptionTrace");
_session.EnableProvider(ClrTraceEventParser.ProviderGuid);
_session.Source.Clr.ExceptionStart += OnClrOnExceptionStart;
_handlerTask = Task.Run(() => _session.Source.Process());
while (true)
{
var keyInfo = Console.ReadKey(true);
switch (keyInfo.KeyChar)
{
case '?': Console.WriteLine("q - quit, p - prcess, e - exception, f - filter (F-clear, Alt-f - print), d - data, ' ' - pause (buffered)");
break;
case ' ': if (_outputEnabled)
{
Disable();
}
else
{
Enable();
}
break;
case 'q': goto exit;
case 'p':
_printOptions.ProcessInfo = _printOptions.EnumRotate(_printOptions.ProcessInfo);
break;
case 'e':
_printOptions.ExceptionInfo = _printOptions.EnumRotate(_printOptions.ExceptionInfo);
break;
case 'd':
_printOptions.DataPrint = !_printOptions.DataPrint;
break;
case 'F':
_printOptions.SimpleFilter.Clear();
break;
case 'f':
if ((keyInfo.Modifiers & ConsoleModifiers.Alt) != 0)
{
Console.WriteLine(string.Join(Environment.NewLine, _printOptions.SimpleFilter));
break;
}
Disable();
Console.Write("Enter filter:");
var filter = Console.ReadLine();
if (string.IsNullOrWhiteSpace(filter))
{
break;
}
filter = filter.Trim();
_printOptions.SimpleFilter.Add(filter);
Enable();
break;
}
}
exit:
_session.Stop();
_handlerTask.Wait();
_session?.Dispose();
}
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);
}
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.");
}
protected override void OnTerminate()
{
Session?.Source.Dispose();
Session?.Dispose();
}
/// <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)
}
public static void CloseDuplicateTraceSession(string sessionName)
{
InternalLogger.Write.ConflictingTraceSessionFound(sessionName);
TraceEventSession s = null;
try
{
// we can't control this session so we need to stop it
s = new TraceEventSession(sessionName); // might throw if it's in the midst of being shut down
s.Stop();
}
catch (FileNotFoundException)
{
// well, okay, then it's probably gone now.
}
finally
{
if (s != null)
{
s.Dispose();
}
}
// Now we enter a brief waiting period to make sure it dies. We must do this because ControlTrace()
// (the underlying win32 API) is asynchronous and our request to terminate the session may take
// a small amount of time to complete.
if (!WaitForSessionChange(sessionName, false))
{
InternalLogger.Write.ConflictingTraceSessionStuck(sessionName);
throw new OperationCanceledException("could not tear down existing trace session");
}
}
public void Dispose()
{
_etwSession?.Dispose();
}
/// <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 = "SimpleMontitorSession";
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");
double firstEventTime;
if (firstEventTimeMSec.TryGetValue(myID, out 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", "Stop", 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;
}
public void Dispose()
{
Console.WriteLine("Disposing resources");
_session?.Dispose();
_timer?.Dispose();
}
public static void Run()
{
var monitoringTimeSec = 10;
Out.WriteLine("******************** ModuleLoadMonitor DEMO ********************");
Out.WriteLine("Monitoring DLL Loads and Process Starts/Stops system wide");
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 program to see some events!");
Out.WriteLine();
if (TraceEventSession.IsElevated() != true)
{
Out.WriteLine("Must be elevated (Admin) to run this program.");
Debugger.Break();
return;
}
// Start the session as a real time monitoring session,
// Before windows 8, there is a restriction that if you wanted kernel events you must name your session
// 'NT Kernel Logger' (the value of KernelSessionName) and there can only be one such session and no
// other ETW providers can be enabled for that session (thus you need two sessions if you want both
// kernel and non-kernel events (fixed in Win 8). We want this to work on Win 7 so we live with those
// restrictions.
using (TraceEventSession session = new TraceEventSession(KernelTraceEventParser.KernelSessionName))
{
/* 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.
Console.CancelKeyPress += new ConsoleCancelEventHandler((object sender, ConsoleCancelEventArgs cancelArgs) =>
{
Out.WriteLine("Control C pressed"); // Note that if you hit Ctrl-C twice rapidly you may be called concurrently.
session.Dispose(); // Note that this causes Process() to return.
cancelArgs.Cancel = true; // This says don't abort, since Process() will return we can terminate nicely.
});
// Enable the Kernel events that we want. At this point data is being collected (but being buffered since we are not reading it)
// See KernelTraceEventParser.Keywords for what else can be turned on and KernelTraceEventParser for a description
// of the events that you get when you turn on the various kernel keywords. Many kernel events will also log a stack
// when they fire see EnableKernelProvider for more on that.
session.EnableKernelProvider(KernelTraceEventParser.Keywords.ImageLoad | KernelTraceEventParser.Keywords.Process);
// .Source will auto-create a TraceEventSource reading the data from the session
// .Kernel will auto-create a KernelTraceEventParser getting its events from the source
// .ImageLoad is an event that you can subscribe to that will be called back when Image load events happen (complete with parsed event)
session.Source.Kernel.ImageLoad += delegate(ImageLoadTraceData data)
{
Out.WriteLine("Process {0,16} At 0x{1,8:x} Loaded {2}", data.ProcessName, data.ImageBase, data.FileName);
};
// Subscribe to more events (process start)
session.Source.Kernel.ProcessStart += delegate(ProcessTraceData data)
{
Out.WriteLine("Process Started {0,6} Parent {1,6} Name {2,8} Cmd: {3}",
data.ProcessID, data.ParentID, data.ProcessName, data.CommandLine);
};
// Subscribe to more events (process end)
session.Source.Kernel.ProcessStop += delegate(ProcessTraceData data)
{
Out.WriteLine("Process Ending {0,6} ", data.ProcessID);
};
// Set up a timer to stop processing after monitoringTimeSec
var timer = new Timer(delegate(object state)
{
Out.WriteLine("Stopped after {0} sec", monitoringTimeSec);
session.Source.StopProcessing();
}, null, monitoringTimeSec * 1000, Timeout.Infinite);
// Start listening for events, will end if session.Source.StopProcessing() is called or session.Dispose() is called.
// Here we never do either of these and thus will only stop when Ctrl-C is hit (but it will clean up because of
// our control C handler).
session.Source.Process();
timer.Dispose(); // Done with the timer.
}
Out.WriteLine("Stopping monitor");
}
public void Dispose()
{
session?.Dispose();
writer?.Dispose();
}
public static void Run()
{
var monitoringTimeSec = 10;
Out.WriteLine("******************** RealTimeTraceLog DEMO (win8) ********************");
Out.WriteLine("This program Shows how to use the real-time support in TraceLog");
Out.WriteLine("We do this by showing how to monitor exceptions in real time ");
Out.WriteLine();
Out.WriteLine("This code depends on a Feature of Windows 8.1 (combined user and kernel sessions)");
Out.WriteLine();
Out.WriteLine("Note that this support is currently experimental and subject to change");
Out.WriteLine();
Out.WriteLine("Monitoring .NET Module load and Exception events (with stacks).");
Out.WriteLine("Run some managed code (ideally that has exceptions) while the monitor is running.");
Out.WriteLine();
if (Environment.OSVersion.Version.Major * 10 + Environment.OSVersion.Version.Minor < 62)
{
Out.WriteLine("This demo only works on Win8 / Win 2012 and above)");
return;
}
TraceEventSession session = null;
// Set up Ctrl-C to stop both user mode and kernel mode sessions
Console.CancelKeyPress += (object sender, ConsoleCancelEventArgs cancelArgs) =>
{
if (session != null)
session.Dispose();
cancelArgs.Cancel = true;
};
// Cause an exception to be thrown a few seconds in (so we have something interesting to look at)
var exceptionGeneationTask = Task.Factory.StartNew(delegate
{
Thread.Sleep(3000);
ThrowException();
});
Timer timer = null;
// Create the new session to receive the events.
// Because we are on Win 8 this single session can handle both kernel and non-kernel providers.
using (session = new TraceEventSession("TraceLogSession"))
{
// Enable the events we care about for the kernel
// For this instant the session will buffer any incoming events.
// Enabling kernel events must be done before anything else.
// This will fail on Win7.
//
// Note that if you turn on the KernelTraceEventParser.Keywords.Profile, you can also get stacks for CPU sampling
// (every millisecond). (You can use the traceLogSource.Kernel.PerfInfoSample callback).
Out.WriteLine("Enabling Image load, Process and Thread events. These are needed to look up native method names.");
session.EnableKernelProvider(
// KernelTraceEventParser.Keywords.Profile | // If you want CPU sampling events
// KernelTraceEventParser.Keywords.ContextSwitch | // If you want context switch events
// KernelTraceEventParser.Keywords.Thread | // If you want context switch events you also need thread start events.
KernelTraceEventParser.Keywords.ImageLoad |
KernelTraceEventParser.Keywords.Process, /****** The second parameter indicates which kernel events should have stacks *****/
// KernelTraceEventParser.Keywords.ImageLoad | // If you want Stacks image load (load library) events
// KernelTraceEventParser.Keywords.Profile | // If you want Stacks for CPU sampling events
// KernelTraceEventParser.Keywords.ContextSwitch | // If you want Stacks for context switch events
KernelTraceEventParser.Keywords.None
);
Out.WriteLine("Enabling CLR Exception and Load events (and stack for those events)");
// We are monitoring exception events (with stacks) and module load events (with stacks)
session.EnableProvider(
ClrTraceEventParser.ProviderGuid,
TraceEventLevel.Informational,
(ulong)(ClrTraceEventParser.Keywords.Jit | // Turning on JIT events is necessary to resolve JIT compiled code
ClrTraceEventParser.Keywords.JittedMethodILToNativeMap | // This is needed if you want line number information in the stacks
ClrTraceEventParser.Keywords.Loader | // You must include loader events as well to resolve JIT compiled code.
ClrTraceEventParser.Keywords.Exception | // We want to see the exception events.
ClrTraceEventParser.Keywords.Stack)); // And stacks on all CLR events where it makes sense.
// The CLR events turned on above will let you resolve JIT compiled code as long as the JIT compilation
// happens AFTER the session has started. To handle the case for JIT compiled code that was already
// compiled we need to tell the CLR to dump 'Rundown' events for all existing JIT compiled code. We
// do that here.
Out.WriteLine("Enabling CLR Events to 'catch up' on JIT compiled code in running processes.");
session.EnableProvider(ClrRundownTraceEventParser.ProviderGuid, TraceEventLevel.Informational,
(ulong)(ClrTraceEventParser.Keywords.Jit | // We need JIT events to be rundown to resolve method names
ClrTraceEventParser.Keywords.JittedMethodILToNativeMap | // This is needed if you want line number information in the stacks
ClrTraceEventParser.Keywords.Loader | // As well as the module load events.
ClrTraceEventParser.Keywords.StartEnumeration)); // This indicates to do the rundown now (at enable time)
// Because we care about symbols in native code or NGEN images, we need a SymbolReader to decode them.
// There is a lot of messages associated with looking up symbols, but we don't want to clutter up
// The output by default, so we save it to an internal buffer you can ToString in debug code.
// A real app should make this available somehow to the user, because sooner or later you DO need it.
TextWriter SymbolLookupMessages = new StringWriter();
// TextWriter SymbolLookupMessages = Out; // If you want the symbol debug spew to go to the output, use this.
// By default a symbol Reader uses whatever is in the _NT_SYMBOL_PATH variable. However you can override
// if you wish by passing it to the SymbolReader constructor. Since we want this to work even if you
// have not set an _NT_SYMBOL_PATH, so we add the Microsoft default symbol server path to be sure/
var symbolPath = new SymbolPath(SymbolPath.SymbolPathFromEnvironment).Add(SymbolPath.MicrosoftSymbolServerPath);
SymbolReader symbolReader = new SymbolReader(SymbolLookupMessages, symbolPath.ToString());
Out.WriteLine("Open a real time TraceLog session (which understands how to decode stacks).");
using (TraceLogEventSource traceLogSource = TraceLog.CreateFromTraceEventSession(session))
{
// We use this action in the particular callbacks below. Basically we pass in a symbol reader so we can decode the stack.
// Often the symbol reader is a global variable instead.
Action<TraceEvent> PrintEvent = ((TraceEvent data) => Print(data, symbolReader));
// We will print Exceptions and ModuleLoad events. (with stacks).
traceLogSource.Clr.ExceptionStart += PrintEvent;
traceLogSource.Clr.LoaderModuleLoad += PrintEvent;
// traceLogSource.Clr.All += PrintEvent;
// If you want to see stacks for various other kernel events, uncomment these (you also need to turn on the events above)
traceLogSource.Kernel.PerfInfoSample += ((SampledProfileTraceData data) => Print(data, symbolReader));
// traceLogSource.Kernel.ImageLoad += ((ImageLoadTraceData data) => Print(data, symbolReader));
// process events until Ctrl-C is pressed or timeout expires
Out.WriteLine("Waiting {0} sec for Events. Run managed code to see data. ", monitoringTimeSec);
Out.WriteLine("Keep in mind there is a several second buffering delay");
// Set up a timer to stop processing after monitoringTimeSec
timer = new Timer(delegate(object state)
{
Out.WriteLine("Stopped Monitoring after {0} sec", monitoringTimeSec);
if (session != null)
session.Dispose();
session = null;
}, null, monitoringTimeSec * 1000, Timeout.Infinite);
traceLogSource.Process();
}
}
Out.WriteLine("Finished");
if (timer != null)
timer.Dispose(); // Turn off the timer.
}
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>
/// CollectData 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 = "SimpleMontitorSession";
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.
{
/* 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(); };
// Enable my provider, you can call many of these on the same session to get other events.
var restarted = session.EnableProvider(MyEventSource.Log.Name);
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("Waiting 12 seconds for events to come in.");
Thread.Sleep(12000);
}
}
public void Dispose()
{
_session?.Dispose();
_isFinished?.Dispose();
}
public void TestSessionClosing()
{
LogManager.Shutdown(); // not needed by us
// set this just to make sure it isn't actually used.
LogManager.AllowEtwLogging = AllowEtwLoggingValues.Disabled;
File.Delete("fakesession.etl");
var s1 = new TraceEventSession(ETLFileLogger.SessionPrefix + "fakeSession", "fakeSession.etl");
s1.EnableProvider(TestLogger.Write.Guid, TraceEventLevel.Verbose);
s1.StopOnDispose = false;
TestLogger.Write.String("mc frontalot = nerdcore raps");
Assert.IsTrue(File.Exists("fakesession.etl"));
Assert.IsNotNull(TraceEventSession.GetActiveSession(ETLFileLogger.SessionPrefix + "fakeSession"));
s1.Dispose();
// so the session should still exist ...
Assert.IsNotNull(TraceEventSession.GetActiveSession(ETLFileLogger.SessionPrefix + "fakeSession"));
var s2 = new ETLFileLogger("fakeSession", "fakeSession.etl", 64);
s2.SubscribeToEvents(TestLogger.Write.Guid, EventLevel.Verbose);
TestLogger.Write.String("optimus rhyme = also rapping nerd");
s2.Dispose();
const int maxWait = 1000;
int slept = 0;
while (slept < maxWait)
{
if (TraceEventSession.GetActiveSession(ETLFileLogger.SessionPrefix + "fakeSession") == null)
{
break;
}
Thread.Sleep(maxWait / 10);
slept += maxWait / 10;
}
Assert.IsNull(TraceEventSession.GetActiveSession(ETLFileLogger.SessionPrefix + "fakeSession"));
}
public static void Stop()
{
tSession?.Dispose();
received = 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);
}
