В предыдущем посте для определения deprecated кода использовались профайлерные события Deprecation Announcement и Deprecation Final Support категории Deprecation. В этом посте мы задействуем новую модную функциональность, появившуюся в SQL Server 2008 под названием расширенные события (XEvents). Ранее в блоге уже использовались расширенные события при отлове чекпойнтов.

Про XEvents все говорят, что это круто, но слабо объясняют, почему. В конце концов, испокон века в SQL Server есть другие диагностические инструменты, такие, как различные команды dbcc или тот же профайлер. Утверждается, что результат dbcc требует сложной последующей обработки - его нужно скинуть в промежуточную таблицу, разобрать и т.д. Результат сессии сбора расширенных событий тоже нельзя потребить как есть, требуется предварительно поупражняться в знании XML и XQuery. Далее, утверждается, что плохо сконфигурированная профайлерная трасса может посадить производительность. Например, если на нагруженной системе включить в трассу Lock: Acquired и Lock: Released и забыть поставить фильтр по DatabaseId / ObjectId, система ляжет. Ровно так же ей поплохеет, если в сессии XEvents поставить NO_EVENT_LOSS и включить мониторинг события sql_statement_completed, скидывая план в синхронный таргет. Хорошую диагностическую информацию предоставляют DMV, но про них говорится, что не всегда они предоставляют достаточную информацию, например, чтобы определить, какие запросы сопровождаются интенсивным гудением пропеллера. Я не спорю, пусть XEvents позволяют это сделать легко, как и многое другое, но документированы они крайне скудно. Сам инструмент не умеет делать то-то и то-то или я не знаю, как заставить его это сделать, - результат одинаков. Пожалуй, основное, в чем XEvents, на мой субъективный взгляд, превосходят DMV, dbcc, SQL Trace, DDL-триггеры, Event Notifications и другие SQL Serverные инструменты мониторинга и диагностики, заключается в том, что, будучи основаны на Event Tracing for Windows (ETW), они могут быть скоррелированы с внешними по отношению к SQL Server компонентами, что полезно при отладке распределенной комплексной системы. Кое-какие философствования на эту тему можно почитать в MSDNовском блоге: https://blogs.msdn.com/alexejs/archive/2009/09/04/sql-server-etw-1.aspx, https://blogs.msdn.com/alexejs/archive/2009/09/04/sql-server-etw-2.aspx,

https://blogs.msdn.com/alexejs/archive/2009/09/06/sql-server-etw-3.aspx,

https://blogs.msdn.com/alexejs/archive/2009/09/07/sql-server-etw-4.aspx.

Однако вернемся к расширенным событиям. Посмотреть список расширенных событий можно так:

select * from sys.dm_xe_objects where object_type = 'event'

Скрипт 1

Просматривая этот список, можно заметить знакомые нам по предыдущему посту события deprecation_announcement и deprecation_final_support. Все события срабатывают синхронно. Например, несовместный кусок кода тут же вызывает после себя события deprecation. Каждое событие несет о себе какую-то информацию. Вспомните профайлер, где по горизонтальной оси идут колонки с параметрами события. Т.е. предполагается, что у всех событий колонки более-менее общие. Это неправильно. Каждое событие, вообще говоря, отдельная таблица со своим набором полей. У таблиц могут иметься общие (существенные) поля типа name, identity, rowguid и частные (все остальные). Например, событие Новый год характеризуется такими существенными параметрами, как длительность праздников и объем выпитого, и несущественными, например, номер года. У события покупки новой машины набор параметров будет, очевидно, отличаться. Хотя существенные параметры, наверное, будут те же. Эти события можно объединить в категорию праздник и выделить для каждой категории существенный набор колонок. Для расширенных событий общими колонками являются ID, UUID, VERSION, CHANNEL и, наверное, KEYWORD. Прочитать про них можно здесь. Набор колонок для конкретных событий можно посмотреть так:

select * from sys.dm_xe_object_columns where object_name in ('deprecation_announcement', 'deprecation_final_support')

Скрипт 2

Специфичными колонками для наших событий являются feature и message.

Действия - это наборы команд. Обычно действия дособирают дополнительную информацию по событию, т.е. они видны как дополнительные колонки события, обычные или вычисляемые. Действия выполняются, как и события, синхронно перед тем, как событие будет оприходовано (consumed). Посмотреть все действия можно так:

select * from sys.dm_xe_objects where object_type = 'action' order by name

Скрипт 3

