sp_StatUpdate_XE_Session.sql

/*
sp_StatUpdate Extended Events Troubleshooting Session

Purpose:    Monitor sp_StatUpdate execution for troubleshooting.
            Captures both statement START and COMPLETION events for before/after
            correlation, plus wait stats, errors, blocking, and -- as the
            truthful proof surface for sort-spill diagnostics -- sort_warning.

            PRESELECTION vs PROOF (gh-552):  sp_StatUpdate's Query Store metrics
            (TEMPDB_SPILLS, WAITS, WAIT_CPU) rank which stats to update BEFORE a
            run.  They are NOT evidence about the UPDATE STATISTICS statements
            themselves -- a DDL statement is not represented in Query Store wait
            data in a way that supports direct spill attribution.  This XE
            session is the proof surface: sort_warning fires from the actual
            spilling UPDATE STATISTICS statement, filtered to the generated
            command text and correlatable to its CommandLog row by time.

Usage:
    1. Run this script to create the XE session
    2. Start the session before running sp_StatUpdate
    3. Review events after completion or during execution

To start:   ALTER EVENT SESSION [sp_StatUpdate_Monitor] ON SERVER STATE = START;
To stop:    ALTER EVENT SESSION [sp_StatUpdate_Monitor] ON SERVER STATE = STOP;
To drop:    DROP EVENT SESSION [sp_StatUpdate_Monitor] ON SERVER;
To view:    See queries at bottom of this script

Version:    2.2.2026.07.25 (Major.Minor.YYYY.MM.DD)

History:    2.2.2026.07.25 - sort_warning (primary) + hash_warning (secondary) spill
                             proof events for UPDATE STATISTICS, filtered to the
                             generated command text with context_info correlation;
                             analysis queries 6 (spill events) and 7 (join spills to
                             CommandLog, UTC->local aligned); preselection-vs-proof
                             documented (gh-552)
            2.1.2026.03.19 - Dynamic map_key resolution for wait_type predicates (#290)
            2.0.2026.02.12 - Added starting events for during-execution visibility
            1.0.2026.01.28 - Initial creation for sp_StatUpdate troubleshooting (#8)
*/

-- Drop existing session if present
IF EXISTS (SELECT 1 FROM sys.server_event_sessions WHERE name = N'sp_StatUpdate_Monitor')
BEGIN
    DROP EVENT SESSION [sp_StatUpdate_Monitor] ON SERVER;
END;
GO

/*
    Resolve wait_type map_key values dynamically from sys.dm_xe_map_values.
    These numeric values are version-specific — hardcoding them caused silent
    no-op filtering on mismatched SQL Server versions (#290).
*/
DECLARE @wait_types TABLE (wait_name NVARCHAR(60), map_key INT);

INSERT INTO @wait_types (wait_name, map_key)
SELECT map_value, map_key
FROM sys.dm_xe_map_values
WHERE name = N'wait_types'
AND   map_value IN (
    N'LCK_M_SCH_S',      /* schema stability lock */
    N'LCK_M_SCH_M',      /* schema modification lock */
    N'LCK_M_U',          /* update lock */
    N'LCK_M_X',          /* exclusive lock */
    N'PAGEIOLATCH_SH',   /* shared page I/O latch */
    N'PAGEIOLATCH_EX',   /* exclusive page I/O latch */
    N'CXPACKET',         /* parallel query waits */
    N'NETWORK_IO'        /* client waiting (shown as ASYNC_NETWORK_IO in DMVs) */
);

/* Pre-flight: warn about any wait types not found on this version */
DECLARE @missing NVARCHAR(500) = N'';
DECLARE @expected TABLE (wait_name NVARCHAR(60));
INSERT INTO @expected (wait_name) VALUES
    (N'LCK_M_SCH_S'), (N'LCK_M_SCH_M'), (N'LCK_M_U'), (N'LCK_M_X'),
    (N'PAGEIOLATCH_SH'), (N'PAGEIOLATCH_EX'), (N'CXPACKET'), (N'NETWORK_IO');

SELECT @missing = @missing + e.wait_name + N', '
FROM @expected AS e
LEFT JOIN @wait_types AS w ON w.wait_name = e.wait_name
WHERE w.map_key IS NULL;

IF LEN(@missing) > 0
BEGIN
    SET @missing = LEFT(@missing, LEN(@missing) - 1);
    DECLARE @warn NVARCHAR(4000) = N'Warning: wait types not found in sys.dm_xe_map_values on this SQL Server version: ' + @missing
        + N'. Wait event filtering will exclude these types.';
    RAISERROR(@warn, 10, 1) WITH NOWAIT;
