Автор: Paul Randal, Tracking expensive queries with extended events in SQL 2008
В рамках курса для администраторов баз данных, который мы проводим здесь, в Мельбурне, я выполнил демонстрацию использования предикатов и файловых целей с расширенными событиями, поэтому я хочу выложить скрипт, чтобы люди могли с ним поиграть.
Для ознакомления с расширенными событиями см.:
- Моя статья в TechNet Magazine за 2008 год: Advanced Troubleshooting with Extended Events
- Отличный технический документ Джонатана Кехайаса (Jonathan Kehayias): Using SQL Server 2008 Extended Events
- Предыдущий пост в блоге об использовании сеанса событий системной работоспособности для получения исторической информации о взаимоблокировках
В этом сценарии я хотел бы отслеживать запросы, которые интенсивно используют процессор в моей системе.
Сначала я создам тестовую базу данных для экспериментов.
USE MASTER;
GO
IF DATABASEPROPERTYEX ('production', 'Version') > 0 DROP DATABASE production;
GO
CREATE DATABASE production;
GO
USE production;
GO
CREATE TABLE t1 (c1 INT IDENTITY, c2 UNIQUEIDENTIFIER ROWGUIDCOL DEFAULT NEWID(), c3 CHAR (5000) DEFAULT 'a');
CREATE CLUSTERED INDEX t1_CL ON t1 (c1);
CREATE NONCLUSTERED INDEX t1_NCL ON t1 (c2);
GO
SET NOCOUNT ON;
INSERT INTO t1 DEFAULT VALUES;
GO 1000
-- Получение идентификатора базы данных для использования в сеансе событий
SELECT DB_ID ('production');
GO
Обратите внимание, что я получил идентификатор созданной базы данных, так как он понадобится мне при определении предиката расширенного события.
IF EXISTS (SELECT * FROM sys.server_event_sessions WHERE name = 'EE_ExpensiveQueries')
DROP EVENT SESSION EE_ExpensiveQueries ON SERVER;
GO
CREATE EVENT SESSION EE_ExpensiveQueries ON SERVER
ADD EVENT sqlserver.sql_statement_completed
(ACTION (sqlserver.sql_text, sqlserver.plan_handle)
WHERE sqlserver.database_id = 18 /*DBID*/ AND cpu_time > 10000 /*общее время ЦП в мс*/)
ADD TARGET package0.asynchronous_file_target
(SET FILENAME = N'C:\SQLskills\EE_ExpensiveQueries.xel', METADATAFILE = N'C:\SQLskills\EE_ExpensiveQueries.xem')
WITH (max_dispatch_latency = 1 seconds);
GO
Я отслеживаю событие, которое срабатывает при завершении каждого оператора, и фильтрую по идентификатору базы данных (убедитесь, что вы подставили правильный идентификатор при попытке воспроизведения) и по количеству миллисекунд процессорного времени, использованного оператором. Примечание: при использовании предикатов всегда следует убеждаться, что они расположены в таком порядке, чтобы наиболее ограничивающие предикаты (те, которые, скорее всего, будут ложными) были первыми в списке, чтобы вычисление предикатов «закорачивалось» как можно быстрее (стандартная практика программирования для булевой логики). Я также использую файловую цель, чтобы показать, как это делается, вместо кольцевого буфера, который обычно используется в демонстрациях расширенных событий.
Теперь я включу сеанс событий и выполню несколько запросов в базе данных production.
ALTER EVENT SESSION EE_ExpensiveQueries ON SERVER STATE = START;
GO
USE production;
GO
SELECT COUNT (*) FROM t1 WHERE c1 > 500;
GO
SELECT SUM (c1) FROM t1 WHERE c3 LIKE 'a';
GO
ALTER INDEX t1_CL ON t1 REORGANIZE;
GO
ALTER INDEX t1_CL ON t1 REBUILD;
GO
Это должно было сгенерировать несколько долго выполняющихся запросов. Теперь я переключусь в контекст базы данных master (чтобы запросы к самому сеансу событий не захватывались им) и посмотрю, что было захвачено.
USE master;
GO
SELECT COUNT (*) FROM sys.fn_xe_file_target_read_file
('C:\SQLskills\EE_ExpensiveQueries*.xel', 'C:\SQLskills\EE_ExpensiveQueries*.xem', NULL, NULL);
GO
В этом случае у меня есть 3 записи. Я могу извлечь их с помощью следующего кода:
SELECT data FROM
(SELECT CONVERT (XML, event_data) AS data FROM sys.fn_xe_file_target_read_file
('C:\SQLskills\EE_ExpensiveQueries*.xel', 'C:\SQLskills\EE_ExpensiveQueries*.xem', NULL, NULL)
) entries;
GO
И я получаю три XML-блока.
Гораздо полезнее извлечь всё из XML-блока программно с помощью кода ниже:
SELECT
data.value (
'(/event[@name="sql_statement_completed"]/@timestamp)[1]', 'DATETIME') AS [Time],
data.value (
'(/event/data[@name="cpu"]/value)[1]', 'INT') AS [CPU (ms)],
CONVERT (FLOAT, data.value ('(/event/data[@name="duration"]/value)[1]', 'BIGINT')) / 1000000
AS [Duration (s)],
data.value (
'(/event/action[@name="sql_text"]/value)[1]', 'VARCHAR(MAX)') AS [SQL Statement],
'0x' + data.value ('(/event/action[@name="plan_handle"]/value)[1]', 'VARCHAR(100)') AS [Plan Handle]
FROM
(SELECT CONVERT (XML, event_data) AS data FROM sys.fn_xe_file_target_read_file
('C:\SQLskills\EE_ExpensiveQueries*.xel', 'C:\SQLskills\EE_ExpensiveQueries*.xem', null, null)
) entries
ORDER BY [Time] DESC;
GO
Результат:
Time CPU (ms) Duration (s) SQL Statement Plan Handle
———————– ——– ———— —————————————— ————————————————–
2009-10-16 17:59:29.623 30 1.214875 ALTER INDEX t1_CL ON t1 REBUILD; 0x06001000EB672A07B8C0C807000000000000000000000000
2009-10-16 17:59:28.407 20 0.024076 ALTER INDEX t1_CL ON t1 REORGANIZE; 0x0600100003594903B8C0C807000000000000000000000000
2009-10-16 17:59:28.343 51 0.045144 SELECT SUM (c1) FROM t1 WHERE c3 LIKE 'a'; 0x06001000FAF5B11EB820C307000000000000000000000000
Теперь я могу подставить один из дескрипторов плана в запрос к sys.dm_exec_query_plan, чтобы получить графический план запроса:
SELECT [query_plan] FROM sys.dm_exec_query_plan (0x06001000FAF5B11EB820C307000000000000000000000000);
GO
И нажав на полученную ссылку XML, я получаю демонстрацию план запроса.
И теперь я могу настроить рабочую нагрузку в production, чтобы она вела себя лучше.
Ради интереса я снова переключился в контекст базы данных production и снова выполнил разбор XML, чтобы захватить план запроса — попробуйте сами! Весьма занятно :-)
Если бы я хотел сделать это более полезным, я бы использовал кольцевой буфер в качестве цели с механизмом опроса каждые несколько секунд, чтобы гарантировать возможность захвата графического плана запроса для дорогих запросов до того, как план будет вытеснен из кэша, — возможно, я когда-нибудь соберусь с этим и опубликую готовое решение.
Комментариев нет:
Отправить комментарий