Среди действий, например, видны такие колонки, как sql_text - исходник команды, tsql_stack - понятно, plan_handle - можно прочитать здесь. Достаточно много действий посвящено SQLOS и губернатору ресурсов.

События вместе с информацией о событиях собираются, как минимум, для того, чтобы на них посмотреть, следовательно, собранные результаты нужно периодически куда-то сбрасывать (приходовать). Место, куда приходуются результаты сбора, и способ их утрамбовки в это место вместе называются таргетом. Место бывает областью в памяти, файлом на диске или SQLным ETW-провайдером, про который мы уже все знаем, сходив по вышеприведенным ссылкам на тему ETW. События можно тупо фиксировать по мере поступления или делать над ними какую-нибудь обработку, например, считать (раз - крокодил, два - крокодил) или сочетать попарно, например, не просто фиксировать высвобождение блокировки, а сопоставлять его тому событию, когда она была наложена. Подробнее про таргеты можно прочитать здесь. Русский BOL имеет свою специфику, поэтому хотя бы для начала прочитайте в оригинале. Таргеты бывают синхронные и асинхронные. Посмотреть список таргетов, как вы уже догадались, можно так:

select * from sys.dm_xe_objects where object_type = 'target' order by name

Скрипт 4

Еще нам понадобятся предикаты. Предикат расположен между событием и действием. Поскольку и то, и другое синхронно, предикат выполняется тоже синхронно. Предикаты позволяют фильтровать события на основе набора логических правил. Это полезно, т.к. некоторые действия содержат дорогие вычисления; если событие не отвечает критерию фильтра, лучше его отбраковать заранее, не доводя до действий. Предикаты смотрятся все там же, в sys.dm_xe_objects. Рred_source - это то, что стоит слева, а pred_compare - оператор:

select * from sys.dm_xe_objects where object_type like 'pred_source' order by name 
select * from sys.dm_xe_objects where object_type like 'pred_compare' order by name

Скрипт 5

Существует еще понятие maps, но нам оно сейчас не понадобится. Maps означают просто перекодировку map_key -> map_value, т.е. вместо того, чтобы ввести поле description, они засунули его в отдельный DMV. Например,

select map_key, map_value from sys.dm_xe_map_values where name = 'lock_mode' 
--------------------- 
0 NL 
1 SCH_S 
2 SCH_M 
3 S 
4 U 
5 X 
6 IS 
7 IU 
8 IX 
...

Скрипт 6

Все вместе (события, действия, таргеты, предикаты и перекодировки) группируется по пакетам. Пакет представляет собой ехешник или dllю, которая регистрируется в SQL Server.

select * from sys.dm_xe_packages

Скрипт 7

По умолчанию, в SQL Server входят пакеты sqlserver, sqlos и package0. Узнать, какие события (действия, таргеты, ...) к какому пакету относятся, можно так:

select xp.name, xo.* from sys.dm_xe_objects xo 
join sys.dm_xe_packages xp on xp.guid = xo.package_guid 
where xo.object_type = 'event' 
order by xp.name, xo.name

Скрипт 8

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

if exists(select 1 from sys.server_event_sessions where name = 'Deprecat') 
 drop event session Deprecat on server 
go 
create event session Deprecat on server 
add event sqlserver.deprecation_announcement 
(action (sqlserver.sql_text,sqlserver.tsql_stack) 
 where sqlserver.database_id = 5), 
add event sqlserver.deprecation_final_support 
(action (sqlserver.sql_text,sqlserver.tsql_stack) 
 where sqlserver.database_id = 5)  
add target package0.ring_buffer 
(set max_memory=4096), 
add target package0.asynchronous_file_target 
(set filename = 'c:\Demo\Deprecat.xel', metadatafile = 'c:\Demo\Deprecat.xem') 
with ( 
MAX_MEMORY = 4096KB, 
EVENT_RETENTION_MODE = ALLOW_MULTIPLE_EVENT_LOSS, 
MAX_DISPATCH_LATENCY = 1 SECONDS, 
MEMORY_PARTITION_MODE = NONE, 
TRACK_CAUSALITY = OFF, 
STARTUP_STATE = OFF 
)

Скрипт 9

