Investigating Errors With Extended Events

Tom
4 minutes

Scenario 🔗︎

There is an error happening somewhere in SQL Server. Maybe you are aware of it, maybe not. At any rate, it’s proving hard to pinpoint. In this post, I’ll provide you with the tools to track and debug them.

The problem 🔗︎

Like in a real-world scenario, I’ll start with the problem first.

I will create a procedure SharedLogic that either passes or fails based on the parameter.
Then I will simulate nesting by creating two more procedures Caller1 and Caller2 that are wrappers around this procedure.

CREATE OR ALTER PROCEDURE dbo.SharedLogic (@trueFalse bit)
AS
IF (@trueFalse = 1) /* golden path - no error */
    SELECT 1 as Pass
ELSE
    SELECT 1/0 as Error /* Generate a divide by 0 error */
GO

CREATE OR ALTER PROCEDURE dbo.Caller1(@passThrough bit) /* Simulate nesting 1 */
AS
EXEC dbo.SharedLogic @trueFalse = @passThrough
GO

CREATE OR ALTER PROCEDURE dbo.Caller2 (@passThrough bit) /* Simulate nesting  2*/
AS
EXEC dbo.SharedLogic @trueFalse = @passThrough
GO

Once the procedures are created, we can test the errors by calling all combination of parameters.

GO
EXEC dbo.SharedLogic @trueFalse = 0 /* Error */
GO
EXEC dbo.SharedLogic @trueFalse = 1
GO
EXEC dbo.Caller1 @passThrough = 0 /* Error */
GO
EXEC dbo.Caller1 @passThrough = 1
GO
EXEC dbo.Caller2 @passThrough = 0 /* Error */
GO
EXEC dbo.Caller2 @passThrough = 1
GO

Note: I’m using the batch separator GO to capture a single statement at a time.

Capturing the errors 🔗︎

To capture the errors, we shall use the Extended Events session. That is a basic example that will work for us.

CREATE EVENT SESSION [Error_reported] ON SERVER
ADD EVENT sqlserver.error_reported
(
    ACTION
    (
          sqlserver.server_instance_name   /* good practice for multi server querying */
        , sqlserver.client_app_name        /* helps locate the calling app */
        , sqlserver.client_hostname        /* calling computer name */
        , sqlserver.server_principal_name  /* can be switched to a user */
        , sqlserver.database_id            /* can be switched to a database_name */
        , sqlserver.sql_text               /* grab calling parameters from input buffer */
        , sqlserver.tsql_stack             /* get the whole stack for parsing later */
    )
    WHERE
    (
        severity > 10
        /* Please test and provide additional filters! */
    )
)
ADD TARGET
    package0.event_file
    (
        SET
            filename=N'Error_reported'
            , max_file_size= 20 /* MB */
    )

 

⚠️ For your system, be sure to test first and filter out benign errors and false positives.

Analysing the errors 🔗︎

Let’s start the extended event session. We can use the TSQL code
ALTER EVENT SESSION Error_reported ON SERVER STATE = Start /* Stop */
Or through the GUI in Object Explorer.

Path to Extended events in SSMS GUI

Don’t forget that Extended events sessions are instance-level objects - that means you are monitoring all Databases. If you only want to monitor a specific database, add it to the filters. In our local environment, we can right-click the session and select Watch Live data. For production, you should analyse the saved file on disk.

Let’s rerun the EXEC statements to generate the errors once more. We can see that three events popped up. Let’s use the Extended events menu option Choose columns… to pick the columns of interest. I have only chosen a few so they can fit on a screenshot.

Extended events with errors reported

  • The XE actions columns (instance, database, app_name, host_name and login) help with locating the calling process.
  • SQL text provides us with an example of how to repro the problem along with the parameter values.
  • And TSQL stack is my favourite. We can query the cache and parse the path through the code using the following snippet.
DECLARE @stackOrFrame xml = '' /* <-- Paste the <frames></frames> here */

;WITH
xmlShred AS
(
    SELECT
        COALESCE
        (
            CONVERT(varbinary(64), f.n.value('.[1]/@handle', 'varchar(max)'), 1),
            CONVERT(varbinary(64), f.n.value('.[1]/@sqlhandle', 'varchar(max)'), 1)
        ) AS handle,
        COALESCE
        (
            f.n.value('.[1]/@offsetStart', 'int'),
            f.n.value('.[1]/@stmtstart', 'int')
        ) AS offsetStart,
        COALESCE
        (
            f.n.value('.[1]/@offsetEnd', 'int'),
            f.n.value('.[1]/@stmtend', 'int')
        ) AS offsetEnd,
        f.n.value('.[1]/@line', 'int') AS line,
        f.n.value('.[1]/@level', 'tinyint') AS stackLevel
    FROM @stackOrFrame.nodes('//frame') AS f(n)
)
SELECT
    xs.stackLevel,
    ca.outerText,
    ca2.statementText
FROM
    xmlShred AS xs
    CROSS APPLY sys.dm_exec_sql_text(xs.handle) AS dest
    CROSS APPLY (SELECT LTRIM(RTRIM(dest.text))  FOR XML PATH(''), TYPE) AS ca(outerText)
    CROSS APPLY
    (
        SELECT
            SUBSTRING
            (
                dest.text,
                (xs.offsetStart / 2) + 1,
                ((
                    CASE
                        WHEN xs.offsetEnd = -1
                            THEN DATALENGTH(dest.text)
                        ELSE xs.offsetEnd
                    END
                    - xs.offsetStart
                ) / 2) + 1
            )
        FOR XML PATH(''), TYPE
    ) AS ca2(statementText)
ORDER BY xs.stackLevel
OPTION (RECOMPILE);

 

Just paste the stack XML into the variable, and we should get the following output.

TSQL Calling stack parsed

I have CAST the text to XML so it’s formatted nicely, but if your code contains XML specific special characters, it might break. I’m also providing this script as a gist so anyone can contribute - Parse TSQL Stack

Conclusion 🔗︎

With these tools and scripts, it’s trivial to monitor and debug errors in SQL Server. I hope you’ll find this information useful!