SQL Server - Cómo identificar timeout o conexiones interrumpidas usando Extended Events (XE) o SQL Profiler (Trace)

¡Hola, chicos!
El tema del post de hoy es el tiempo de espera, que consiste en un límite de tiempo (generalmente medido en segundos) en el que una operación esperará hasta finalizar forzosamente la ejecución, si se alcanza este límite de tiempo.

El objetivo de este post es mostrar cómo identificar tiempos de espera o conexiones interrumpidas utilizando Extended Events (XE) o SQL Profiler (Trace) y facilitar el análisis de este tipo de problemas tan comunes en la vida cotidiana.

Después de identificar la causa raíz del tiempo de espera, la solución para resolverlo es intentar optimizar las consultas mediante técnicas de Performance Tuning para reducir el tiempo de ejecución. Dependiendo del proceso, si realmente es algo que implica mucho procesamiento y realmente lleva mucho tiempo, vale la pena aumentar el tiempo de espera para ese proceso específico, pero ese es un tema para mi serie de Ajuste de rendimiento en SQL Server.

En SQL Server tenemos varios tipos de tiempos de espera, donde me gustaría destacar:

• Tiempo de espera de consulta remota (sp_configure), que define el tiempo máximo que se pueden ejecutar consultas remotas (usando el servidor vinculado) (tiempo predeterminado: 600 segundos)
• lock_timeout (comando SET), que es el tiempo que el cliente que ejecuta un comando SQL esperará a que se libere un bloqueo para continuar ejecutando ese comando (tiempo predeterminado: -1 = infinito = esperará indefinidamente)
• Tiempo de espera del comando es una propiedad de los controladores de conexión de bases de datos, como ADO.NET, JDBC y otros, que permite definir un límite de tiempo máximo que una declaración SQL puede ejecutar en la base de datos. Este valor se puede cambiar dinámicamente en la aplicación y puede tener diferentes tiempos de espera, según el contexto. (tiempo predeterminado: 30 segundos)
• Tiempo de espera de conexión es una propiedad de cadena de conexión que le permite establecer un límite de tiempo máximo que el controlador de conexión esperará para establecer una conexión a la base de datos (tiempo predeterminado: 30 segundos)

Tampoco podemos olvidarnos del tiempo de espera de la herramienta de desarrollo (IDE) que utiliza el DBA o desarrollador para acceder a la base de datos.

SQL Server Management Studio (SSMS), por ejemplo, tiene una propiedad llamada "Tiempo de espera de ejecución", que define cuánto tiempo debe esperar SSMS para ejecutar una consulta (internamente, esta es la propiedad Tiempo de espera de comando del controlador de conexión).

El valor predeterminado de esta propiedad en SSMS es 0 (infinito), es decir, no tiene límite de tiempo.

Cómo generar un tiempo de espera usando SQLCMD

Para crear algunos registros de prueba y demostrar cómo identificar tiempos de espera en la base de datos, forzaré que se produzcan tiempos de espera en la base de datos.

Para hacer esto, usaré el Utilidad SQLCMD y la propiedad -t 1 (tiempo de espera de consulta de 1 segundo), y usaré el comando WAITFOR DELAY '00:00:05′, que espera 5 segundos, es decir, cada vez que ejecute este comando, generaré un evento de tiempo de espera.

Resultado de la ejecución:

Tiempos de espera generados.

Cómo identificar tiempos de espera en la base de datos usando Eventos Extendidos (XE)

Para identificar tiempos de espera en la base de datos, he visto a muchas personas usar el tiempo de ejecución de la consulta para definir si hubo un tiempo de espera o no. Como el valor predeterminado es 30 segundos, la persona asume que si la consulta tomó exactamente 30 segundos es porque se agotó el tiempo de espera. Sin embargo, esto no siempre es cierto porque, como mencioné al principio del post, para cada contexto o pantalla del sistema, el desarrollador puede definir diferentes tiempos de espera.

Una de las formas de identificar si realmente se ha producido un tiempo de espera es mediante eventos extendidos (XE), analizando el clase de evento de atencion, disponible desde SQL Server 2012, que indica que ha ocurrido un evento que requiere atención, como cancelaciones, solicitudes de detención de clientes y pérdida de conexiones de clientes. Las operaciones de cancelación también se pueden ver como parte de la implementación de tiempos de espera de acceso a los datos del conductor (tiempos de espera)

Compartiré el script listo para implementar el monitoreo y también capturas de pantalla de la interfaz de Eventos Extendidos, en caso de que desee crearla usted mismo, a través de la pantalla.

Script para monitorear el tiempo de espera en SQL Server usando Eventos Extendidos (XE)

