ETW, or Event Tracing for Windows, is a technology from Microsoft that allows for extremely fast logging from a running application. Windows itself is using ETW, and technology has been part of Windows since Windows 2000. A developer can write code to start and stop tracing sessions, given that an application being traced has been instrumented for ETW. A developer can define many events that he/she wants to trace. Maine advantage behind ETW is that is has virtually zero overhead when a tracing session is not running. Hence, you can live your instrumentation code in-place in production. It only has overhead when an active trace is running. Event then, if the running trace is hosted inside a different process, running application has extremely minimal overhead. By the way, Microsoft recommends that trace is hosted out-of-process as a result.
One thing that I want to use ETW for is to trace query execution performance in Entity Framework. I will use Entity Framework 6.0+ feature for this purpose, called interceptors. I can add an interceptor to a running EF application, and it will get notified in 6 cases: before and after query execution, command execution and scalar execution. To create one, I just need to implement a single interface: IDbCommandInterceptor. My class is simple as a result:
As you can see, I capture current time before a commend is executed, then compute time after it runs. Finally, I just call my logging component, called CustomEventSource.
In order to code that component, I first have to install ETW NuGet package: Microsoft.Diagnostics.Tracing.TraceEvent.
Next I can just inherit from EventSource base class and create a few methods.
using System;
using System.Data.Common;
using System.Data.Entity.Infrastructure.Interception;
using ETW.Common;
namespace ETWDemo
{
public class CustomInterceptor : IDbCommandInterceptor
{
public void NonQueryExecuting(
DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
{
interceptionContext.UserState = DateTime.Now;
}
public void NonQueryExecuted(
DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
{
CustomEventSource.Logger.EfExecutionTime(
command.CommandText, DateTime.Now.Subtract((DateTime) interceptionContext.UserState).TotalMilliseconds);
}
public void ReaderExecuting(
DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
{
interceptionContext.UserState = DateTime.Now;
}
public void ReaderExecuted(
DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
{
CustomEventSource.Logger.EfExecutionTime(
command.CommandText, DateTime.Now.Subtract((DateTime)interceptionContext.UserState).TotalMilliseconds);
}
public void ScalarExecuting(
DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
{
interceptionContext.UserState = DateTime.Now;
}
public void ScalarExecuted(
DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
{
CustomEventSource.Logger.EfExecutionTime(
command.CommandText, DateTime.Now.Subtract((DateTime)interceptionContext.UserState).TotalMilliseconds);
}
}
}
As you can see, I capture current time before a commend is executed, then compute time after it runs. Finally, I just call my logging component, called CustomEventSource. I need to wire up an interceptor somewhere before accessing DbContext for the first time using static class:
DbInterception.Add(new CustomInterceptor());
In order to code that component, I first have to install ETW NuGet package: Microsoft.Diagnostics.Tracing.TraceEvent.
Next I can just inherit from EventSource base class and create a few methods.
using System;
using System.Diagnostics.Tracing;
using Microsoft.Diagnostics.Tracing;
namespace ETW.Common
{
[EventSource(Name = "CustomEventSource")]
public class CustomEventSource : EventSource
{
public void EfExecutionTime(string query, double executionTime)
{
WriteEvent(1, query, executionTime);
}
public void Start()
{
WriteEvent(2);
}
public static CustomEventSource Logger = new CustomEventSource();
public void Stop()
{
WriteEvent(3);
}
public static void ReadQueryEvents(string logFile, Action<EfQueryData> callback)
{
using (var source = new ETWTraceEventSource(logFile))
{
// Set up the callbacks
source.Dynamic.All += delegate(TraceEvent data)
{
if (data.EventName == "EfExecutionTime")
{
var queryData = new EfQueryData
{
ExecutionTime = (double)data.PayloadByName("executionTime"),
Query = (string)data.PayloadByName("query")
};
callback(queryData);
}
};
source.Process();//start reading event
}
}
}
}
I specify the name of my source in an attribute. The name is important, as later I want to make sure to look at the correct events. I define three methods: EfExecutionTime, Start and Stop. There are a few points when it comes to those methods. Method name will later become event name! Each event has an ID, which is the first parameter to WriteEvent method. Make sure to start with 1, and add 1 to each consecutive event! Each of the event methods has parameters. Parameter names are important! They will later be used to get event fields. Finally, last method is used to read events and call a callback function with each one. You can see how I am using event write method parameter names to get event metadata. This method will be used by monitoring program to read events and show them to the user.
This is it as far as instrumentation goes! So easy, even I can do it.
Now, we need to write another program to capture events. The whole routine is very short, and involves creating a session to ETW.
using System;
using Microsoft.Diagnostics.Tracing.Session;
namespace ETW.Common
{
public class EtwListener : IDisposable
{
private const string SessioName = "CustomSession";
private TraceEventSession _session;
private bool _stopped;
public void Start()
{
_session = new TraceEventSession(SessioName, "CustomSession.etl");
_session.EnableProvider("CustomEventSource");
}
public void Stop()
{
_stopped = true;
_session.Stop();
_session.Dispose();
}
public void Dispose()
{
if (_stopped)
{
Dispose();
}
}
}
}
TraceEventSession implements IDisposable, but I have to avoid “using” statement in order to allow my program to start and stop in different places in my routine. Now, here is my outer routine that starts the trace, waits for the user to stop it, and shows / prints captured events.
using System;
using ETW.Common;
using System.Threading;
using Microsoft.Diagnostics.Tracing.Session;
namespace ETFListenderDemo
{
class Program
{
private static void Main(string[] args)
{
if (!(TraceEventSession.IsElevated() ?? false))
{
Console.WriteLine("To turn on ETW events you need to be Admin process.");
Console.ReadKey();
return;
}
Console.WriteLine("press any key to start listening");
Console.ReadKey();
var listener = new EtwListener();
listener.Start();
bool continueCollection = true;
while (continueCollection)
{
Thread.Sleep(10000);
Console.WriteLine("Press Q to quit");
var key = Console.ReadKey();
if (key.Key == ConsoleKey.Q)
{
continueCollection = false;
}
}
listener.Stop();
CustomEventSource.ReadQueryEvents("CustomSession.etl",
queryData => Console.WriteLine("EfExecutionTime: time: {0} for query {1}",
queryData.ExecutionTime, queryData.Query));
Console.WriteLine("press any key to quit");
Console.ReadKey();
}
}
}
Administrative access is required to start a trace. I can run this program, then start another program that just executes some queries. Then I can type Q, as you can see in the code above, will terminate the trace and display the events. This of course just demonstrates how to capture the events in a console app. In truth, I would write a windows app, like WPF app, instead of console app for production. You can download the source code for sample app here. It includes both listener and event creation projects. Just run the solution, it is configured to run both projects simultaneously. Then click in the listener window to start it, then click in the other window to create events. Finally, stop the listener by typing Q to see generated events.
You can easily extend upon this demo to find commands that take longer than certain amount of time to execute, find most frequently executed queries, etc…
Enjoy!
Pingback: sql-server – 如何连续测量EF性能？ - 算法网