END;

/* Build the wait_type predicate dynamically */
DECLARE @wait_predicate NVARCHAR(1000) = N'';
DECLARE @wk INT, @wn NVARCHAR(60);

DECLARE wait_cur CURSOR LOCAL FAST_FORWARD FOR
    SELECT map_key, wait_name FROM @wait_types ORDER BY map_key;
OPEN wait_cur;
FETCH NEXT FROM wait_cur INTO @wk, @wn;
WHILE @@FETCH_STATUS = 0
BEGIN
    IF @wait_predicate <> N''
        SET @wait_predicate = @wait_predicate + N'
            OR ';
    SET @wait_predicate = @wait_predicate + N'wait_type = ' + CONVERT(NVARCHAR(10), @wk)
        + N'    /* ' + @wn + N' */';
    FETCH NEXT FROM wait_cur INTO @wk, @wn;
END;
CLOSE wait_cur;
DEALLOCATE wait_cur;

/* If no wait types resolved at all, use a FALSE predicate so the event is harmless */
IF @wait_predicate = N''
BEGIN
    RAISERROR(N'Warning: No wait types resolved. Wait event will capture nothing.', 10, 1) WITH NOWAIT;
    SET @wait_predicate = N'wait_type = -1 /* no wait types resolved */';
END;

/* Build and execute the full CREATE EVENT SESSION DDL.
   CONVERT(NVARCHAR(MAX), ...) on the first operand forces the whole
   concatenation to MAX -- otherwise literal + @wait_predicate + literal caps at
   4000 nchars and silently truncates the DDL mid-token (gh-552: adding the
   sort_warning/hash_warning events pushed the session past 4000 and exposed it,
   producing "Incorrect syntax near '.'" as the DDL ended at a dangling
   "sqlserver."). Part B is appended via a separate SET so it stays MAX too. */
