Advanced Server-Side SQL Server Query Troubleshooting

The XEvent Profiler in SSMS is a powerful troubleshooting tool, but what happens when it's not enough?

Today I was debugging a Go script that I hadn't written.  It was executing several T-SQL statements directly against a SQL Server database using the Go mssql-db driver.  I was banging away against a development copy of the database.  A colleague had used the same script earlier against his development copy and it worked without a problem.

There were many potential points of failure, and I had no clear view into what was going on behind the scenes.

Starting with the Obvious: XEvent Profiler

The obvious place to start was to fire up the XEvent Profiler in SSMS.

By doing that, I was able to identify the statement that was causing problems.  The entry above was the one causing the problem.  Notice how the result of the operation is "Error."  Not a particularly helpful message, but that's no big deal–or, at least, it's usually not a big deal.

The batch_text property had the T-SQL that the Go script was trying to execute.  So, I copied and pasted the T-SQL into a new Query window in SSMS and executed it.  I fully expected to see a more useful error message, but alas, it actually worked.  

Here's the relevant entry from XEvent Profiler:

It looks very similar to the previous one, with a few key differences:

• client_app_name is SSMS instead of go-mssqldb
• result is OK instead of Error
• row_count is 65,082 instead of 0

Now the fact that XEvent Profiler's result field has a generic value of "Error" is suddenly a big problem.

Custom XEvent Session: FailedQueries

Out of ideas, I threw myself at the mercy of the Google gods.

They delivered in the form of an article by Microsoft Data Platform MVP, Andrew Pruski, Identifying failed queries with extended events.  Andrew's article is not long, but I'll reproduce the bits that solved my particular problem here.

I ran the following T-SQL to create the custom FailedQueries extended event session:

-- Original author: Andrew Pruski
-- source: https://dbafromthecold.com/2017/06/07/identifying-failed-queries-with-extended-events/
CREATE EVENT SESSION [FailedQueries] ON SERVER
ADD EVENT sqlserver.error_reported
    (ACTION(sqlserver.client_app_name, sqlserver.client_hostname,  
        sqlserver.database_name, sqlserver.sql_text, sqlserver.username)
    WHERE ([package0].[greater_than_int64]([severity], (10))))
 
ADD TARGET package0.event_file (SET
    filename = N'D:\SQL\XEvents\FailedQueries.xel'       -- customize these
    ,metadatafile = N'D:\SQL\XEvents\FailedQueries.xem'  --   two lines
    ,max_file_size = (5)
    ,max_rollover_files = (10))
 
WITH (STARTUP_STATE = ON)
GO

If you look carefully, you will notice that I used different file paths than Andrew.  You'll need to adjust those lines for your environment, too.

After running the above T-SQL statement, I went to Management > Extended Events > Sessions (right-click and choose Refresh) > FailedQueries (right-click and choose "Start Session") > FailedQueries (right-click and choose "Watch Live Data"):

I then re-ran my Go script and watched the FailedQueries session.  This time I got a slightly more helpful error message,

Network error code 0x2746 occurred while establishing a connection; the connection has been closed.

While this was an improvement over the generic "Error" message in the Standard XEvent Profiler session, it was still a fairly generic error itself–with many potential root causes.

Parsing the Custom XEvent's XML Data

The real gem from Andrew's article was near the end where he described how to use XQuery to parse the extended event's XML data.

-- Original author: Andrew Pruski
-- source: https://dbafromthecold.com/2017/06/07/identifying-failed-queries-with-extended-events/
SELECT
    [XML Data],
    [XML Data].value('(/event[@name=''error_reported'']/@timestamp)[1]','DATETIME')             AS [Timestamp],
    [XML Data].value('(/event/action[@name=''database_name'']/value)[1]','varchar(max)')        AS [Database],
    [XML Data].value('(/event/data[@name=''message'']/value)[1]','varchar(max)')                AS [Message],
    [XML Data].value('(/event/action[@name=''sql_text'']/value)[1]','varchar(max)')             AS [Statement]
FROM
    (SELECT
        OBJECT_NAME              AS [Event],
        CONVERT(XML, event_data) AS [XML Data]
    FROM
        sys.fn_xe_file_target_read_file
    ('D:\SQL\XEvents\FailedQueries*.xel',NULL,NULL,NULL)) as FailedQueries;
GO

Once again, I had to modify the file path in the final line of the T-SQL query to match my earlier T-SQL statement.

To my utter surprise, this query provided the full details of the root cause of the error I was getting in my Go script.

Snapshot isolation transaction failed accessing database 'WayneCounty' because snapshot isolation is not allowed in this database. Use ALTER DATABASE to allow snapshot isolation.

Now, enabling snapshot isolation is apparently not something to take lightly on a production database server.  Luckily for me, I was working with a development copy, so I had no such worries.  Besides, the point of this article was not to tell you what was wrong with my specific situation.  Rather, I wanted to take you along for the ride in how I managed to identify the root cause of my problem.

Andrew Pruski's custom XEvent session and accompanying XQuery SELECT statement saved my bacon today.  Here's to hoping it will save yours someday, too.

External references

DBA from the Cold - Andrew Pruski
Identifying failed queries with extended events

Use the SSMS XEvent Profiler - SQL Server

The XEvent Profiler displays a live viewer of extended events. Learn why to use this profiler, key features, and how to get started viewing extended events.

Microsoft Docsyualan

Image by David Mark from Pixabay