-- Apaga a sessão, caso ela já exista
IF ((SELECT COUNT(*) FROM sys.server_event_sessions WHERE [name] = 'Monitora Timeouts') > 0) DROP EVENT SESSION [Monitora Timeouts] ON SERVER 
GO

CREATE EVENT SESSION [Monitora Timeouts]
ON SERVER
ADD EVENT sqlserver.attention ( 
    ACTION
    (
        sqlserver.client_app_name,
        sqlserver.client_hostname,
        sqlserver.[database_name],
        sqlserver.nt_username,
        sqlserver.num_response_rows,
        sqlserver.server_instance_name,
        sqlserver.server_principal_name,
        sqlserver.server_principal_sid,
        sqlserver.session_id,
        sqlserver.session_nt_username,
        sqlserver.session_server_principal_name,
        sqlserver.sql_text,
        sqlserver.username
    )
)
ADD TARGET package0.event_file ( 
    SET 
        filename = N'D:\SQL\Traces\Monitora_Timeout.xel', -- Não esqueça de mudar o caminho aqui :)
        max_file_size = ( 50 ), -- Tamanho máximo (MB) de cada arquivo
        max_rollover_files = ( 8 ) -- Quantidade de arquivos gerados
)
WITH
(
    STARTUP_STATE = OFF
)

-- Ativando a sessão (por padrão, ela é criada desativada)
ALTER EVENT SESSION [Monitora Timeouts] ON SERVER STATE = START
GO

Interfaz para monitorear el tiempo de espera en SQL Server usando Eventos Extendidos (XE)
Haga clic para ver capturas de pantalla

Captura de pantalla 1: abra el asistente XE a través del Explorador de objetos SSMS

Captura de pantalla 2: pantalla de inicio

Captura de pantalla 3: defina el nombre del evento extendido y marque la casilla para habilitar el evento al final de la configuración.

Captura de pantalla 4: Marcar que no quiero usar ninguna plantilla

Captura de pantalla 5: seleccione el evento de "atención" y agréguelo a la lista de eventos seleccionados

Captura de pantalla 6: Confirme la selección y pase a la siguiente pantalla

Captura de pantalla 7: seleccione los campos de devolución que desea que devuelva el evento

Captura de pantalla 8: Avanzar sin aplicar filtros

Captura de pantalla 9: defina la ubicación para guardar el archivo .xel, el tamaño máximo y la sustitución del archivo

Captura de pantalla 10 – Pantalla final y resumen de operaciones

Script para leer datos escritos por Extended Event (XE)
Haga clic para ver el guión

IF (OBJECT_ID('dbo.Historico_Timeout') IS NULL)
BEGIN

    -- DROP TABLE dbo.Historico_Timeout
    CREATE TABLE dbo.Historico_Timeout (
        [Dt_Evento]            DATETIME,
        [session_id]           INT,
        [duration]             BIGINT,
        [server_instance_name] VARCHAR(100),
        [database_name]        VARCHAR(100),
        [session_nt_username]  VARCHAR(100),
        [nt_username]          VARCHAR(100),
        [client_hostname]      VARCHAR(100),
        [client_app_name]      VARCHAR(100),
        [num_response_rows]    INT,
        [sql_text]             XML
    ) WITH(DATA_COMPRESSION=PAGE)

END


