拡張イベントを利用して、スロークエリを調査します。
拡張イベントはSQLServer2008から利用できます。
- 拡張イベントの登録
実行完了までに2秒以上掛かっているクエリを取得します。
・G:\work\ExtendedEvents_logフォルダを用意します。
・下記のクエリを実行します。
MSSQL2008用
--2008 拡張イベントの登録
CREATE EVENT SESSION [slowquery_report_2sec] ON SERVER
ADD EVENT sqlserver.rpc_completed(
ACTION(sqlserver.client_hostname,sqlserver.database_id,sqlserver.sql_text,sqlserver.username)
WHERE ([duration]>(2000))),
ADD EVENT sqlserver.sp_statement_completed(
ACTION(sqlserver.client_hostname,sqlserver.database_id,sqlserver.sql_text,sqlserver.username)
WHERE ([duration]>(2000000))),
ADD EVENT sqlserver.sql_statement_completed(
ACTION(sqlserver.client_hostname,sqlserver.database_id,sqlserver.sql_text,sqlserver.username)
WHERE ([duration]>(2000000))),
ADD EVENT sqlserver.xml_deadlock_report
ADD TARGET package0.asynchronous_file_target(SET filename=N'G:\work\ExtendedEvents_log\slowquery.xel',max_file_size=(2),max_rollover_files=(3),metadatafile=N'G:\work\ExtendedEvents_log\slowquery.xem'),
ADD TARGET package0.ring_buffer(SET max_memory=(4096))
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=10 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=ON)
GO
MSSQL2012用
--2012 拡張イベントの登録
CREATE EVENT SESSION [slowquery_report_2sec] ON SERVER
ADD EVENT sqlserver.rpc_completed(
ACTION(sqlserver.client_hostname,sqlserver.database_id,sqlserver.sql_text,sqlserver.username)
WHERE ([duration]>(2000000))),
ADD EVENT sqlserver.sp_statement_completed(
ACTION(sqlserver.client_hostname,sqlserver.database_id,sqlserver.sql_text,sqlserver.username)
WHERE ([duration]>(2000000))),
ADD EVENT sqlserver.sql_batch_completed(
ACTION(sqlserver.client_hostname,sqlserver.database_id,sqlserver.sql_text,sqlserver.username)
WHERE ([duration]>(2000000))),
ADD EVENT sqlserver.sql_statement_completed(
ACTION(sqlserver.client_hostname,sqlserver.database_id,sqlserver.sql_text,sqlserver.username)
WHERE ([duration]>(2000000))),
ADD EVENT sqlserver.xml_deadlock_report
ADD TARGET package0.event_counter,
ADD TARGET package0.event_file(SET filename=N'G:\work\ExtendedEvents_log\slowquery.xel',max_file_size=(2),max_rollover_files=(3),metadatafile=N'G:\work\ExtendedEvents_log\slowquery.xem'),
ADD TARGET package0.ring_buffer(SET max_memory=(8192))
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=10 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=ON)
GO
下記のイベントを対象としました。
sqlserver.rpc_completed
リモート プロシージャ コールが完了したことを示します。
sqlserver.sp_statement_completed
ストアド プロシージャ内の Transact-SQL ステートメントが完了したことを示します。
sqlserver.sql_batch_completed
Transact-SQL バッチが完了したことを示します。
sqlserver.sql_statement_completed
Transact-SQL ステートメントが完了したことを示します。
sqlserver.xml_deadlock_report
デッドロックがいつ発生し、どのオブジェクトが関係しているかを監視します。
4つの完了のイベントを対象にすると、クエリの実行方法によって重複して取得されるものもありますが、各イベントでしか取得されないものもあるようなので全て入れておいた方がよさそうです。
また、クエリが完了したタイミングで記録されるので、アボートすると記録されないようです。
timestampには完了時間が入るようです。
STARTUP_STATE=ON としたので、SQLサービスが実行されるタイミングでこの拡張イベントは開始されます。
SQL Server Management Studioから確認できます。
MSSQL2008,2008R2の場合は、こちらのコマンドで確認します。
-- Serverに登録されている拡張イベントを確認 select * from sys.server_event_sessions -- 実行されている拡張イベントを確認 select * from sys.dm_xe_sessions
- 拡張イベントの実行
登録後は、実行されていませんので、登録した拡張イベントを開始します。
-- 開始 ALTER EVENT SESSION slowquery_report_2sec ON SERVER STATE = START
- 拡張イベントの結果確認
下記のSQLを実行し、スロークエリの確認をします。
SELECT
xml_data.value('(event/@name)[1]', 'varchar(50)') AS event_name
, DATEADD(hh, 9, xml_data.value('(/event/@timestamp)[1]','datetime')) time
,CASE WHEN CHARINDEX('Server 2012',@@VERSION,1) > 1 THEN
xml_data.value('(/event/data[@name=''cpu_time'']/value)[1]','bigint')
ELSE
xml_data.value('(/event/data[@name=''cpu'']/value)[1]','bigint')
END cpu
,CASE WHEN CHARINDEX('Server 2012',@@VERSION,1) > 1
OR xml_data.value('(event/@name)[1]', 'varchar(50)') <>'rpc_completed'
then xml_data.value('(/event/data[@name=''duration'']/value)[1]','bigint')/1000000.0
else xml_data.value('(/event/data[@name=''duration'']/value)[1]','bigint')/1000.0
end duration_sec
,CASE WHEN CHARINDEX('Server 2012',@@VERSION,1) > 1 THEN
xml_data.value('(/event/data[@name=''logical_reads'']/value)[1]','bigint')
ELSE
xml_data.value('(/event/data[@name=''reads'']/value)[1]','bigint')
END reads
, xml_data.value('(/event/action[@name=''sql_text'']/value)[1]','varchar(max)') sql_text
, xml_data.value('(/event/data[@name=''statement'']/value)[1]','varchar(max)') statement
, xml_data.value('(/event/action[@name=''client_hostname'']/value)[1]','varchar(max)') client_hostname
, xml_data.value('(/event/action[@name=''username'']/value)[1]','varchar(max)') username
FROM
(select object_name as event, CONVERT(xml, event_data) as xml_data
FROM sys.fn_xe_file_target_read_file
('G:\work\ExtendedEvents_log\slowquery*.xel', 'G:\work\ExtendedEvents_log\slowquery*.xem', null, null)
) v
ORDER BY time DESC
2秒以上かかっているクエリを取得できました。
- 拡張イベントの削除
調査後、不要であれば拡張イベントを停止し、削除します。
-- 停止 ALTER EVENT SESSION slowquery_report_2sec ON SERVER STATE = STOP -- 拡張イベントの削除 DROP EVENT SESSION slowquery_report_2sec ON SERVER
