Troubleshooting Deadlocks

• 
  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

  Chris Spencer January 07, 2011 07:52

  - 0 +
• 
  Chris,
  
  Just to confirm - does SQL Server itself only send through the partial query fragment or is this a SQL Monitor issue?
  
  Thx

  cjlotz January 07, 2011 09:35

  - 0 +
• 
  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

  Chris Spencer January 07, 2011 10:48

  - 0 +
• 
  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.

  cjlotz January 11, 2011 08:21

  - 0 +
• 
  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

  Chris Spencer January 11, 2011 09:00

  - 0 +
• 
  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.

  cjlotz January 11, 2011 09:23

  - 0 +

Add comment

Please sign in to leave a comment.