DECLARE @TimeZone INT = DATEDIFF(HOUR, GETUTCDATE(), GETDATE())
DECLARE @Dt_Ultimo_Evento DATETIME = ISNULL((SELECT MAX(Dt_Evento) FROM dbo.Historico_Timeout WITH(NOLOCK)), '1990-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'D:\SQL\Traces\Monitora_Timeout*.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_Evento
    
 
INSERT INTO dbo.Historico_Timeout
SELECT
    A.Dt_Evento,
    xed.event_data.value('(action[@name="session_id"]/value)[1]', 'int') AS [session_id],
    xed.event_data.value('(data[@name="duration"]/value)[1]', 'bigint') AS [duration],
    xed.event_data.value('(action[@name="server_instance_name"]/value)[1]', 'varchar(100)') AS [server_instance_name],
    xed.event_data.value('(action[@name="database_name"]/value)[1]', 'varchar(100)') AS [database_name],
    xed.event_data.value('(action[@name="session_nt_username"]/value)[1]', 'varchar(100)') AS [session_nt_username],
    xed.event_data.value('(action[@name="nt_username"]/value)[1]', 'varchar(100)') AS [nt_username],
    xed.event_data.value('(action[@name="client_hostname"]/value)[1]', 'varchar(100)') AS [client_hostname],
    xed.event_data.value('(action[@name="client_app_name"]/value)[1]', 'varchar(100)') AS [client_app_name],
    xed.event_data.value('(action[@name="num_response_rows"]/value)[1]', 'int') AS [num_response_rows],
    TRY_CAST(xed.event_data.value('(action[@name="sql_text"]/value)[1]', 'varchar(max)') AS XML) AS [sql_text]
FROM
    #Eventos A
    CROSS APPLY A.event_data.nodes('//event') AS xed (event_data)

Ejemplo de datos devueltos:

Cómo identificar tiempos de espera en la base de datos usando SQL Profiler (Trace)

Otra forma de identificar tiempos de espera en la base de datos es usar SQL Profiler (Trace), especialmente si está utilizando una versión anterior a 2012, que no admite el evento de atención de Eventos Extendidos.

Para lograr este objetivo con SQL Profiler, monitorearemos los eventos RPC:Completed, SP:StmtCompleted y SQL:BatchCompleted y filtraremos solo los resultados que cumplan con el filtro Error = 2.

Script para monitorear el tiempo de espera en SQL Server usando SQL Profiler (Trace)

--------------------------------------------------------
-- Armazena os resultados do Trace na tabela
--------------------------------------------------------

DECLARE @Trace_Id INT, @Path VARCHAR(MAX)

SELECT 
    @Trace_Id = id,
    @Path = [path]
FROM 
    sys.traces
WHERE 
    [path] LIKE '%Monitora_Timeout.trc'
 

IF (@Trace_Id IS NOT NULL)
BEGIN

    -- Interrompe o rastreamento especificado.
    EXEC sys.sp_trace_setstatus
        @Trace_Id = @Trace_Id, 
        @status = 0
 
 
    -- Fecha o rastreamento especificado e exclui sua definição do servidor.
    EXEC sys.sp_trace_setstatus 
        @Trace_Id = @Trace_Id,
        @status = 2


    IF (OBJECT_ID('dbo.Historico_Timeout') IS NULL)
    BEGIN
 
        -- DROP TABLE dbo.Historico_Timeout
        CREATE TABLE [dbo].[Historico_Timeout] (
            [TextData]        VARCHAR(MAX),
            [NTUserName]      NVARCHAR(256),
            [HostName]        NVARCHAR(256),
            [ApplicationName] NVARCHAR(256),
            [LoginName]       NVARCHAR(256),
            [Duration]        DECIMAL(15, 2),
            [StartTime]       DATETIME,
            [EndTime]         DATETIME,
            [ServerName]      NVARCHAR(256),
            [DatabaseName]    NVARCHAR(256)
        )
        WITH ( DATA_COMPRESSION = PAGE )
 
        CREATE CLUSTERED INDEX [SK01_Traces] ON [dbo].[Historico_Timeout] ([StartTime]) WITH (FILLFACTOR=80, STATISTICS_NORECOMPUTE=ON, DATA_COMPRESSION = PAGE)
    
    END
 
    
    INSERT INTO dbo.Historico_Timeout (
        TextData,
        NTUserName,
        HostName,
        ApplicationName,
        LoginName,
        Duration,
        StartTime,
        EndTime,
        ServerName,
        DatabaseName
    )
    SELECT
        TextData,
        NTUserName,
        HostName,
        ApplicationName,
        LoginName,
        CAST(Duration / 1000 / 1000.00 AS NUMERIC(15, 2)) Duration,
        StartTime,
        DATEADD(MILLISECOND, Duration / 1000, StartTime) AS EndTime,
        ServerName,
        DatabaseName
    FROM
        ::fn_trace_gettable(@Path, DEFAULT)
    WHERE
        ApplicationName NOT LIKE '%Management Studio%'
        AND Error = 2 -- Abort
    ORDER BY
        StartTime


    --------------------------------------------------------
    -- Apaga o arquivo de trace
    --------------------------------------------------------
    
    DECLARE @Fl_Xp_CmdShell_Ativado BIT = (SELECT (CASE WHEN CAST([value] AS VARCHAR(MAX)) = '1' THEN 1 ELSE 0 END) FROM sys.configurations WHERE [name] = 'xp_cmdshell')
 
    IF (@Fl_Xp_CmdShell_Ativado = 0)
    BEGIN
 
        EXECUTE sp_configure 'show advanced options', 1;
        RECONFIGURE WITH OVERRIDE;
    
        EXEC sp_configure 'xp_cmdshell', 1;
        RECONFIGURE WITH OVERRIDE;
    
    END
 
 
    DECLARE @Cmd VARCHAR(4000) = 'del ' + @Path + ' /Q'
    EXEC sys.xp_cmdshell @Cmd
 
 
    IF (@Fl_Xp_CmdShell_Ativado = 0)
    BEGIN
 
        EXEC sp_configure 'xp_cmdshell', 0;
        RECONFIGURE WITH OVERRIDE;
 
        EXECUTE sp_configure 'show advanced options', 0;
        RECONFIGURE WITH OVERRIDE;
 
    END
 
 
END
 
 
--------------------------------------------------------
-- Ativa o trace novamenmte
--------------------------------------------------------

DECLARE
    @rc INT,
    @TraceID INT,
    @maxfilesize BIGINT = 50,
    @on BIT = 1

EXEC @rc = sp_trace_create @TraceID OUTPUT, 0, N'D:\SQL\Traces\Monitora_Timeout', @maxfilesize, NULL

IF (@rc = 0)
BEGIN

    exec sp_trace_setevent @TraceID, 10, 1, @on
    exec sp_trace_setevent @TraceID, 10, 10, @on
    exec sp_trace_setevent @TraceID, 10, 3, @on
    exec sp_trace_setevent @TraceID, 10, 6, @on
    exec sp_trace_setevent @TraceID, 10, 8, @on
    exec sp_trace_setevent @TraceID, 10, 11, @on
    exec sp_trace_setevent @TraceID, 10, 12, @on
    exec sp_trace_setevent @TraceID, 10, 13, @on
    exec sp_trace_setevent @TraceID, 10, 14, @on
    exec sp_trace_setevent @TraceID, 10, 31, @on
    exec sp_trace_setevent @TraceID, 10, 34, @on
    exec sp_trace_setevent @TraceID, 10, 35, @on
    exec sp_trace_setevent @TraceID, 10, 60, @on
    exec sp_trace_setevent @TraceID, 45, 1, @on
    exec sp_trace_setevent @TraceID, 45, 3, @on
    exec sp_trace_setevent @TraceID, 45, 6, @on
    exec sp_trace_setevent @TraceID, 45, 8, @on
    exec sp_trace_setevent @TraceID, 45, 10, @on
    exec sp_trace_setevent @TraceID, 45, 11, @on
    exec sp_trace_setevent @TraceID, 45, 12, @on
    exec sp_trace_setevent @TraceID, 45, 13, @on
    exec sp_trace_setevent @TraceID, 45, 14, @on
    exec sp_trace_setevent @TraceID, 45, 28, @on
    exec sp_trace_setevent @TraceID, 45, 34, @on
    exec sp_trace_setevent @TraceID, 45, 35, @on
    exec sp_trace_setevent @TraceID, 45, 60, @on
    exec sp_trace_setevent @TraceID, 12, 1, @on
    exec sp_trace_setevent @TraceID, 12, 3, @on
    exec sp_trace_setevent @TraceID, 12, 11, @on
    exec sp_trace_setevent @TraceID, 12, 6, @on
    exec sp_trace_setevent @TraceID, 12, 8, @on
    exec sp_trace_setevent @TraceID, 12, 10, @on
    exec sp_trace_setevent @TraceID, 12, 12, @on
    exec sp_trace_setevent @TraceID, 12, 13, @on
    exec sp_trace_setevent @TraceID, 12, 14, @on
    exec sp_trace_setevent @TraceID, 12, 31, @on
    exec sp_trace_setevent @TraceID, 12, 35, @on
    exec sp_trace_setevent @TraceID, 12, 60, @on


    -- Inclui os filtros
    declare @intfilter int
    declare @bigintfilter bigint

    set @intfilter = 2
    exec sp_trace_setfilter @TraceID, 31, 0, 0, @intfilter

    set @intfilter = NULL
    exec sp_trace_setfilter @TraceID, 31, 0, 1, @intfilter

    -- Ativa o trace
    exec sp_trace_setstatus @TraceID, 1

END

Interfaz para monitorear el tiempo de espera en SQL Server usando SQL Profiler (Trace)
Haga clic para ver capturas de pantalla

Captura de pantalla 1: apertura del Perfilador SQL

Captura de pantalla 2: Conexión a la base de datos

Captura de pantalla 3: seleccione la plantilla de ajuste y haga clic en la pestaña "Selección de evento"

Captura de pantalla 4: marque la casilla de verificación "Mostrar todas las columnas", seleccione la columna "Error" (y cualquier otra que desee devolver) y haga clic en el botón "Filtros de columnas"

Captura de pantalla 5: aplique un filtro a la columna Error y use la medición Error = 2. Marque la casilla de verificación "Excluir filas que no contienen valores"

Captura de pantalla 6: haga clic en el botón Ejecutar para iniciar el seguimiento en el servidor

Captura de pantalla 7: Analizar los resultados encontrados

Captura de pantalla 8: Resultados recopilados y ya almacenados en una tabla de historial

Extracto de un live donde el Marcio Junior demuestra cómo identificar el tiempo de espera en SQL Server

¡Y eso es todo, amigos!
Un fuerte abrazo y hasta luego.