December 4, 2012 at 8:54 am
Hi all:
Here is the output from the errorlog on a deadlock that occurred this morning:
12/04/2012 09:15:54,spid18s,Unknown,waiter id=process8d9e28 mode=S requestType=wait
12/04/2012 09:15:54,spid18s,Unknown,waiter-list
12/04/2012 09:15:54,spid18s,Unknown,owner id=process8dfe28 mode=IX
12/04/2012 09:15:54,spid18s,Unknown,owner-list
12/04/2012 09:15:54,spid18s,Unknown,pagelock fileid=1 pageid=514043 dbid=9 objectname=EC_Prod.Master.EmpBen id=lock75382d00 mode=IX associatedObjectId=72057629617422336
12/04/2012 09:15:54,spid18s,Unknown,waiter id=process8dfe28 mode=IX requestType=wait
12/04/2012 09:15:54,spid18s,Unknown,waiter-list
12/04/2012 09:15:54,spid18s,Unknown,owner id=process8d9e28 mode=S
12/04/2012 09:15:54,spid18s,Unknown,owner-list
12/04/2012 09:15:54,spid18s,Unknown,pagelock fileid=1 pageid=593967 dbid=9 objectname=EC_Prod.Master.EmpBen id=lock5e036680 mode=S associatedObjectId=72057629617422336
12/04/2012 09:15:54,spid18s,Unknown,resource-list
12/04/2012 09:15:54,spid18s,Unknown,(@Param000004 datetime<c/>@Param000005 datetime)UPDATE [Master].[EmpBen] SET [ExpDate]=@Param000004<c/>[ProDate]=@Param000005
12/04/2012 09:15:54,spid18s,Unknown,inputbuf
12/04/2012 09:15:54,spid18s,Unknown,unknown
12/04/2012 09:15:54,spid18s,Unknown,frame procname=unknown line=1 sqlhandle=0x000000000000000000000000000000000000000000000000
12/04/2012 09:15:54,spid18s,Unknown,UPDATE [Master].[EmpBen] SET [ExpDate]=@Param000004<c/>[ProDate]=@Param000005
12/04/2012 09:15:54,spid18s,Unknown,frame procname=adhoc line=1 stmtstart=90 sqlhandle=0x02000000eebc540b8a38dfe94b225dd0ee152cf9787c5dff
12/04/2012 09:15:54,spid18s,Unknown,executionStack
12/04/2012 09:15:54,spid18s,Unknown,process id=process8dfe28 taskpriority=0 logused=408 waitresource=PAGE: 9:1:593967 waittime=2421 ownerId=319153183 transactionname=UPDATE CURSOR lasttranstarted=2012-12-04T09:15:52.123 XDES=0x145d1930 lockMode=IX schedulerid=3 kpid=5324 status=suspended spid=110 sbid=0 ecid=0 priority=0 transcount=2 lastbatchstarted=2012-12-04T09:15:52.097 lastbatchcompleted=2012-12-04T09:15:52.097 clientapp=Internet Information Services hostname=WEB02 hostpid=3192 loginname=ACC2SQL_EC isolationlevel=read committed (2) xactid=319153183 currentdb=9 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
12/04/2012 09:15:54,spid18s,Unknown,SELECT EmpBen.DedPer<c/> Count(EmpBen.EmpID) AS CountOfEmpID FROM MASTER.EmpBen WHERE (EmpBen.EffDate<='11/24/2012') AND (EmpBen.ExpDate>='11/18/2012') AND (EmpBen.ExpDate>=EmpBen.EffDate) GROUP BY EmpBen.CltID<c/> EmpBen.DedPer HAVING EmpBen.CltID=301022 ORDER BY Count(EmpBen.EmpID)
12/04/2012 09:15:54,spid18s,Unknown,inputbuf
12/04/2012 09:15:54,spid18s,Unknown,unknown
12/04/2012 09:15:54,spid18s,Unknown,frame procname=unknown line=1 sqlhandle=0x000000000000000000000000000000000000000000000000
12/04/2012 09:15:54,spid18s,Unknown,SELECT EmpBen.DedPer<c/> Count(EmpBen.EmpID) AS CountOfEmpID FROM MASTER.EmpBen WHERE (EmpBen.EffDate<='11/24/2012') AND (EmpBen.ExpDate>='11/18/2012') AND (EmpBen.ExpDate>=EmpBen.EffDate) GROUP BY EmpBen.CltID<c/> EmpBen.DedPer HAVING EmpBen.CltID=301022 ORDER BY Count(EmpBen.EmpID)
12/04/2012 09:15:54,spid18s,Unknown,frame procname=adhoc line=1 sqlhandle=0x02000000f8cc3c08b64e3012fdf73a86f61e80dd5756f437
12/04/2012 09:15:54,spid18s,Unknown,executionStack
12/04/2012 09:15:54,spid18s,Unknown,process id=process8d9e28 taskpriority=0 logused=0 waitresource=PAGE: 9:1:514043 waittime=2406 ownerId=319152578 transactionname=DECLARE CURSOR lasttranstarted=2012-12-04T09:15:51.637 XDES=0x3e243e08 lockMode=S schedulerid=2 kpid=6384 status=suspended spid=109 sbid=0 ecid=0 priority=0 transcount=0 lastbatchstarted=2012-12-04T09:15:51.630 lastbatchcompleted=2012-12-04T09:15:51.630 lastattention=2012-12-04T09:12:56.457 clientapp=Internet Information Services hostname=WEB02 hostpid=3192 loginname=ACC2SQL_EC isolationlevel=read committed (2) xactid=319152578 currentdb=9 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
12/04/2012 09:15:54,spid18s,Unknown,process-list
12/04/2012 09:15:54,spid18s,Unknown,deadlock victim=process8d9e28
12/04/2012 09:15:54,spid18s,Unknown,deadlock-list
As best as I can tell, it appears the deadlock occurred between two processes within the same SPID, one of them executing a SELECT while the other was executing an UPDATE. Below is an error message from the application (this is a web app, if that matters) from the process that was killed:
ERROR TYPE:
Microsoft SQL Native Client
<b>Transaction (Process ID 109) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.</b> <b>/ASP/Payroll/FormPayCert.asp, line 369, column 0</b>
And here is the code around line 369 of that web page:
Set oRS = Server.CreateObject("ADODB.RecordSet")
SQL = "SELECT EmpBen.DedPer, Count(EmpBen.EmpID) AS CountOfEmpID" _
& " FROM MASTER.EmpBen" _
& " WHERE (EmpBen.EffDate<='" & CovEndDt & "')" _
& " AND (EmpBen.ExpDate>='" & CovBegDt & "')" _
& " AND (EmpBen.ExpDate>=EmpBen.EffDate)" _
& " GROUP BY EmpBen.CltID, EmpBen.DedPer" _
& " HAVING EmpBen.CltID=" & strSesCltID _
& " ORDER BY Count(EmpBen.EmpID)"
oRS.Open SQL, oConnSQL, adOpenStatic, adLockReadOnly, adCmdText
If oRS.RecordCount > 1 then
WarningTxt=WarningTxt & "
<font style=""font-size: 11; color: red"">ERROR: Multiple Pay frequencies in employee benefits."
If SesModeTPA then
Call A910_ListEmpIDs(oRS)
End if
A900_MultiPayPeriods=True
End If
oRS.Close
There are no UPDATEs within the asp that this code is in, but I've located a couple of other files where an update is occurring to the table indicated. There is alot of code in one of these files and a number of places where the UPDATE is coded. Recordsets are opened and closed, etc. in a number of places and it will take time to make sure all of them are being closed. My guess is, because the deadlock is coming from the same SPID, that a recordset is being opened somewhere and left open, but that would seem to have to occur in the code above (which clearly the recordset is closed). Further, the adLockReadOnly in the code above should indicate that no lock is being attempted in the process that was killed.
I've given my thoughts. I'd appreciate any other thoughts on this.
December 6, 2012 at 12:45 pm
Still looking at this...
Since the app is a web app, I guess nothing can be determined from the two processes coming from the same SPID due to connection pooling. I have verified that all the recordsets in the code are opened and closed appropriately.
The SELECT statement that was chosen as the victim does not appear to be a long running query (it runs instantaneously from SSMS), so I'm at a loss as to why a deadlock even occurred. AFAIK, a SELECT will only have a Shared lock on the page and will release the lock as soon as the statement has executed. So, why would the deadlock occur?
December 7, 2012 at 9:50 am
FYI, I found this which describes how a deadlock can occur with a SELECT.
I'm now struggling with why the output from the errorlog seems to include only part of the SQL statement doing the update. There is not an update statement in the application code that doesn't include a WHERE clause. If it did, it would create massive data problems, so I'm fairly certain part of the statement has been left off. It would be nice to know so I could zero in on which update was the culpret. Having this, then perhaps I could come up with a strategy for preventing this particular deadlock going forward.
Would be nice to get some comments from others on this. 🙂
Viewing 3 posts - 1 through 2 (of 2 total)
You must be logged in to reply to this topic. Login to reply