¡Hola, chicos!
En este artículo me gustaría compartir con ustedes cómo identificar y recopilar información de consultas de larga duración utilizando Eventos Extendidos (XE), en un artículo muy similar al SQL Server: cómo identificar y recopilar información de consultas de larga duración utilizando Trace (SQL Server Profiler), que utiliza la tecnología Profiler (Trace).

Lo que me motivó a escribir este artículo fue que Profiler es una característica que ha estado marcada como obsoleta durante mucho tiempo, es una tecnología mucho más antigua y el código no es amigable ni legible en absoluto. Entonces, pensando en brindarles una solución más moderna e intuitiva, decidí compartir esta solución usando XE.

Si todo lo que dije anteriormente aún no es suficiente para que cambies tu Profiler a XE, debes saber que la sobrecarga de XE es MUCHO menor que la de los eventos que usan Trace, como podemos encontrar en los artículos siguientes:

Paso 1: activar el evento extendido en el servidor (SQL 2012+)

Para comenzar a monitorear los comandos que se ejecutan en la instancia, habilitemos el evento extendido capturando los eventos del comando. sqlserver.sql_batch_completed. Incluso podría ser sqlserver.sp_statement_completed y/o sqlserver.sql_statement_completed, pero solo capturaría las partes de una consulta ad-hoc o SP que hayan superado el límite de tiempo de duración. En este artículo, mi objetivo es capturar todo el SP o lote que haya pasado el límite de tiempo y luego analizarlo para descubrir qué declaración está tardando más.

-- 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 este seguimiento, establecí el límite de tiempo para capturar consultas en 3 segundos. Si se ha alcanzado o superado este tiempo, la consulta queda registrada en nuestro seguimiento. Configuré el destino de los datos recopilados en "C:\Traces\Query Slow", con un tamaño máximo de 10 MB de datos y un máximo de 10 archivos. Debido a que la implementación está configurada, los archivos siempre conservarán los datos más recientes, por lo que no debemos preocuparnos por eliminar los datos o que los archivos crezcan demasiado.

Paso 1: activar el evento extendido en el servidor (SQL 2008)

Si todavía está utilizando SQL Server 2008 en su entorno (ya es hora de migrar, eh... el soporte finaliza en julio de 2019), notará que al intentar crear los eventos extendidos descritos anteriormente, recibirá el siguiente mensaje de error:

Mensaje 25623, Nivel 16, Estado 1, Línea 16
El nombre del evento, "sqlserver.sql_batch_completed", no es válido o no se pudo encontrar el objeto

Esto ocurre porque en SQL Server 2008, este evento aún no era compatible, como podemos ver usando la siguiente consulta:

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:

En otras palabras, si queremos implementar una solución de monitoreo de consultas lentas usando Extended Events, tendremos que buscar otro tipo de eventos, y para este caso usaré los métodos sp_statement_completed y sql_statement_completed:

-- 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

A diferencia del método que usé anteriormente (sql_batch_completed), que mide el tiempo de ejecución de todo el lote, estos 2 tipos de eventos capturarán secciones de consulta o Procedimientos Almacenados que excedan el límite de tiempo, es decir, si tienes un Procedimiento Almacenado que tarda 40 segundos en ejecutarse y ninguna de las declaraciones excede los 3 segundos, este SP no será monitoreado.

Paso 2: crear la tabla del historial de datos

Para almacenar los datos recogidos por nuestro seguimiento, crearemos una tabla física que utilizaremos para introducir los datos y, posteriormente, consultar los datos recogidos cuando sea necesario.

Servidor SQL 2012+

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

Servidor SQL 2008:

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

Paso 3: cree el procedimiento almacenado para capturar los datos

Ahora que estamos monitoreando consultas, necesitamos leer los datos recopilados y almacenarlos en una tabla física para consultas, ya que configuré el tamaño máximo de archivo para que sea muy pequeño (10 MB) para que las consultas sean siempre rápidas. Dependiendo de la cantidad de consultas pesadas en su entorno, puede aumentar o disminuir el tamaño máximo según su entorno.

Para capturar datos en SQL Server 2012+, utilizaremos el procedimiento almacenado a continuación:

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

Si está utilizando SQL Server 2008, también preparé un procedimiento almacenado para usted 🙂

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

Paso 4: cree un trabajo en el Agente SQL para automatizar la recopilación de datos

Para que los datos recopilados siempre se escriban en la tabla que creamos, ahora debe crear un Trabajo en el Agente SQL Server para automatizar la ejecución del Procedimiento almacenado creado en el Punto 3, de acuerdo con la frecuencia con la que necesita que se escriban los datos.

Mi sugerencia es comenzar con ejecuciones cada 10 minutos y ajustar este tiempo según sea necesario.

A continuación compartiré un ejemplo de código para crear el Job, pero creo que crearlo usando la interfaz de SQL Server Management Studio (SSMS) es mucho más práctico e intuitivo, ¿verdad?

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

Y finalmente, ahora que nuestro monitoreo está activado y ya tenemos un trabajo para automatizar la recopilación de estos datos y escribirlos en una tabla de base de datos, podemos consultar los datos de esta tabla siempre que sea necesario para identificar consultas lentas en nuestro entorno.

Ejemplo de ejecución:

Tenga en cuenta que la última columna (Resultado) nos informa si el comando se ejecutó exitosamente o si fue interrumpido. Muy bien, ¿verdad?

Espero que te haya gustado este tip, un fuerte abrazo y nos vemos en el próximo artículo.