- SQL Server – Introdução ao estudo de Performance Tuning
- Entendendo o funcionamento dos índices no SQL Server
- SQL Server – Como identificar uma query lenta ou “pesada” no seu banco de dados
- SQL Server – Dicas de Performance Tuning: Conversão implícita? NUNCA MAIS!
- SQL Server – Comparação de performance entre Scalar Function e CLR Scalar Function
- SQL Server – Dicas de Performance Tuning: Qual a diferença entre Seek Predicate e Predicate?
- SQL Server – Utilizando colunas calculadas (ou colunas computadas) para Performance Tuning
- SQL Server – Como identificar e coletar informações de consultas demoradas utilizando Extended Events (XE)
- SQL Server – Como identificar todos os índices ausentes (Missing indexes) de um banco de dados
- SQL Server e Azure SQL Database: Como Identificar ocorrências de Key Lookup através da plancache
Fala pessoal!
Nesse artigo eu gostaria de compartilhar com vocês como identificar e coletar informações de consultas demoradas utilizando Extended Events (XE), num artigo bem parecido com o SQL Server – Como identificar e coletar informações de consultas demoradas utilizando Trace (SQL Server Profiler), que utiliza a tecnologia de Profiler (Trace).
O que me motivou a escrever esse artigo foi que o Profiler é um recurso que está marcado como deprecated há bastante tempo, é uma tecnologia bem mais antiga e o código não é nada amigável ou legível. Então, pensando em trazer uma solução mais moderna e intuitiva para vocês, resolvi compartilhar essa solução utilizando o XE.
Se tudo o que eu falei acima ainda não é suficiente para você trocar o seu Profiler pelo XE, saiba que o overhead do XE é MUITO menor que de eventos utilizando Trace, conforme podemos encontrar nos artigos abaixo:
- Comparing Extended Events vs SQL Trace – or why SQL Trace & Profiler are just a thing of the past
- Performance overhead of tracing with Extended Event targets vs SQL Trace under CPU Load
- Measuring “Observer Overhead” of SQL Trace vs. Extended Events
Passo 1 – Ativar o Extended Event no Servidor (SQL 2012+)
A fim de começar a monitorar os comandos que são executados na instância, vamos ativar o Extended Event capturando os eventos de sqlserver.sql_batch_completed. Poderia até ser o sqlserver.sp_statement_completed e/ou sqlserver.sql_statement_completed, mas iria capturar apenas os trechos de uma query ad-hoc ou SP que passaram do tempo limite de duração. Nesse artigo, o meu objetivo é capturar a SP ou batch inteiro que passou do tempo limite e depois analiso para saber qual o statement que está demorando mais.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 |
-- Apaga a sessão, caso ela já exista IF ((SELECT COUNT(*) FROM sys.server_event_sessions WHERE [name] = 'Query Lenta') > 0) DROP EVENT SESSION [Query Lenta] ON SERVER GO -- Cria o Extended Event no servidor, configurado para iniciar automaticamente quando o serviço do SQL é iniciado CREATE EVENT SESSION [Query Lenta] ON SERVER ADD EVENT sqlserver.sql_batch_completed ( ACTION ( sqlserver.session_id, sqlserver.client_app_name, sqlserver.client_hostname, sqlserver.database_name, sqlserver.username, sqlserver.session_nt_username, sqlserver.session_server_principal_name, sqlserver.sql_text ) WHERE duration > (3000000) -- 3 segundos ) ADD TARGET package0.event_file ( SET filename=N'C:\Traces\Query Lenta', max_file_size=(10), max_rollover_files=(10) ) WITH (STARTUP_STATE=ON) GO -- Ativa o Extended Event ALTER EVENT SESSION [Query Lenta] ON SERVER STATE = START GO |
Para esse monitoramento, defini que o limite de tempo para capturar as consultas é de 3 segundos. Atingiu ou passou desse tempo, a consulta é logada no nosso monitoramento. O destino dos dados coletados eu configurei para “C:\Traces\Query Lenta”, com tamanho máximo de 10 MB de dados e 10 arquivos no máximo. Como o rollout está configurado, os arquivos vão manter sempre os dados mais recentes, então não precisamos nos preocupar com expurgar os dados ou com os arquivos crescendo muito.
Passo 1 – Ativar o Extended Event no Servidor (SQL 2008)
Caso você ainda esteja utilizando o SQL Server 2008 no seu ambiente (já passou da hora de migrar hein.. suporte acaba em julho/2019), irá notar que ao tentar criar o Extended Events descrito acima, você receberá a mensagem de erro abaixo:
The event name, “sqlserver.sql_batch_completed”, is invalid, or the object could not be found
Isso ocorre porque no SQL Server 2008, esse evento ainda não era suportado, conforme podemos consultar utilizando a query abaixo:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 |
SELECT p.[name] package_name, o.[name] event_name, c.[name] event_field, c.[type_name] field_type, c.column_type column_type FROM sys.dm_xe_objects o JOIN sys.dm_xe_packages p ON o.package_guid = p.[guid] JOIN sys.dm_xe_object_columns c ON o.[name] = c.[object_name] WHERE o.object_type = 'event' AND o.[name] LIKE '%_completed%' ORDER BY package_name, event_name |
Resultado:
Ou seja, se quisermos implementar uma solução de monitoramento de query lenta utilizando Extended Events, teremos que buscar outros tipos de evento, e para este caso, vou utilizar os métodos sp_statement_completed e sql_statement_completed:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 |
-- Apaga a sessão, caso ela já exista IF ((SELECT COUNT(*) FROM sys.server_event_sessions WHERE [name] = 'Query Lenta') > 0) DROP EVENT SESSION [Query Lenta] ON SERVER GO -- Cria o Extended Event no servidor, configurado para iniciar automaticamente quando o serviço do SQL é iniciado CREATE EVENT SESSION [Query Lenta] ON SERVER ADD EVENT sqlserver.sp_statement_completed ( ACTION ( sqlserver.session_id, sqlserver.client_app_name, sqlserver.client_hostname, sqlserver.username, sqlserver.database_id, sqlserver.session_nt_username, sqlserver.sql_text ) WHERE duration > (3000000) -- 3 segundos ), ADD EVENT sqlserver.sql_statement_completed ( ACTION ( sqlserver.session_id, sqlserver.client_app_name, sqlserver.client_hostname, sqlserver.username, sqlserver.database_id, sqlserver.session_nt_username, sqlserver.sql_text ) WHERE duration > (3000000) -- 3 segundos ) ADD TARGET package0.asynchronous_file_target ( SET filename=N'C:\Traces\Query Lenta 2008.xel', max_file_size=(100), max_rollover_files=(1) ) WITH (STARTUP_STATE=ON) GO -- Ativa o Extended Event ALTER EVENT SESSION [Query Lenta] ON SERVER STATE = START GO |
Diferente do método que utilizei anteriormente (sql_batch_completed), que mede o tempo de execução de todo o batch, esses 2 tipos de eventos vão capturar trechos de query ou Stored Procedures que ultrapassem o tempo limite, ou seja, se você tem um Stored Procedure que demora 40s para executar e nenhum dos statements ultrapassa os 3 segundos, essa SP não cairá no monitoramento.
Passo 2 – Criar a Tabela de Histórico dos Dados
Para armazenar os dados coletados pelo nosso monitoramento, vamos criar uma tabela física que utilizaremos para inserir os dados e, posteriormente, para consultar os dados coletados sempre que necessário.
SQL Server 2012+
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 |
CREATE TABLE dbo.Historico_Query_Lenta ( [Dt_Evento] DATETIME, [session_id] INT, [database_name] VARCHAR(128), [username] VARCHAR(128), [session_server_principal_name] VARCHAR(128), [session_nt_username] VARCHAR(128), [client_hostname] VARCHAR(128), [client_app_name] VARCHAR(128), [duration] DECIMAL(18, 2), [cpu_time] DECIMAL(18, 2), [logical_reads] BIGINT, [physical_reads] BIGINT, [writes] BIGINT, [row_count] BIGINT, [sql_text] XML, [batch_text] XML, [result] VARCHAR(100) ) WITH(DATA_COMPRESSION=PAGE) GO CREATE CLUSTERED INDEX SK01_Historico_Query_Lenta ON dbo.Historico_Query_Lenta (Dt_Evento) WITH(DATA_COMPRESSION=PAGE) GO |
SQL Server 2008:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 |
CREATE TABLE dbo.Historico_Query_Lenta ( Dt_Evento DATETIME, Tp_Evento VARCHAR(50), session_id INT, database_id INT, [database_name] VARCHAR(128), [object_id] INT, [object_name] VARCHAR(128), username VARCHAR(128), session_nt_username VARCHAR(128), client_hostname VARCHAR(128), client_app_name VARCHAR(128), duration NUMERIC(18, 2), cpu_time NUMERIC(18, 2), reads BIGINT, writes BIGINT, sql_text VARCHAR(MAX) ) WITH (DATA_COMPRESSION = PAGE) GO CREATE CLUSTERED INDEX [SK01_Historico_Query_Lenta] ON [dbo].[Historico_Query_Lenta] ([Dt_Evento]) WITH (DATA_COMPRESSION = PAGE) GO |
Passo 3 – Criar a Stored Procedure para Capturar os Dados
Agora que já estamos monitorando as consultas, precisamos ler os dados coletados e armazenar em uma tabela física para consultas, já que configurei o tamanho máximo dos arquivos bem pequenos (10 MB) para que as consultas sejam sempre rápidas. Dependendo da quantidade de consultas pesadas no seu ambiente, você pode aumentar o diminuir o tamanho máximo de acordo com o seu ambiente.
Para capturar os dados no SQL Server 2012+, vamos utilizar a Stored Procedure abaixo:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 |
USE [dirceuresende] GO IF (OBJECT_ID('dbo.stpCarga_Query_Lenta') IS NULL) EXEC('CREATE PROCEDURE dbo.stpCarga_Query_Lenta AS SELECT 1') GO ALTER PROCEDURE dbo.stpCarga_Query_Lenta AS BEGIN DECLARE @TimeZone INT = DATEDIFF(HOUR, GETUTCDATE(), GETDATE()), @Dt_Ultimo_Registro DATETIME = ISNULL((SELECT MAX(Dt_Evento) FROM dbo.Historico_Query_Lenta), '1900-01-01') IF (OBJECT_ID('tempdb..#Eventos') IS NOT NULL) DROP TABLE #Eventos ;WITH CTE AS ( SELECT CONVERT(XML, event_data) AS event_data FROM sys.fn_xe_file_target_read_file(N'C:\Traces\Query Lenta*.xel', NULL, NULL, NULL) ) SELECT DATEADD(HOUR, @TimeZone, CTE.event_data.value('(//event/@timestamp)[1]', 'datetime')) AS Dt_Evento, CTE.event_data INTO #Eventos FROM CTE WHERE DATEADD(HOUR, @TimeZone, CTE.event_data.value('(//event/@timestamp)[1]', 'datetime')) > @Dt_Ultimo_Registro INSERT INTO dbo.Historico_Query_Lenta SELECT A.Dt_Evento, xed.event_data.value('(action[@name="session_id"]/value)[1]', 'int') AS session_id, xed.event_data.value('(action[@name="database_name"]/value)[1]', 'varchar(128)') AS [database_name], xed.event_data.value('(action[@name="username"]/value)[1]', 'varchar(128)') AS username, xed.event_data.value('(action[@name="session_server_principal_name"]/value)[1]', 'varchar(128)') AS session_server_principal_name, xed.event_data.value('(action[@name="session_nt_username"]/value)[1]', 'varchar(128)') AS [session_nt_username], xed.event_data.value('(action[@name="client_hostname"]/value)[1]', 'varchar(128)') AS [client_hostname], xed.event_data.value('(action[@name="client_app_name"]/value)[1]', 'varchar(128)') AS [client_app_name], CAST(xed.event_data.value('(//data[@name="duration"]/value)[1]', 'bigint') / 1000000.0 AS NUMERIC(18, 2)) AS duration, CAST(xed.event_data.value('(//data[@name="cpu_time"]/value)[1]', 'bigint') / 1000000.0 AS NUMERIC(18, 2)) AS cpu_time, xed.event_data.value('(//data[@name="logical_reads"]/value)[1]', 'bigint') AS logical_reads, xed.event_data.value('(//data[@name="physical_reads"]/value)[1]', 'bigint') AS physical_reads, xed.event_data.value('(//data[@name="writes"]/value)[1]', 'bigint') AS writes, xed.event_data.value('(//data[@name="row_count"]/value)[1]', 'bigint') AS row_count, TRY_CAST(xed.event_data.value('(//action[@name="sql_text"]/value)[1]', 'varchar(max)') AS XML) AS sql_text, TRY_CAST(xed.event_data.value('(//data[@name="batch_text"]/value)[1]', 'varchar(max)') AS XML) AS batch_text, xed.event_data.value('(//data[@name="result"]/text)[1]', 'varchar(100)') AS result FROM #Eventos A CROSS APPLY A.event_data.nodes('//event') AS xed (event_data) END |
Caso você esteja utilizando o SQL Server 2008, preparei uma Stored Procedure para você também 🙂
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 |
IF (OBJECT_ID('dbo.stpCarga_Query_Lenta') IS NULL) EXEC('CREATE PROCEDURE dbo.stpCarga_Query_Lenta AS SELECT 1') GO ALTER PROCEDURE dbo.stpCarga_Query_Lenta AS BEGIN DECLARE @TimeZone INT = DATEDIFF(HOUR, GETUTCDATE(), GETDATE()), @Dt_Ultimo_Registro DATETIME = ISNULL((SELECT MAX(Dt_Evento) FROM dbo.Historico_Query_Lenta), '1900-01-01') IF (OBJECT_ID('tempdb..#Eventos') IS NOT NULL) DROP TABLE #Eventos ;WITH CTE AS ( SELECT CONVERT(XML, event_data) AS event_data FROM sys.fn_xe_file_target_read_file(N'C:\Traces\Query Lenta 2008*.xel', N'C:\Traces\Query Lenta 2008*.xem', NULL, NULL) ) SELECT DATEADD(HOUR, @TimeZone, CTE.event_data.value('(//event/@timestamp)[1]', 'datetime')) AS Dt_Evento, CTE.event_data INTO #Eventos FROM CTE WHERE DATEADD(HOUR, @TimeZone, CTE.event_data.value('(//event/@timestamp)[1]', 'datetime')) > @Dt_Ultimo_Registro INSERT INTO dbo.Historico_Query_Lenta ( Dt_Evento, Tp_Evento, session_id, database_id, [database_name], [object_id], [object_name], username, session_nt_username, client_hostname, client_app_name, duration, cpu_time, reads, writes, sql_text ) SELECT A.Dt_Evento, xed.event_data.value('@name[1]', 'varchar(128)') AS event_name, xed.event_data.value('(action[@name="session_id"]/value)[1]', 'int') AS session_id, xed.event_data.value('(action[@name="database_id"]/value)[1]', 'int') AS [database_id], DB_NAME(xed.event_data.value('(action[@name="database_id"]/value)[1]', 'int')) AS [database_name], xed.event_data.value('(data[@name="object_id"]/value)[1]', 'int') AS [object_id], OBJECT_NAME(xed.event_data.value('(data[@name="object_id"]/value)[1]', 'int'), xed.event_data.value('(action[@name="database_id"]/value)[1]', 'int')) AS [object_name], xed.event_data.value('(action[@name="username"]/value)[1]', 'varchar(128)') AS username, xed.event_data.value('(action[@name="session_nt_username"]/value)[1]', 'varchar(128)') AS [session_nt_username], xed.event_data.value('(action[@name="client_hostname"]/value)[1]', 'varchar(128)') AS [client_hostname], xed.event_data.value('(action[@name="client_app_name"]/value)[1]', 'varchar(128)') AS [client_app_name], CAST(xed.event_data.value('(//data[@name="duration"]/value)[1]', 'bigint') / 1000000.0 AS NUMERIC(18, 2)) AS duration, CAST(xed.event_data.value('(//data[@name="cpu"]/value)[1]', 'bigint') / 1000000.0 AS NUMERIC(18, 2)) AS cpu_time, xed.event_data.value('(//data[@name="reads"]/value)[1]', 'bigint') AS reads, xed.event_data.value('(//data[@name="writes"]/value)[1]', 'bigint') AS writes, xed.event_data.value('(//action[@name="sql_text"]/value)[1]', 'varchar(max)') AS sql_text FROM #Eventos A CROSS APPLY A.event_data.nodes('//event') AS xed (event_data) END |
Passo 4 – Criar um job no SQL Agent para automatizar a coleta dos dados
Para que os dados coletados sejam sempre gravados na tabela que criamos, agora você deve criar um Job no SQL Server Agent para automatizar a execução da Stored Procedure criada no Item 3, de acordo com a frequência que você precisa que sejam gravados os dados.
A minha sugestão, é começar com execuções a cada 10 minutos e ir ajustando esse tempo conforme a necessidade.
Abaixo, vou compartilhar um exemplo de código para criação do Job, mas acredito que criar pela interface do SQL Server Management Studio (SSMS) seja bem mais prático e intuitivo, né ?
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 |
USE [msdb] GO DECLARE @jobId BINARY(16) EXEC msdb.dbo.sp_add_job @job_name=N'DBA - Coleta de Query Lenta', @enabled=1, @notify_level_eventlog=0, @notify_level_email=2, @notify_level_page=2, @delete_level=0, @category_name=N'Database Maintenance', @owner_login_name=N'dirceu.resende', @job_id = @jobId OUTPUT select @jobId GO EXEC msdb.dbo.sp_add_jobserver @job_name=N'DBA - Coleta de Query Lenta', @server_name = N'SQLSERVER\SQL2017' GO USE [msdb] GO EXEC msdb.dbo.sp_add_jobstep @job_name=N'DBA - Coleta de Query Lenta', @step_name=N'Executa SP', @step_id=1, @cmdexec_success_code=0, @on_success_action=1, @on_fail_action=2, @retry_attempts=0, @retry_interval=0, @os_run_priority=0, @subsystem=N'TSQL', @command=N'EXEC dbo.stpCarga_Query_Lenta', @database_name=N'dirceuresende', @flags=8 GO USE [msdb] GO EXEC msdb.dbo.sp_update_job @job_name=N'DBA - Coleta de Query Lenta', @enabled=1, @start_step_id=1, @notify_level_eventlog=0, @notify_level_email=2, @notify_level_page=2, @delete_level=0, @description=N'', @category_name=N'Database Maintenance', @owner_login_name=N'dirceu.resende', @notify_email_operator_name=N'', @notify_page_operator_name=N'' GO USE [msdb] GO DECLARE @schedule_id int EXEC msdb.dbo.sp_add_jobschedule @job_name=N'DBA - Coleta de Query Lenta', @name=N'A cada 10 minutos', @enabled=1, @freq_type=4, @freq_interval=1, @freq_subday_type=4, @freq_subday_interval=10, @freq_relative_interval=0, @freq_recurrence_factor=1, @active_start_date=20190218, @active_end_date=99991231, @active_start_time=112, @active_end_time=235959, @schedule_id = @schedule_id OUTPUT select @schedule_id GO |
E por fim, agora que nosso monitoramento está ativado e já temos um job para automatizar a coleta desses dados e gravá-los em uma tabela do banco de dados, podemos consultar os dados dessa tabela sempre que for necessário identificar consultas lentas no nosso ambiente.
Exemplo de execução:
Reparem que a última coluna (Result) nos informa se o comando foi executado com sucesso ou se ele foi interrompido. Bem legal, né ?
Espero que tenham gostado dessa dica, um grande abraço e até o próximo artigo.
Portuguese 
English
Uma alternativa a essa rotina de coleta, seria guardar o retorno da sp_Whoisactive em uma tabela, mas ai a limitação de coleta fica a no mínimo 10 Seg (Frequência mínima de exec de job). Por outro lado tem mais algumas informações uteis, como o tipo de wait que a sessão esta sofrendo (caso esteja), blocks, etc…
Só vai precisar fazer uma rotina de expurgo pra não guardar dados da vida toda
Vale lembrar que isso não seria uma implementação nativa do SQL, seria mais um “Recurso técnico”, mas pode ser bem útil.
Eu implementei no ambiente a versão 2012+, mas não está capturando o texto da queries AD-HOC.
Excelente postagem, Dirceu! Havia implementado em meus ambientes utilizando o sql_statement_completed e o sp_statement_completed porém vou passar a utilizar o batch_completed com sua dica. Além disso, me ajudou muito visualizar os dados através do Power B, como por exemplo, focar naquelas que são mais executadas durante o horário de trabalho. Só uma dúvida: você chegou a testar obtendo também o query_hash e o plan_handle? Abraços.
Bom dia. O Extended Events foi implementado a partir do SQL Server 2012.
a partir de qual versão funciona?