DECLARE @sql NVARCHAR(MAX) = CONVERT(NVARCHAR(MAX), N'
CREATE EVENT SESSION [sp_StatUpdate_Monitor] ON SERVER

/* Capture UPDATE STATISTICS command START (for during-execution visibility) */
ADD EVENT sqlserver.sp_statement_starting
(
    ACTION (sqlserver.session_id, sqlserver.database_name, sqlserver.sql_text)
    WHERE (
        sqlserver.like_i_sql_unicode_string(sqlserver.sql_text, N''%UPDATE STATISTICS%'')
    )
),

/* Capture UPDATE STATISTICS command COMPLETION (duration, CPU, reads) */
ADD EVENT sqlserver.sp_statement_completed
(
    ACTION (sqlserver.session_id, sqlserver.database_name, sqlserver.sql_text, sqlserver.query_hash)
    WHERE (
        sqlserver.like_i_sql_unicode_string(sqlserver.sql_text, N''%UPDATE STATISTICS%'')
        OR sqlserver.like_i_sql_unicode_string(sqlserver.sql_text, N''%sp_StatUpdate%'')
    )
),

/* Capture errors during execution */
ADD EVENT sqlserver.error_reported
(
    ACTION (sqlserver.session_id, sqlserver.database_name, sqlserver.sql_text)
    WHERE (
        severity >= 11
        OR error_number = 1222  /* Lock timeout */
        OR error_number = 1205  /* Deadlock victim */
        OR error_number = 3621  /* Statement aborted */
        OR error_number = 8115  /* Arithmetic overflow */
    )
),

/* Capture wait statistics for blocking/performance issues */
/* map_key values resolved dynamically from sys.dm_xe_map_values (#290) */
ADD EVENT sqlos.wait_completed
(
    ACTION (sqlserver.session_id, sqlserver.database_name)
    WHERE (
        duration > 1000000  /* > 1 second (in microseconds) */
        AND (
               ') + @wait_predicate;
SET @sql = @sql + N'
        )
    )
),

/* Capture UPDATE STATISTICS statement START (sql_statement level) */
ADD EVENT sqlserver.sql_statement_starting
(
    ACTION (sqlserver.session_id, sqlserver.database_name, sqlserver.sql_text)
    WHERE (
        sqlserver.like_i_sql_unicode_string(sqlserver.sql_text, N''%UPDATE STATISTICS%'')
    )
),

/* Capture long-running UPDATE STATISTICS COMPLETION (> 10 seconds) */
ADD EVENT sqlserver.sql_statement_completed
(
    ACTION (sqlserver.session_id, sqlserver.database_name, sqlserver.sql_text, sqlserver.plan_handle)
    WHERE duration > 10000000  /* > 10 seconds (in microseconds) */
    AND sqlserver.like_i_sql_unicode_string(sqlserver.sql_text, N''%UPDATE STATISTICS%'')
),

/* SPILL PROOF (gh-552, PRIMARY): sort_warning is the truthful evidence surface
   for a sort spill in the generated UPDATE STATISTICS statement.  Query Store
   TEMPDB_SPILLS/WAITS metrics only PRESELECT candidates before the run; they do
   not prove the stats-update statement itself spilled -- this event does.
   Filtered to the UPDATE STATISTICS command text; context_info carries the
   sp_StatUpdate run tag (gh-423) for session attribution, plan_handle links to
   the plan.  Correlate to CommandLog by time via analysis query 7. */
ADD EVENT sqlserver.sort_warning
(
    ACTION (sqlserver.session_id, sqlserver.database_name, sqlserver.sql_text,
            sqlserver.plan_handle, sqlserver.context_info)
    WHERE (
        sqlserver.like_i_sql_unicode_string(sqlserver.sql_text, N''%UPDATE STATISTICS%'')
    )
),

/* SPILL PROOF (gh-552, SECONDARY/supporting context): hash_warning flags a hash
   spill during the same statement.  Labeled secondary -- sort_warning is the
   primary proof for stats-maintenance sort spills. */
ADD EVENT sqlserver.hash_warning
(
    ACTION (sqlserver.session_id, sqlserver.database_name, sqlserver.sql_text,
            sqlserver.plan_handle, sqlserver.context_info)
    WHERE (
        sqlserver.like_i_sql_unicode_string(sqlserver.sql_text, N''%UPDATE STATISTICS%'')
    )
),

/* Capture lock escalation (common during large stat scans) */
ADD EVENT sqlserver.lock_escalation
(
    ACTION (sqlserver.session_id, sqlserver.database_name, sqlserver.sql_text)
),

/* Capture query timeouts and cancellations (attention = client cancel or timeout) */
ADD EVENT sqlserver.attention
(
    ACTION (sqlserver.session_id, sqlserver.database_name, sqlserver.sql_text)
),

/* Capture deadlocks involving stat maintenance */
ADD EVENT sqlserver.xml_deadlock_report
(
    ACTION (sqlserver.session_id)
)

/* Output to ring buffer (in-memory, no file needed) */
ADD TARGET package0.ring_buffer
(
    SET max_memory = 8192  /* 8 MB ring buffer (increased for starting + completed events) */
)

WITH (
    MAX_MEMORY = 8192 KB,
    EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS,
    MAX_DISPATCH_LATENCY = 5 SECONDS,
    STARTUP_STATE = OFF  /* Don''t auto-start on SQL Server restart */
);';

EXEC sp_executesql @sql;
GO

RAISERROR(N'XE session [sp_StatUpdate_Monitor] created with dynamically resolved wait_type map_keys.', 10, 1) WITH NOWAIT;
RAISERROR(N'To start: ALTER EVENT SESSION [sp_StatUpdate_Monitor] ON SERVER STATE = START;', 10, 1) WITH NOWAIT;
GO

/*
===============================================================================
VIEWING XE DATA
===============================================================================

-- 1. Check session status
SELECT
    name,
    CASE WHEN ses.session_id IS NOT NULL THEN 'RUNNING' ELSE 'STOPPED' END AS status
FROM sys.server_event_sessions AS s
LEFT JOIN sys.dm_xe_sessions AS ses ON ses.name = s.name
WHERE s.name = N'sp_StatUpdate_Monitor';

-- 2. View captured events (while session is running)
;WITH ring_buffer AS
(
    SELECT
        CAST(target_data AS xml) AS event_data
    FROM sys.dm_xe_session_targets AS xst
    JOIN sys.dm_xe_sessions AS xs ON xs.address = xst.event_session_address
    WHERE xs.name = N'sp_StatUpdate_Monitor'
    AND   xst.target_name = N'ring_buffer'
)
SELECT
    event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,
    event_data.value('(event/@timestamp)[1]', 'datetime2(3)') AS event_time,
    event_data.value('(event/action[@name="session_id"]/value)[1]', 'int') AS session_id,
    event_data.value('(event/action[@name="database_name"]/value)[1]', 'sysname') AS database_name,
    event_data.value('(event/data[@name="duration"]/value)[1]', 'bigint') / 1000 AS duration_ms,
    event_data.value('(event/data[@name="cpu_time"]/value)[1]', 'bigint') / 1000 AS cpu_ms,
    event_data.value('(event/data[@name="logical_reads"]/value)[1]', 'bigint') AS logical_reads,
    LEFT(event_data.value('(event/action[@name="sql_text"]/value)[1]', 'nvarchar(max)'), 200) AS sql_text_truncated
FROM ring_buffer
CROSS APPLY event_data.nodes('RingBufferTarget/event') AS n(event_data)
ORDER BY event_time DESC;

-- 3. Summary by event type
;WITH ring_buffer AS
(
    SELECT
        CAST(target_data AS xml) AS event_data
    FROM sys.dm_xe_session_targets AS xst
    JOIN sys.dm_xe_sessions AS xs ON xs.address = xst.event_session_address
    WHERE xs.name = N'sp_StatUpdate_Monitor'
    AND   xst.target_name = N'ring_buffer'
)
SELECT
    event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,
    COUNT(*) AS event_count
FROM ring_buffer
CROSS APPLY event_data.nodes('RingBufferTarget/event') AS n(event_data)
GROUP BY event_data.value('(event/@name)[1]', 'varchar(50)')
ORDER BY event_count DESC;

-- 4. View wait statistics captured
;WITH ring_buffer AS
(
    SELECT
        CAST(target_data AS xml) AS event_data
    FROM sys.dm_xe_session_targets AS xst
    JOIN sys.dm_xe_sessions AS xs ON xs.address = xst.event_session_address
    WHERE xs.name = N'sp_StatUpdate_Monitor'
    AND   xst.target_name = N'ring_buffer'
)
SELECT
    event_data.value('(event/data[@name="wait_type"]/text)[1]', 'varchar(50)') AS wait_type,
    COUNT(*) AS wait_count,
    SUM(event_data.value('(event/data[@name="duration"]/value)[1]', 'bigint')) / 1000 AS total_duration_ms,
    AVG(event_data.value('(event/data[@name="duration"]/value)[1]', 'bigint')) / 1000 AS avg_duration_ms
FROM ring_buffer
CROSS APPLY event_data.nodes('RingBufferTarget/event') AS n(event_data)
WHERE event_data.value('(event/@name)[1]', 'varchar(50)') = 'wait_completed'
GROUP BY event_data.value('(event/data[@name="wait_type"]/text)[1]', 'varchar(50)')
ORDER BY total_duration_ms DESC;

-- 5. Correlate starting/completed events (calculate in-progress duration)
;WITH ring_buffer AS
(
    SELECT
        CAST(target_data AS xml) AS event_data
    FROM sys.dm_xe_session_targets AS xst
    JOIN sys.dm_xe_sessions AS xs ON xs.address = xst.event_session_address
    WHERE xs.name = N'sp_StatUpdate_Monitor'
    AND   xst.target_name = N'ring_buffer'
),
events AS (
    SELECT
        event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,
        event_data.value('(event/@timestamp)[1]', 'datetime2(3)') AS event_time,
        event_data.value('(event/action[@name="session_id"]/value)[1]', 'int') AS session_id,
        LEFT(event_data.value('(event/action[@name="sql_text"]/value)[1]', 'nvarchar(max)'), 200) AS sql_text
    FROM ring_buffer
    CROSS APPLY event_data.nodes('RingBufferTarget/event') AS n(event_data)
    WHERE event_data.value('(event/@name)[1]', 'varchar(50)') IN ('sp_statement_starting', 'sp_statement_completed')
)
SELECT
    s.event_time AS start_time,
    c.event_time AS end_time,
    DATEDIFF(MILLISECOND, s.event_time, c.event_time) AS duration_ms,
    s.session_id,
    s.sql_text
FROM events AS s
LEFT JOIN events AS c ON c.session_id = s.session_id
    AND c.event_name = 'sp_statement_completed'
    AND c.event_time >= s.event_time
    AND c.sql_text = s.sql_text
WHERE s.event_name = 'sp_statement_starting'
ORDER BY s.event_time DESC;

-- 6. SPILL PROOF -- sort_warning (PRIMARY) and hash_warning (SECONDARY) events.
--    This is the truthful proof surface for an UPDATE STATISTICS sort spill;
--    Query Store TEMPDB_SPILLS/WAITS only PRESELECT candidates before the run.
;WITH ring_buffer AS
(
    SELECT
        CAST(target_data AS xml) AS event_data
    FROM sys.dm_xe_session_targets AS xst
    JOIN sys.dm_xe_sessions AS xs ON xs.address = xst.event_session_address
    WHERE xs.name = N'sp_StatUpdate_Monitor'
    AND   xst.target_name = N'ring_buffer'
)
SELECT
    event_data.value('(event/@name)[1]', 'varchar(50)') AS spill_event,   -- sort_warning | hash_warning
    CASE event_data.value('(event/@name)[1]', 'varchar(50)')
         WHEN 'sort_warning' THEN 'PRIMARY (proof)' ELSE 'SECONDARY (context)' END AS evidence_class,
    event_data.value('(event/@timestamp)[1]', 'datetime2(3)') AS event_time_utc,
    event_data.value('(event/action[@name="session_id"]/value)[1]', 'int') AS session_id,
    event_data.value('(event/action[@name="database_name"]/value)[1]', 'sysname') AS database_name,
    /* sort_warning_type: single-pass vs multiple-pass (field absent on some builds -> NULL, harmless) */
    event_data.value('(event/data[@name="sort_warning_type"]/text)[1]', 'varchar(30)') AS sort_warning_type,
    event_data.value('(event/action[@name="context_info"]/value)[1]', 'varchar(256)') AS context_info,  -- sp_StatUpdate run tag (gh-423)
    LEFT(event_data.value('(event/action[@name="sql_text"]/value)[1]', 'nvarchar(max)'), 300) AS sql_text
FROM ring_buffer
CROSS APPLY event_data.nodes('RingBufferTarget/event') AS n(event_data)
WHERE event_data.value('(event/@name)[1]', 'varchar(50)') IN ('sort_warning', 'hash_warning')
ORDER BY event_time_utc DESC;

-- 7. Tie each spill event back to the CommandLog UPDATE_STATISTICS row that
--    produced it (truthful attribution).  Run in the maintenance DB where
--    CommandLog lives.  XE @timestamp is UTC while CommandLog StartTime/EndTime
--    use SYSDATETIME() (server-local), so the spill time is shifted UTC->local
--    by the server's current offset before the window join.
;WITH ring_buffer AS
(
    SELECT
        CAST(target_data AS xml) AS event_data
    FROM sys.dm_xe_session_targets AS xst
    JOIN sys.dm_xe_sessions AS xs ON xs.address = xst.event_session_address
    WHERE xs.name = N'sp_StatUpdate_Monitor'
    AND   xst.target_name = N'ring_buffer'
),
spills AS
(
    SELECT
        event_data.value('(event/@name)[1]', 'varchar(50)') AS spill_event,
        /* UTC -> server-local using the live offset (robust to absolute clock skew) */
        DATEADD(MINUTE, DATEDIFF(MINUTE, SYSUTCDATETIME(), SYSDATETIME()),
                event_data.value('(event/@timestamp)[1]', 'datetime2(3)')) AS event_time_local,
        event_data.value('(event/action[@name="session_id"]/value)[1]', 'int') AS session_id,
        event_data.value('(event/action[@name="database_name"]/value)[1]', 'sysname') AS database_name
    FROM ring_buffer
    CROSS APPLY event_data.nodes('RingBufferTarget/event') AS n(event_data)
    WHERE event_data.value('(event/@name)[1]', 'varchar(50)') IN ('sort_warning', 'hash_warning')
)
SELECT
    sp.spill_event,
    sp.event_time_local,
    sp.session_id,
    cl.ID AS commandlog_id,
    cl.DatabaseName,
    cl.SchemaName,
    cl.ObjectName,
    cl.StatisticsName,
    cl.StartTime,
    cl.EndTime,
    LEFT(cl.Command, 300) AS command
FROM spills AS sp
INNER JOIN dbo.CommandLog AS cl
    ON  cl.CommandType = N'UPDATE_STATISTICS'
    AND cl.DatabaseName = sp.database_name COLLATE DATABASE_DEFAULT
    AND sp.event_time_local >= cl.StartTime
    AND sp.event_time_local <= COALESCE(cl.EndTime, SYSDATETIME())
ORDER BY sp.event_time_local DESC;

-- 8. Export to file (optional - creates file in SQL Server default backup dir)
-- ALTER EVENT SESSION [sp_StatUpdate_Monitor] ON SERVER
-- ADD TARGET package0.event_file (SET filename = N'sp_StatUpdate_Monitor.xel', max_file_size = 50);

===============================================================================
*/