I’ve been chasing down a series of issues with a system. One of the symptoms we’ve been getting is massive lock timeouts, so I’ve been taking (server side) profiler traces to see what code is requesting the locks that are being timed out. Today I landed on a lovely solution for correlating the lock timeouts I see in the trace file with the associated code. Let’s talk setup, and then we’ll walk through the thinking that led to our solution.
Setup
Take a server side trace, be sure to get “existing connections”, RPC:Starting, RPC:Completed, and Lock Timeout (Timeout > 0) (see the previous blog “Lock Timeout Revelation on Twitter”). For the RPCs and Timeouts, get your basic measures, plus ObjectName and DatabaseID.
Once you’ve captured enough of a trace, save it to a table, preferably on your local box.
Depending on how much time you’re going to spend digging through this data, you may want to index your trace table. Here are the indexes I developed for this query:
CREATE INDEX ix_trace ON trace (eventclass, spid, rownumber, databaseID, objectName) INCLUDE (starttime, endTime) CREATE INDEX ix_trace2 ON trace (spid, eventclass, rownumber, databaseID, objectName)
Developing
Once you save the trace into a table, you'll need to know the event id (event class names aren't displayed). (*See footnote about trace in tables…)
Trace event 189 is Lock Timeout (timeout > 0). So when you find a 189, it’s easy to go back up the trace rows until you find the closest one with a corresponding SPID, which will have an eventclass of 11: RPC:Started. Rough pseudocode:
1. Find a timeout eventclass = 189
2. Find the closest row with rownumber < timeout.rownumber and spid = timeout.spid
Part 1 is easy:
SELECT TOP 10 [Timeout].RowNumber , [Timeout].EventClass , [Timeout].DatabaseID , [Timeout].spid , [Timeout].starttime , [Timeout].endtime , FROM Trace AS [Timeout] WHERE [Timeout].EventClass = 189Note that I’m limiting the query to the TOP 10 for now, just so I don’t have to look through 10,000 rows at once.
So Part 2: for each timeout, find the closest previous RPC Started with the same spid. On first look, I started falling into the cursor trap. You say it to yourself procedurally: “for each timeout” is actually direct pseudocode for a cursor. But don’t go there….just don’t…
What do we know about the timeout and its associated code call?
-
They have the same spid
-
They’re on the same database
-
The statement will have an RPC start (eventclass = 11), but not necessarily an RPC complete (eventclass = 10)
-
The statement will precede the timeout, and therefore have an earlier row number
So we could say that for a timeout, the corresponding statement is
-
the MAX rownum less than the timeout rownum
-
where the spids and databases match,
-
and eventclass=11.
Well partner, that’s a correlated subquery right there! Pretend for a moment that we only have one lock timeout, SPID = 52, rownumber = 11,304. So to find the code that goes with it:
SELECT TOP 1 rownumber FROM trace WHERE spid = 52 –Timeout spid AND rownumber < 11304 -–Timeout rownumber AND eventclass = 11 ORDER BY rownumber DESCThat’s our subquery. Let’s plug it into the part 1 query, and correlate the thing!
SELECT TOP 10 [Timeout].RowNumber , [Timeout].EventClass , [Timeout].DatabaseID , [Timeout].spid , [Timeout].starttime , [Timeout].endtime , Statement.* FROM Trace AS [Timeout] INNER JOIN Trace AS [Statement] ON Statement.spid = [Timeout].spid AND Statement.spid = [Timeout].spid AND Statement.DatabaseID = [Timeout].DatabaseID AND statement.rownumber = ( SELECT TOP 1 rownumber FROM trace WHERE spid = [Timeout].spid AND rownumber < [Timeout].rownumber AND eventclass = 11 ORDER BY rownumber DESC ) WHERE [Timeout].EventClass = 189And finally, let’s do better with our select than just Statement.*:
SELECT TOP 10 [Timeout].RowNumber , [Timeout].EventClass , [Timeout].DatabaseID , [Timeout].spid , [Timeout].starttime , [Timeout].endtime , 'STATEMENT: ' AS spacer, Statement.rownumber , Statement.objectname , Statement.textdata, Statement.loginname , Statement.spid , Statement.starttime , Statement.endtime FROM Trace AS [Timeout] INNER JOIN Trace AS [Statement] ON Statement.spid = [Timeout].spid AND Statement.spid = [Timeout].spid AND Statement.DatabaseID = [Timeout].DatabaseID AND statement.rownumber = ( SELECT TOP 1 rownumber FROM trace WHERE spid = [Timeout].spid AND rownumber < [Timeout].rownumber AND eventclass = 11 ORDER BY rownumber DESC ) WHERE [Timeout].EventClass = 189
I like the “STATEMENT” spacer; it’s a nice break between your timeout columns, and your statement columns.
I found another great application for this, but we’ve gone a bit long here. So, come back tomorrow for Correlating Data in SQL Trace, Part 2!
-Jen McCown
*Footnote: Again, I'll have to come back later with a link, but I also learned today that when you port your trace results into a table, duration is stored in microseconds (1/1,000,000 s), instead of milliseconds (1/1,000). This seems like it would be pretty good info to have. Edit: Linky! Here's the Brian Moran article "Duration and CPU Values" that mentions this.
