Troubleshooting Deadlocks

cjlotz

Hi

I'm having trouble trying to pinpoint a deadlock issue raised by SQL Monitor. SQL Monitor only displays fragments of the queries that are deadlocked and I'm unable to locate the specific queries in the SQL Processes/Profiler trace views.

Here are the steps I'm following:

Click on the Victim process for the Deadlock alert. This shows only a fragment of the query that was terminated (first 5 lines). I then click on the SQL Processes/Profiler trace window to look at all the queries executed for the specific victim process. I tried to find the specific query by first selecting the complete trace and pasting it in Notepad to do search for the text (

Please add improved searching functionality to search the traces)
However, I find no occurence of the SQL fragment. My expectation would be that the trace should include the fragment but it does not.


Another issue with using the SQL fragment to locate the query is that the fragment doesn't include all the context (i.e. the values being inserted). This is problematic in searching the trace when we have 100 of the same queries executing with different values. Because the fragment doesn't include the values we can't determine the exact query that failed.

Thx

Chris Spencer

Hi

I'm having issues recreating this issue internally. I have created several deadlock alerts but each time the sql query fragment can also be found in the trace listing.

I did notice that when copy/pasting the trace into notepad that the search for the fragment didn't work for me due to it being pasted in with no space between the fragment and the date (as follows):

7 Jan 2011 11:06:22UPDATE ##17826ade WITH (PAGLOCK) SET col1 = 1

The trace presented should be 40 seconds of trace for that process, 20 seconds prior and 20 seconds after the deadlock occurrence. We get the fragment from SQL Server and are limited by what we can do here but in theory the fragment should appear in the trace.

What are the date/times displayed in the trace listing and do they cover the point in time that the deadlock occurred?

In the meantime, I have raised a couple of enhancement requests
SRP-3032 - Make it easier to locate the SQL query fragment in the trace listing
SRP-3033 - Investigate improving the query fragment to include more context.

Thanks
Chris

cjlotz

Chris,

Just to confirm - does SQL Server itself only send through the partial query fragment or is this a SQL Monitor issue?

Thx

Chris Spencer

I'm not exactly sure how SQL Monitor gets the sql query fragment for deadlock alerts but checking my system, I notice that the exact same fragment appears in the SQL Server Error logs so I'd guess we read it directly from there.

We do have other reported issues along these lines:
http://www.red-gate.com/MessageBoard/vi ... hp?t=12473

We will be investigating and hopefully improving the trace collection for version 2.2.

Regards
Chris

cjlotz

After some more digging I came to the same deadlock that was logged using the previous version of SQL Monitor. In the old version the log gave us the correct information to point out the error.

Old Version Log:

SQL query fragment:
Language Event: INSERT INTO astTasks(Id,Version,LastModifiedOn,LastModifiedByUserId,Code,Description,AlternativeDescription,SiteId,IsActive,Sequ

New Version Log:

SQL query fragment:
Language Event: (@Id int,@Version int,@LastModifiedOn datetime,@LastModifiedByUserId int,@Code nvarchar(50),@Description nvarchar(255),@AlternativeDescription nvarchar(255),@SiteId int,@IsActive bit,@SequenceNumber smallint,@DevelopmentStatus int,@LastConfirmedOn datetim

You'll notice that in the new version it starts off with the parameters, thus not giving us the table that it occurs on.
With regard to the fragment. I've switched on tracing on SQL Server 2008, by issuing the following command: DBCC TRACEON (1222, -1)
In SQL Monitor I get this fragment:

SQL query fragment:
Language Event: SELECT T.Id, RUA.Id AS RollupAssetId, RUA.Code, RUA.Description
FROM astAssetTree AT 
INNER JOIN astTasks T ON T.AssetId = AT.AssetId
INNER JOIN astAssets A ON A.Id = T.AssetId 
INNER JOIN

If I look in the SQL Server Error Log I get the following:

2011-01-11 12:10:22.27 spid4s      Node:2

2011-01-11 12:10:22.27 spid4s      PAGE: 8:1:367896               CleanCnt:2 Mode:S Flags: 0x3
2011-01-11 12:10:22.27 spid4s       Grant List 1:
2011-01-11 12:10:22.27 spid4s         Owner:0x00000000B1ACB700 Mode: S        Flg:0x40 Ref:0 Life:00000001 SPID:63 ECID:0 XactLockInfo: 0x000000019D09F5F0
2011-01-11 12:10:22.27 spid4s         SPID: 63 ECID: 0 Statement Type: SELECT Line #: 1
2011-01-11 12:10:22.27 spid4s         Input Buf: Language Event: SELECT T.Id, RUA.Id AS RollupAssetId, RUA.Code, RUA.Description
                    FROM astAssetTree AT 
		            INNER JOIN astTasks T ON T.AssetId = AT.AssetId
		            INNER JOIN astAssets A ON A.Id = T.AssetId  
		            INNER JOIN
2011-01-11 12:10:22.27 spid4s      Requested by: 
2011-01-11 12:10:22.27 spid4s        ResType:LockOwner Stype:'OR'Xdes:0x0000000127C4E8F0 Mode: IX SPID:55 BatchID:2 ECID:0 TaskProxy:(0x00000001AA68C538) Value:0xdd1a3fc0 Cost:(0/70416)
2011-01-11 12:10:22.27 spid4s      
2011-01-11 12:10:22.27 spid4s      Victim Resource Owner:
2011-01-11 12:10:22.27 spid4s       ResType:LockOwner Stype:'OR'Xdes:0x000000019D09F5B0 Mode: S SPID:63 BatchID:2 ECID:0 TaskProxy:(0x00000001561A0538) Value:0xb3138dc0 Cost:(0/0)
2011-01-11 12:10:22.27 spid21s     deadlock-list
2011-01-11 12:10:22.27 spid21s      deadlock victim=process3e89708
2011-01-11 12:10:22.27 spid21s       process-list
2011-01-11 12:10:22.27 spid21s        process id=process3e89708 taskpriority=0 logused=0 waitresource=PAGE: 8:1:314426 waittime=3859 ownerId=2081590891 transactionname=SELECT lasttranstarted=2011-01-11T12:10:16.950 XDES=0x19d09f5b0 lockMode=S schedulerid=2 kpid=3820 status=suspended spid=63 sbid=2 ecid=0 priority=0 trancount=0 lastbatchstarted=2011-01-11T12:10:16.950 lastbatchcompleted=2011-01-11T12:10:16.950 clientapp=.Net SqlClient Data Provider hostname=PRODS-HARM hostpid=4604 loginname=OnKey5 isolationlevel=read committed (2) xactid=2081590891 currentdb=8 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
2011-01-11 12:10:22.27 spid21s         executionStack
2011-01-11 12:10:22.27 spid21s          frame procname=adhoc line=1 sqlhandle=0x0200000020ac2b241e4e25d6f5dfaabe4012c10170109e6f
2011-01-11 12:10:22.27 spid21s     SELECT T.Id, RUA.Id AS RollupAssetId, RUA.Code, RUA.Description
2011-01-11 12:10:22.27 spid21s                         FROM astAssetTree AT 
2011-01-11 12:10:22.27 spid21s     		            INNER JOIN astTasks T ON T.AssetId = AT.AssetId
2011-01-11 12:10:22.27 spid21s     		            INNER JOIN astAssets A ON A.Id = T.AssetId  
2011-01-11 12:10:22.27 spid21s     		            INNER JOIN stdSites SITE ON SITE.Id = A.SiteId  
2011-01-11 12:10:22.27 spid21s     		            INNER JOIN astTaskScenarios S ON (S.ParentId = T.Id AND S.ScenarioId = A.ScenarioId) 
2011-01-11 12:10:22.27 spid21s     		            LEFT OUTER JOIN vw_schIntervals I ON I.Id = S.IntervalId 
2011-01-11 12:10:22.27 spid21s     		            LEFT OUTER JOIN astComponents C ON C.Id = T.ComponentId  
2011-01-11 12:10:22.27 spid21s     		            LEFT OUTER JOIN astMeters M ON M.Id = T.MeterId  
2011-01-11 12:10:22.27 spid21s     		            LEFT OUTER JOIN astEvents E ON E.Id = T.EventId  
2011-01-11 12:10:22.27 spid21s     		            JOIN astAssetTree RUAT ON (T.AssetId = RUAT.AssetId)
2011-01-11 12:10:22.27 spid21s     		            JOIN astAssets RUA ON ((RUAT.ParentId = RUA.Id) AND (T.RollUpPointId = RUA.RollUpPointId))
2011-01-11 12:10:22.27 spid21s                         JOIN astTaskIntervalTypes TIT ON T.IntervalTypeId = TIT.Id
2011-01-11 12:10:22.27 spid21s                          JOIN usrUserRights UR ON ((A.SiteId = UR.SiteId) AND (UR.UserId = 1012) AND (     
2011-01-11 12:10:22.27 spid21s         inputbuf
2011-01-11 12:10:22.27 spid21s     SELECT T.Id, RUA.Id AS RollupAssetId, RUA.Code, RUA.Description
2011-01-11 12:10:22.27 spid21s                         FROM astAssetTree AT 
2011-01-11 12:10:22.27 spid21s     		            INNER JOIN astTasks T ON T.AssetId = AT.AssetId
2011-01-11 12:10:22.27 spid21s     		            INNER JOIN astAssets A ON A.Id = T.AssetId  
2011-01-11 12:10:22.27 spid21s     		            INNER JOIN stdSites SITE ON SITE.Id = A.SiteId  
2011-01-11 12:10:22.27 spid21s     		            INNER JOIN astTaskScenarios S ON (S.ParentId = T.Id AND S.ScenarioId = A.ScenarioId) 
2011-01-11 12:10:22.27 spid21s     		            LEFT OUTER JOIN vw_schIntervals I ON I.Id = S.IntervalId 
2011-01-11 12:10:22.27 spid21s     		            LEFT OUTER JOIN astComponents C ON C.Id = T.ComponentId  
2011-01-11 12:10:22.27 spid21s     		            LEFT OUTER JOIN astMeters M ON M.Id = T.MeterId  
2011-01-11 12:10:22.27 spid21s     		            LEFT OUTER JOIN astEvents E ON E.Id = T.EventId  
2011-01-11 12:10:22.27 spid21s     		            JOIN astAssetTree RUAT ON (T.AssetId = RUAT.AssetId)
2011-01-11 12:10:22.27 spid21s     		            JOIN astAssets RUA ON ((RUAT.ParentId = RUA.Id) AND (T.RollUpPointId = RUA.RollUpPointId))
2011-01-11 12:10:22.27 spid21s                         JOIN astTaskIntervalTypes TIT ON T.IntervalTypeId = TIT.Id
2011-01-11 12:10:22.27 spid21s                          JOIN usrUserRights UR ON ((A.SiteId = UR.SiteId) AND (UR.UserId = 1012) AND     
2011-01-11 12:10:22.27 spid21s        process id=process3e88e08 taskpriority=0 logused=70416 waitresource=PAGE: 8:1:367896 waittime=4763 ownerId=2081593817 transactionname=user_transaction lasttranstarted=2011-01-11T12:10:17.043 XDES=0x127c4e8f0 lockMode=IX schedulerid=2 kpid=1680 status=suspended spid=55 sbid=2 ecid=0 priority=0 trancount=2 lastbatchstarted=2011-01-11T12:10:17.507 lastbatchcompleted=2011-01-11T12:10:17.507 clientapp=.Net SqlClient Data Provider hostname=PRODS-HARM hostpid=4604 loginname=OnKey5 isolationlevel=repeatable read (3) xactid=2081593817 currentdb=1 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
2011-01-11 12:10:22.27 spid21s         executionStack

You'll notice that it gives me the fragment that SQL Monitor prints out, but further down it gives me a bigger fragment of the query.

In Summary:
1. The old version of SQL Monitor gave us better information about the query that was involved in the deadlock. For inserts it gave us the first part of the query, where the table name is. In the new version it starts off with the Parameters.
2. Even though SQL Server prints out more information in the error log, this information is not available in SQL Monitor. It would be great to have it there too.
3. I've also confirmed that going to "SQL processes/Profiler trace" and looking for the SPID in question, I could not find the queries in the fragment anywhere in the list of statements for that SPID.

Chris Spencer

Thanks for this. I'm currently investigating trace issues with SQL Monitor and performing direct comparisions with SQL Response so will look at the issues raised here.

Regarding your summary points:
1. We are definitely looking to ensure that SQL Monitor presents as least as much information as our previous product (SQL Response)
2. I'll investigate this and potentially raise an enhancement request.
3. I'm worried about this as I can't reproduce it internally. The list of trace statements in SQL Monitor should have datetime values. Do these values coincide with the time of the deadlock occurrence in the SQL Server error log? I'm worried that we might be reading the wrong chunk of the trace file for some reason.

Thanks
Chris

cjlotz

We can't see the detailed time values in the SQL Monitor log entries, but the alert is raised at the same time (up to minutes) than the entries in the SQL trace files. All other details in the SQL trace matches the SQL Monitor log entry, but as illustrated, SQL Monitor shows considerably less content than the SQL Server trace logs.