Сессия будет собирать событияdeprecation_announcement и deprecation_final_support (Скрипт 1) вместе с полагающимися им колонками (Скрипт 2). События будут фильтроваться по предикату database_id = 5. В нашем случае это БД AdventureWorks. Как мы видели (Скрипт 5), в pred_source входит только id базы данных, имя не входит. Дополнительно в информацию о событии будут включаться действия sql_text и tsql_stack (Скрипт 3). Информация будет писаться в таргеты (Скрипт 4) ring_buffer и asynchronous_file_target, которые входят в пакет (Скрипт 7) package0. Проще говоря, эти таргеты означают память и файл. Настраиваемые параметры каждого таргета можно посмотреть так, а разъяснения прочитать здесь. Большими буквами выделены общие параметры настройки сессии. Про них можно прочитать здесь.

Запускаем сессию

alter event session Deprecat on server state = start

Скрипт 10

Производим криминальные команды из предыдущего поста, Скрипт 1. Выполняем для наглядности первую строчку. В таргете, который собирает в память, результаты можно смотреть, пока сессия жива:

select cast(xet.target_data as xml) from sys.dm_xe_session_targets xet 
       inner join sys.dm_xe_sessions xe on (xe.address = xet.event_session_address) 
       where xe.name = 'Deprecat' 
<RingBufferTarget eventsPerSec="0" processingTime="0" totalEventsProcessed="1" eventCount="1" droppedCount="0" memoryUsed="798"> 
  <event name="deprecation_final_support" package="sqlserver" id="207" version="1" timestamp="2010-01-03T10:50:14.966Z"> 
    <data name="feature"> 
      <type name="unicode_string" package="package0" /> 
      <value>DATABASEPROPERTY</value> 
      <text /> 
    </data> 
    <data name="message"> 
      <type name="unicode_string" package="package0" /> 
      <value>DATABASEPROPERTY will be removed in the next version of SQL Server. Avoid using this feature in new development work, and plan to modify applications that currently use it.</value> 
      <text /> 
    </data> 
    <action name="sql_text" package="sqlserver"> 
      <type name="unicode_string" package="package0" /> 
      <value>select databaseproperty('AdventureWorks2008R2', 'Version')</value> 
      <text /> 
    </action> 
    <action name="tsql_stack" package="sqlserver"> 
      <type name="unicode_string" package="package0" /> 
      <value>&lt;frame level='1' handle='0x01000500F1558B0EB07F8B07000000000000000000000000' line='1' offsetStart='0' offsetEnd='-1'/&gt;</value> 
      <text /> 
    </action> 
  </event> 
</RingBufferTarget>

Скрипт 11

В элементе <data name="feature"> указывается несовместимость, в <data name="message"> - развернутое ругательство, что конкретно не понравилось, а в <action name="sql_text" package="sqlserver"> - код, в котором это встретилось.

Выполним еще пару несовместимостей и закроем сессию.

alter event session Deprecat on server state = stop

Скрипт 12

В отличие от памяти, файловый таргет можно читать и после закрытия сессии:

select object_name, cast(event_data as xml) 
from sys.fn_xe_file_target_read_file('c:\Demo\Deprecat*.xel', 'c:\Demo\Deprecat*.xem', null, null)

Скрипт 13

На каждое открытие сессии, а также по достижении max_file_size создается свой файл. Старые файлы удаляются. Кол-во файлов в каждый момент = max_rollover_files. Эти параметры таргета задавались в Скрипте 9. Т.е. если было задано set filename = 'c:\Demo\Deprecat.xel', в c:\Demo будут собираться файлы Deprecat_0_129069889744690000.xel, Deprecat_0_129069900954000000.xel и т.д. Начиная с какого файла читать, задается в третьем параметре ф-ции fn_xe_file_target_read_file. Null означает, что все. Внутри каждого файла еще имеется смещение. Начиная с какого смещения читать, задается в четвертом параметре. Текущий файл и смещение показываются в каждой строчке fn_xe_file_target_read_file, что позволяет читать по кускам. Путем несложного упражнения с XML в каждую строчку можно вытащить в виде полей интересующие элементы/атрибуты из event_data, чтобы сразу получить интересующую картину событий.

with cte(event, xml, file_name, file_offset) as ( 
select object_name, cast(event_data as xml), file_name, file_offset 
from sys.fn_xe_file_target_read_file('c:\Demo\Deprecat*.xel', 'c:\Demo\Deprecat*.xem', null, null) 
) 
select event, 
xml.value('(/event/@timestamp)[1]', 'datetime') [time], 
xml.value('(/event/data[@name="message"]/value)[1]', 'varchar(max)') msg, 
xml.value('(/event/action[@name="sql_text"]/value)[1]', 'nvarchar(max)') [sql], 
file_name, file_offset 
from cte order by time desc

Скрипт 14

Время показывается GMT.

Автор: Алексей Шуленин