Профайлер для Entity Framework

Приветствую!

Продолжу серию статей про программирование. На это раз я хочу поговорить о профилировании и логировании по отношению с Entity Framework-у ( далее EF) c 4-й по 6-ю версию, а также о некоторых примененных мной решениях, таких как декомпилирование .NET кода на лету, форма для обработки исключению и прочее.

Подробности под катом.

Введение

Когда я начинал изучение EF, передо мной стал вопрос в профилировании запросов которые генерирует EF. После некоторого поиска я с неудовольствием обнаружил, что штатных средств EF не предоставляет, соответственно, приходилось пользоваться, на мой взгляд, крайне неудобной в использовании программой SQL Server Profiler или купить достаточно дорогой сторонний инструмент Entity Framework Profiler 2.0, за $389.00, а я жадный.

С появлением EF версии 6, ситуация с логированием команд изменилась. Появился механизм, который позволяет добавить свой интерцептор:

//Регистрируем  при старте программы свой IDbCommandInterceptor  DbInterception.Add(new LogFormatter()); 

public class LogFormatter : IDbCommandInterceptor { 	private readonly Stopwatch _stopwatch = new Stopwatch(); 	public void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext<int> interceptionContext) 	{ 		// Перезапускам таймер 		_stopwatch.Restart(); 	} 	public void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext) 	{ 		// Останавливаем таймер 		_stopwatch.Stop(); 		// Логируем команду 		Log(command, interceptionContext); 	} 	public void ReaderExecuting(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext) 	{ 		_stopwatch.Restart(); 	} 	public void ReaderExecuted(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext) 	{ 		_stopwatch.Stop(); 		Log(command, interceptionContext); 	} 	public void ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext) 	{ 		_stopwatch.Restart(); 	} 	public void ScalarExecuted(DbCommand command, DbCommandInterceptionContext<object> interceptionContext) 	{ 		_stopwatch.Stop(); 		Log(command, interceptionContext); 	} 	private void Log<TResult>(DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext) 	{ 		Logger.Log(command, _stopwatch.ElapsedMilliseconds, interceptionContext.Exception); 	} } 

public static class Logger { 	public static void Log(DbCommand command, long elapsedMilliseconds, Exception exception) 	{ 		// Выводим в Trace команду 		Trace.WriteLine(string.Format("Command:{0}, Elapsed Milliseconds:{1}", command.CommandText, elapsedMilliseconds)); 	} } 

Для 4-й версии EF похожего механизма логирования я не нашел.

Мое решение

Идею написать свой профайлер, повторяющий функционал платного, я вынашивал достаточно долго. Первоначальная версия базировалась на механизме интерцепторов EF 6-й версии, но к сожалению в EF 4-й версии этот механизм не работает.
После недолгого гугления, была найдена отличная библиотека для профилировки EF в ASP MVC приложениях, под названием MiniProfiler . На его основе и было решено сделать свое приложения.

Что получилось

Система получилась максимально простой для использования и интеграции. Забрать бинарники с примером проекта можно на созданном мной сайте на wordpress-e http://ef-logger.com/
Главное окно приложения:

Использование

1. Забрать архив с бинарниками и примером проекта

2. Подключить библиотеку EFlogger.EntityFramework4.dll для EF 4-5 версии и EFlogger.EntityFramework6.dll для EF 6-й версии
3. Инициализировать профайлер путем выполнения статического метода

// Для EF 6-й версии EFloggerFor6.Initialize(); // или для  EF с 4-й по 6-ю EFloggerFor4.Initialize(); 

4. Запустить приложение EFlogger.exe

API

Пример для библиотеки EFlogger.EntityFramework6.dl, в случае использования EFlogger.EntityFramework4.dl статический класс будет назваться EFloggerFor6

//Инициализация EFloggerFor6.Initialize();  // Задает IP профалера в случаях его отличие от "127.0.0.1" EFloggerFor6.SetProfilerClientIP(“192.168.10.50″);  // Посылает текстовое сообщение в профайлер EFloggerFor6.WriteMessage(“Text message”);  // Стартует посылку логов профайлер (уже запущен по умолчанию после инициализации)  EFloggerFor6.StartSendToClient();  // Останавливает посылку логов профайлер EFloggerFor6.StopSendToClient();  // Стартует логирование в файл EFlogger.log приложения EFloggerFor6.StartSaveToLogFile();  // Останавливает логирование в файл EFlogger.log приложения EFloggerFor6.StopSaveToLogFile();  //Очищает лог в профайлере и удаляет файл лога, если включен EFloggerFor6.ClearLog();  // Отключает декомпиляцию кода EFloggerFor6.DisableDecompiling();  // Добавляет сборку для игнорирования при построении Stack Trace-a EFloggerFor6.ExcludeAssembly(“MyAssemly”); 

Как это все работает

Механизм внедрения в EF 4-й версии сильно отличается от EF 6-й версии.
Штатные механизмов подмены DbProviderFactory в EF 4 отсутствуют, поэтому приходится идти на подмену штатной фабрики на свою через рефлекцию.
Сам процесс выглядит так:

// проверяем что все фабрики загруженны DbProviderFactories.GetFactoryClasses();  // получаем тип DbProviderFactories Type type = typeof(DbProviderFactories);  DataTable table = null; //получаем значение DataSet статического поля _configTable или _providerTable object setOrTable = (type.GetField("_configTable", BindingFlags.NonPublic | BindingFlags.Static) ??                 type.GetField("_providerTable", BindingFlags.NonPublic | BindingFlags.Static)).GetValue(null);  var set = setOrTable as DataSet; if (set != null)     table = set.Tables["DbProviderFactories"];  table = (DataTable)setOrTable;  // для каждой записи в DataTable подставляем свою фабрику foreach (DataRow row in table.Rows.Cast<DataRow>().ToList()) {     DbProviderFactory factory;     try     {         factory = DbProviderFactories.GetFactory(row);     }     catch (Exception)     {         continue;     }      var profType = EFProviderUtilities.ResolveFactoryType(factory.GetType());     if (profType != null)     {         DataRow profiled = table.NewRow();         profiled["Name"] = row["Name"];         profiled["Description"] = row["Description"];         profiled["InvariantName"] = row["InvariantName"];         profiled["AssemblyQualifiedName"] = profType.AssemblyQualifiedName;         table.Rows.Remove(row);         table.Rows.Add(profiled);     } } 

Для интеграции в EF 6-й версии можно воспользоваться штатным механизмом подстановки сервисов:

DbConfiguration.Loaded += (_, a) => a.ReplaceService<DbProviderServices>((s, k) => new EFProfiledDbProviderServices()); 

Декомпиляция

EFlogger на лету декомпелирует код и отображает тело метода, который сгенерировал тот или иной запрос. Для этого используются библиотеки из бесплатного аналога рефлектора ILSpy. Чтобы декомпировать метод нужно его сначала найти поднявшись по Stack Trace и исключить лишние вызовы сторонних библиотек:

public static string Get(out StackFrame outStackFrame) { 	outStackFrame = null; 	var frames = new StackTrace(0, true).GetFrames(); 	if (frames == null) 	{ 		return ""; 	}  	var methods = new List<string>();  	// проходим по всем фреймам 	foreach (StackFrame t in frames) 	{ 		// получаем метод 		var method = t.GetMethod();  		// получаем сборку и проверяем нужно ли ее пропустить 		var assembly = method.Module.Assembly.GetName().Name; 		if (ShouldExcludeType(method) || AssembliesToExclude.Contains(assembly) || 			MethodsToExclude.Contains(method.Name)) 			continue;  		// находим первый по стеку фрейм и считаем что именно он сгенерировал команду, если нет нужно добавить имя сборки в список на пропуск 		if (outStackFrame == null) 		{ 			outStackFrame = t; 		} 		methods.Add(method.DeclaringType.FullName + ":" + method.Name); 	} 	return string.Join("\r\n", methods); } 

private static string GetMethodBody(StackFrame stackFrame) { 	MethodBase methodBase = stackFrame.GetMethod(); 	return Decompiler.GetSourceCode(methodBase.Module.FullyQualifiedName, methodBase.DeclaringType.Name, methodBase.Name); } 

using System; using System.IO; using System.Linq; using ICSharpCode.Decompiler; using ICSharpCode.Decompiler.Ast; using ICSharpCode.Decompiler.Ast.Transforms; using Mono.Cecil;  namespace Common {     public static class Decompiler     {         public static string GetSourceCode(string pathToAssembly, string className, string methodName)         {             try             {                 var assemblyDefinition = AssemblyDefinition.ReadAssembly(pathToAssembly);                  TypeDefinition assembleDefenition = assemblyDefinition.MainModule.Types.First(type => type.Name == className);                 MethodDefinition methodDefinition = assembleDefenition.Methods.First(method => method.Name == methodName);                 var output = new StringWriter();                 var plainTextOutput = new PlainTextOutput(output);                 DecompileMethod(methodDefinition, plainTextOutput);                 return output.ToString();             }             catch (Exception exception)             {                  return string.Format( "Exception in decompling. \r\n Message:{0}, \r\n Inner Exception:{1}, \r\n StackTrace:{2}",exception.Message, exception.InnerException, exception.StackTrace);             }         }          private static void DecompileMethod(MethodDefinition method, ITextOutput output)         {             AstBuilder codeDomBuilder = CreateAstBuilder(currentType: method.DeclaringType, isSingleMember: true);             if (method.IsConstructor && !method.IsStatic && !method.DeclaringType.IsValueType)             {                 AddFieldsAndCtors(codeDomBuilder, method.DeclaringType, method.IsStatic);                 RunTransformsAndGenerateCode(codeDomBuilder, output);             }             else             {                 codeDomBuilder.AddMethod(method);                 RunTransformsAndGenerateCode(codeDomBuilder, output);             }         }          private static AstBuilder CreateAstBuilder(ModuleDefinition currentModule = null, TypeDefinition currentType = null, bool isSingleMember = false)         {             if (currentModule == null)                 currentModule = currentType.Module;             var settings = new DecompilerSettings();             if (isSingleMember)             {                 settings = settings.Clone();                 settings.UsingDeclarations = false;             }             return new AstBuilder(                 new DecompilerContext(currentModule)                 {                     CurrentType = currentType,                     Settings = settings                 });         }          private static void AddFieldsAndCtors(AstBuilder codeDomBuilder, TypeDefinition declaringType, bool isStatic)         {             foreach (var field in declaringType.Fields)             {                 if (field.IsStatic == isStatic)                     codeDomBuilder.AddField(field);             }             foreach (var ctor in declaringType.Methods)             {                 if (ctor.IsConstructor && ctor.IsStatic == isStatic)                     codeDomBuilder.AddMethod(ctor);             }         }          private static void RunTransformsAndGenerateCode(AstBuilder astBuilder, ITextOutput output, IAstTransform additionalTransform = null)         {             astBuilder.GenerateCode(output);         }     } } 

Пример рабочего проекта декомпиляции на яндекс файлах: yadi.sk/d/AzBGet5-Nwns2

Окно обработки исключительной ситуации

Никому не секрет, что приложения периодически падают, это может произойти по самым разным причинам и задача разработчика показать какое-то вменяемое окно для сообщения об ошибке.
Мой вариант формы выглядит так:

Форма предлагает пользователю добавить информацию об ошибке, шаги для воспроизведения и свой email для ответа.
При нажатии на кнопку Отправить, на почту разработчику приходить письмо со всем данными.

 [STAThread] [STAThread] static void Main() {      	SetupLogger();         // если дебагер не подключен        	if (!Debugger.IsAttached) 	{                 // отлавливаем все необработанные ошибки 		Application.ThreadException += (sender, e) => HandleError(e.Exception); 		AppDomain.CurrentDomain.UnhandledException += (sender, e) => HandleError((Exception)e.ExceptionObject); 	}  	Application.EnableVisualStyles(); 	Application.SetCompatibleTextRenderingDefault(false); 	Application.Run(new MainForm()); } private static void HandleError(Exception exception) { 	try 	{                    // запускаем контроллер формы обернутый try/catch на случай если в контроллере тоже произойдет ошибка 	 	new ErrorHandlerController(exception).Run(); 	} 	catch (Exception e) 	{ 		MessageBox.Show("Error processing exception. Please send log file EFlogger.log to developer: " + Settings.Default.ProgrammerEmail + " \r\n Exception:" + e);                 // записываем ошибку в лог файл 		Logger.Error(e); 		if (MessageBox.Show("Attach debugger? \n Only for developer!!!", "Debugging...", MessageBoxButtons.YesNo, MessageBoxIcon.Question) == DialogResult.Yes) 		{ 			Debugger.Launch(); 			throw; 		} 	} 	finally 	{                        // обязательно принудительно завершаем приложение чтобы Windows не отображала стандартное окно ошибки приложения 		Environment.Exit(1); 	} }  //new ErrorHandlerController(exception).Run(); public void Run() {      // формируем текст ошибки  	 	string exceptionInfoText = string.Format( 		"An unexpected error occurred: {0}" + Environment.NewLine + 		"Time: {1} " + Environment.NewLine + 		"{2}" + Environment.NewLine + 		"InnerException: \n {3}" + Environment.NewLine + 		"InnerException StackTrace: \n  {4}" + Environment.NewLine,  		_exception.Message,  		DateTime.Now,  		_exception,  		_exception.InnerException,  		_exception.InnerException != null  			? _exception.InnerException.StackTrace  			: string.Empty 	);          // записываем ошибку с лог файл 	 	Program.Logger.Error(exceptionInfoText); 	_view.ExceptionInfoText = exceptionInfoText;  	// показываем форму, вызвав метод ShowDialog, в противном случае покажется стандартное окно ошибки приложения 	_view.ShowDialog(); } 

Пример рабочего проекта с формой обработки ошибок можете забрать на яндекс файлах: yadi.sk/d/7y4i_cz7NwtE3

Послесловие

На случай если сайт упадет, вы можете сказать архив профайлера опять же, на яндекс файлах: yadi.sk/d/trLmkJnkNwtg7
Уверен, багов еще много, но я постараюсь все ошибки исправлять максимально быстро. Так же, я хочу спросить совета у уважаемого хабра сообщества как поступить с этим профайлером, так с одной стороны хочется сделать бесплатный продукт, но в то же время и немного заработать. В настоящее время я думаю о том чтобы сделать профайлер полностью бесплатным для личного использования и платным для компаний, но опять же по минимальной цене баксов в 20-30. Ну или просто оставить бесплатным с кнопочной Donate.

Всем спасибо за внимание. Надеюсь этот инструмент будет полезен.

PS: По всем вопросам, баг репортам и прочее можете писать на почту: developer@ef-logger.com или st.glushak@gmail.com. Также, автор ищет подработку, ибо ипотека. Спасибо за понимание.