SQL Server и ETW. Ч.3
В конце первой серии говорилось, что, начиная с Висты, в ETW поддерживается мультиплексирование. Это очень позитивное нововведение, которым мы сейчас конкретно займемся. Еще в посте про SQL Profiler я говорил о ценности консолидированной картины мира, когда мы сводили воедино профайлерную трассу с графиками Performance Monitor. Продолжу развивать эту мысль. Ясно, что настройка и отладка сложного многокомпонентного приложения - процесс нетривиальный. Он становится еще нетривиальней, если каждая компонента пишет информацию о ходе своей работы в собственный журнал, и эти журналы затем приходится состыковывать, чтобы понять последовательность действий в общем масштабе приложения: чем занималась компонента А, вызвавшая компоненту Б, и компонента Б, вызвавшая компоненту В, прежде чем в компоненте В вылезла какая-нибудь бякость. В особенности если учесть, что А, Б, В могли быть разработаны независимо. Йа нопешу афегительно сложное преложенее, которое обращается к SQL Server, и сведу события от них обоих в единую трассу. В сценарии будут участвовать два ETW-провайдера: штатный SQL Serverный MSSQLServer Trace, который мы посмотрели во второй серии, и самопальный, задачей которого является трассировка кастомного клиентского приложения. Благодаря возможности мультиплексирования они будут шарить одну ETWшную сессию. Для начала стоит изобразить кастомный провайдер.
Программирование контроллера, провайдера и потребителя описывается в документации MSDN. Как говорилось в одном посте, those whose curiosity has been piqued can jump into the MSDN documentation, which is not very good IMO but better than nothing.
Там описываются примеры с использованием native API. Как говорилось в другом посте, The ETW API has been around for a number of years, so it’s implemented in unmanaged code. As I write this, there are no shipping managed libraries to make working with it simpler. Internally, various groups here are looking at the best way to make ETW a first class citizen in the managed world. Это писалось 5 лет назад, и сейчас в графе .NET-поддержка можно ставить галочку. Не слишком жирную, though. Написание своего провайдера обрисовано в посте .NET Event Tracing for Windows от апреля нынешнего года. В нем предлагается следующая последовательность действий. Во-первых, надлежит создать манифест провайдера в виде XML-документа. Апологеты инволюции к иерархическим БД под названием XML в качестве одного из преимуществ приводят его наглядность по сравнению с проприетарными бинарными форматами и самоописательность. Прекрасно, значит, поглядев примеры в %MSSDK%\Samples\WinBase\Eventing, свой манифест они смогут составить самостоятельно. Для всех остальных в %MSSDK%\bin существует тула ecmangen.exe, способная генерить этот манифест. Не зная, что допускается в узлах по правилам игры, от наглядности XML мало прока. С таким же успехом генератор, в который это знание заложено, мог бы производить манифест в бинарном формате. Без разницы, как воплощать это знание: в виде элементов и атрибутов или побайтно отсчитывая с такой-то позиции по такую-то. Хотя нет, XML занимает больше места.
Во-вторых, на основе манифеста при помощи тулы mc.exe (Message Compiler, также входит в SDK) приготовляется 4 файла (временный, .bin, .h, .rc), из которых существенным в данном случае является ресурсный. В-третьих, берется rc.exe (Resource Compiler, также должен лежать в C:\Program Files\Microsoft SDKs\Windows\v6.0A\bin), при помощи которого из .rc файла делается ресурс .res. Ресурс затем вставляется в Project Properties вижуал студийного проекта, что образует класс с именем манифеста, используя который в коде, можно инициализировать и отправлять события. Все просто, если не считать, что .NET здесь несколько притянут за уши. Искреннее отношение человека к данному процессу можно почитать здесь.
Сергей Мелещук в своем блоге (How to do ETW logging from .NET application) приводит другой способ генерации событий из .NET. Он не рассматривает задачи создать произвольный собственный ETW-провайдер с нуля при помощи манифеста и класса System.Diagnostics.Eventing.EventProvider. В System.Diagnostics имеется класс TraceSource, который позволяет писать из приложения сообщения трассировки в разные места. Место определяется абстрактным классом TraceListener, который в .NET 2.0 воплощался в ConsoleTraceListener - вывод отладочных сообщений в консоль, TextWriterTraceListener - в текстовый файл, XmlWriterTraceListener - в XML, EventLogTraceListener - в журнал Windows. В 3.5 к ним добавился EventProviderTraceListener, направляющий отладочные сообщения в ETW. Добавление такого слушателя автоматически создает новый ETW-провайдер, хотя и не позволяет такой полноты контроля над его обликом, как в первом случае. Я взял за основу пример Сергея и немного его модифицировал применительно к нашему сценарию.
Удалим для чистоты эксперимента созданный в первой серии SqlDataCollector:
Рис.1
Создадим каким-либо способом новый гуид. В моем случае это получился {4E7F098A-3E72-4D5B-9EA3-1B41A83527B0}.
Рис.2
Создадим текстовый файл c:\Temp\SqlDataCollector.cfg, куда напишем следующие две строчки:
"MSSQLServer Trace" 6 0
{4E7F098A-3E72-4D5B-9EA3-1B41A83527B0}
Рис.3
где вторая есть свежесозданный гуид.
Откроем окно командной строки и вобьем следующую команду. Сейчас поясню, что в ней к чему.
logman create trace AppDataCollector -o c:\Temp\SqlDataCollector.etl -pf c:\Temp\SqlDataCollector.cfg -ow --v
Скрипт 1
Logman create trace создает новый коллектор данных на основе одного или нескольких провайдеров данных. По условию задачи у нас должно быть два провайдера: MSSQLServer Trace и самопальный, пишущих в один файл. Если создавать два коллектора
logman create trace Коллектор1 -o c:\Temp\SqlDataCollector.etl -р Провайдер1
logman start Коллектор1
logman create trace Коллектор2 -o c:\Temp\SqlDataCollector.etl -р Провайдер2
logman start Коллектор2
при старте второго возникнет ошибка, что файл занят, следовательно, нужно их сводить в один коллектор. Ключ -р, как можно посмотреть в logman create trace /?, позволяет задать только одного провайдера - A single Event Trace provider to enable. В случае нескольких их нужно прописывать в отдельном файле, который передается в ключе -pf. В нашем случае это c:\Temp\SqlDataCollector.cfg (Рис.3). Первая строчка инициализирует провайдер MSSQLServer Trace. Мы ее уже видели во второй серии (Скрипт 7). Вторая соответствует самопальному провайдеру. С ним дело обстоит чуть хитрее. В примере Сергея используется класс EventProviderTraceListener. Как говорится в документации, конструктор EventProviderTraceListener инициализирует новый экземпляр класса с помощью указанного идентификатора поставщика. Где ж его взять, коли поставщик еще не создан? Команда logman create trace ... -р Провайдер будет ругаться, если ей указать имя несуществующего провайдера. К счастью, если вместо имени подсунуть гуид, она поверит взаймы, что такой есть. Это может быть совершенно произвольный гуид. На рис.3 он передается во второй строчке. Ключ -ow говорит перезаписывать файл c:\Temp\SqlDataCollector.etl, ежели таковой уже имеется. Ключ --v отменяет действие ключа -v, чтобы файл выхлопа был один. Иначе он будет создавать SqlDataCollector_000001.etl, SqlDataCollector_000002.etl и т.д. Пускаем сессию сбора данных для свежесозданного коллектора
logman start AppDataCollector
Скрипт 2
и выполняем следующее консольное приложение.
using System;
using System.Diagnostics;
using System.Diagnostics.Eventing;
using System.Data.SqlClient;
class Program
{
private static Guid etwProviderId = new Guid("{4E7F098A-3E72-4D5B-9EA3-1B41A83527B0}");
private static string etwProviderName = "AppDataCollector";
static void Main(string[] args)
{
EventProviderTraceListener etwListener = new EventProviderTraceListener(etwProviderId.ToString(), etwProviderName);
TraceSource ts = new TraceSource(etwProviderName, SourceLevels.All);
ts.Listeners.Clear();
ts.Listeners.Add(etwListener);
ts.TraceEvent(TraceEventType.Information | TraceEventType.Start, 0, "Поехали");
ts.TraceData(TraceEventType.Verbose, 0, String.Format("Здравствуйте. Я - приложение {0}", System.Reflection.Assembly.GetEntryAssembly().Location));
SqlConnection cnn = new SqlConnection("server=localhost;database=TestFS;trusted_connection=true"); cnn.Open();
SqlCommand cmd = new SqlCommand("exec sp_trace_generateevent @eventid = 82, @userinfo = N'Пользовательское событие №0', @userdata = 0x12345", cnn);
ts.TraceData(TraceEventType.Verbose, 0, String.Format("Отправляю на SQL Server команду {0}", cmd.CommandText));
cmd.ExecuteNonQuery();
ts.TraceInformation("И смотрю, что из этого получилось");
cnn.Close(); ts.Close();
}
}
Скрипт 3
Это одновременно будет обращающийся к SQL Server клиент и сам себе режиссер, то есть ETW-провайдер. Все свои действия он протоколирует, посылая их в TraceSource. К любому TraceSource по умолчанию подстегивается консольный слушатель, нам он неинтересен, отсюда ts.Listeners.Clear(). Вместо него добавляется EventProviderTraceListener, отсылающий трассировку ETW-провайдеру, которого он сам же и создает. Единственно, мы говорим, чтобы он создал его с определенным гуидом, тем самым, который нам поверил в долг логман. Обращаю внимание, что это может быть совершенно произвольный гуид, потому что некоторые упорно выбирают {E13C0D23-CCBC-4E12-931B-D9CC2EEE27E4} (провайдер .NET Common Language Runtime). Не буду отвлекаться на рассказ про методы TraceEvent, TraceData и TraceInformation. Можно посмотреть в документации или в совершенно замечательном .NET Instrumentation Workshop. TraceSource отправляет информацию с этих методов привязанным к нему слушателям, то есть в данном случае ETW-провайдеру с гуидом {4E7F098A-3E72-4D5B-9EA3-1B41A83527B0}. Затем на SQL Server отправляется запрос. Это Скрипт 8 из предыдущей серии. Как и в прошлый раз, SQL Server на него реагирует, отправляя событие своему провайдеру MSSQLServer Trace. Оба провайдера: и MSSQLServer Trace, и самопальный {4E7F098A-3E72-4D5B-9EA3-1B41A83527B0}, - завязаны в данном случае на одну сессию:
Рис.4
которая кидает сообщения в c:\Temp\SqlDataCollector.etl (см. Скрипт 1). Туда же после реакции SQL Server падает заключительное TraceInformation от приложения. В итоге имеем объединенный трейс-лог, что и требовалось продемонстрировать. Останавливаем сессию, конвертируем etl и смотрим:
logman stop AppDataCollector
tracerpt C:\Temp\SqlDataCollector.etl -lr -o C:\Temp\SqlDataCollector.xml
Скрипт 4
Рис.5
Рис.6