September 18, 2008 at 9:48 am
In my ERRORLOG I can see that a deadlock was found, the entry is:
2008-09-18 08:15:41.65 spid4s Starting deadlock search 30926
2008-09-18 08:15:41.65 spid4s Target Resource Owner:
2008-09-18 08:15:41.65 spid4s ResType:LockOwner Stype:'OR'Xdes:0x047ECFD0 Mode: U SPID:55 BatchID:0 ECID:0 TaskProxy:(0x6140C378) Value:0x3098e880
2008-09-18 08:15:41.65 spid4s 0:Insert new node: Node:1 ResType:LockOwner Stype:'OR'Xdes:0x047ECFD0 Mode: U SPID:55 BatchID:0 ECID:0 TaskProxy:(0x6140C378) Value:0x3098e880
2008-09-18 08:15:41.65 spid4s 1:SearchOR Considering new blocker - task: 00BD46B8, Worker 05E9C0E8
2008-09-18 08:15:41.65 spid4s 2:Insert new node: Node:2 ResType:LockOwner Stype:'OR'Xdes:0x03D7F848 Mode: U SPID:58 BatchID:0 ECID:0 TaskProxy:(0x45BB6378) Value:0x537bc960
2008-09-18 08:15:41.65 spid4s 3:SearchOR Considering new blocker - task: 0092FB58, Worker 5424E0E8
2008-09-18 08:15:41.65 spid4s 4:InsertKnown Cycle found between old res owner: [ ResType:LockOwner Stype:'OR'Xdes:0x047ECFD0 Mode: U SPID:55 BatchID:0 ECID:0 TaskProxy:(0x6140C378) Value:0x3098e880] and new res owner [ ResType:LockOwner Stype:'OR'Xdes:0x047ECFD0 Mode: U SPID:55 BatchID:0 ECID:0 TaskProxy:(0x6140C378) Value:0x3098e880]
2008-09-18 08:15:41.65 spid4s 4:InsertKnown search result: Deadlock found (blocking owner is on a stack)
2008-09-18 08:15:41.65 spid4s 3:SearchOR search result: Deadlock found (cycle on this level or before)
2008-09-18 08:15:41.65 spid4s 1:SearchOR search result: Deadlock found (cycle on this level or before)
2008-09-18 08:15:41.65 spid4s
2008-09-18 08:15:41.65 spid4s Deadlock cycle was encountered .... verifying cycle
2008-09-18 08:15:41.65 spid4s 0:Insert new node: Node:1 ResType:LockOwner Stype:'OR'Xdes:0x047ECFD0 Mode: U SPID:55 BatchID:0 ECID:0 TaskProxy:(0x6140C378) Value:0x3098e880 Cost:(0/284)
2008-09-18 08:15:41.65 spid4s 1:SearchOR Considering new blocker - task: 00BD46B8, Worker 05E9C0E8
2008-09-18 08:15:41.65 spid4s 2:Insert new node: Node:2 ResType:LockOwner Stype:'OR'Xdes:0x03D7F848 Mode: U SPID:58 BatchID:0 ECID:0 TaskProxy:(0x45BB6378) Value:0x537bc960 Cost:(0/2196)
2008-09-18 08:15:41.65 spid4s 3:SearchOR Considering new blocker - task: 0092FB58, Worker 5424E0E8
2008-09-18 08:15:41.65 spid4s 4:InsertKnown Cycle found between old res owner: [ ResType:LockOwner Stype:'OR'Xdes:0x047ECFD0 Mode: U SPID:55 BatchID:0 ECID:0 TaskProxy:(0x6140C378) Value:0x3098e880 Cost:(0/284)] and new res owner [ ResType:LockOwner Stype:'OR'Xdes:0x047ECFD0 Mode: U SPID:55 BatchID:0 ECID:0 TaskProxy:(0x6140C378) Value:0x3098e880 Cost:(0/284)]
2008-09-18 08:15:41.65 spid4s 4:InsertKnown search result: Deadlock found (blocking owner is on a stack)
2008-09-18 08:15:41.65 spid4s 3:SearchOR search result: Deadlock found (cycle on this level or before)
2008-09-18 08:15:41.65 spid4s 1:SearchOR search result: Deadlock found (cycle on this level or before)
2008-09-18 08:15:41.65 spid4s End deadlock search 30926 ... a deadlock was found.
Can anyone tell me how I go about translating this into something that I can use to try and find what caused the deadlock?
Thanks
ps. I didn't put in the 🙁 !!!
September 18, 2008 at 10:11 am
Isolate the activity, if you can.
Do you have a Beta/QA environment?
Find out what processes are blocking each other.
Usually things are going in conflicting order.
Rewrite one so it harmonizes with the other, and you'll be good.
Easy, right? 🙂
Good luck...............
September 18, 2008 at 10:20 am
What traceflag do you have on to get that output? (1205?)
Try switching whichever that one is off and switching 1222 on. It gives very nice, very detailed output. There's nothing in that output that I can see that would help in finding the cause.
Is this frequent, or was it a once-off?
Gail Shaw
Microsoft Certified Master: SQL Server, MVP, M.Sc (Comp Sci)
SQL In The Wild: Discussions on DB performance with occasional diversions into recoverability
September 18, 2008 at 10:21 am
Hmmm...not sure about easy 😉
This deadlock is occurring on our live server and is related to a third party product so trying to recreate what the problem is will be tricky. Can you advise on what else I can do to try and get more meaningful data from SQL Server?
Thanks
September 18, 2008 at 10:22 am
GilaMonster (9/18/2008)
What traceflag do you have on to get that output? (1205?)Try switching whichever that one is off and switching 1222 on. It gives very nice, very detailed output. There's nothing in that output that I can see that would help in finding the cause.
Is this frequent, or was it a once-off?
Hi Gail,
Yes it is 1205, I'll try the trace you suggest. This is probably occurring daily but I cannot identify a pattern.
Thanks
September 18, 2008 at 10:29 am
When you get a deadlock graph, post it here and I'm sure someone will help you with it.
Gail Shaw
Microsoft Certified Master: SQL Server, MVP, M.Sc (Comp Sci)
SQL In The Wild: Discussions on DB performance with occasional diversions into recoverability
September 18, 2008 at 11:09 am
Can you replicate it at will? (On a development server, of course?)
If so...turn on SQL Profiler - it is a tricky and complex tool, however you should be able to select enough counters (stored procedure executes, select statements, lock waits, etc.) to get a good snapshot.
This is if your other idea doesn't work - it's a lot of effort to set it up.
September 19, 2008 at 4:16 am
GilaMonster (9/18/2008)
When you get a deadlock graph, post it here and I'm sure someone will help you with it.
Hi Gail,
Here is the output in the ERRORLOG after turning the trace flag you suggested on:
2008-09-19 10:10:45.87 spid16s deadlock-list
2008-09-19 10:10:45.87 spid16s deadlock victim=process9294c8
2008-09-19 10:10:45.87 spid16s process-list
2008-09-19 10:10:45.87 spid16s process id=process9294c8 taskpriority=0 logused=472 waitresource=RID: 5:1:571:66 waittime=937 ownerId=57579558 transactionname=implicit_transaction lasttranstarted=2008-09-19T10:10:44.923 XDES=0x22b404d8 lockMode=U schedulerid=2 kpid=2832 status=suspended spid=57 sbid=0 ecid=0 priority=0 transcount=2 lastbatchstarted=2008-09-19T10:10:44.923 lastbatchcompleted=2008-09-19T10:10:44.923 hostname=TEST hostpid=7972 loginname=tsuser isolationlevel=read committed (2) xactid=57579558 currentdb=5 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128058
2008-09-19 10:10:45.87 spid16s executionStack
2008-09-19 10:10:45.87 spid16s frame procname=dbTest.tsuser.jxc_158 line=10 stmtstart=446 stmtend=914 sqlhandle=0x030005004c7c8154b1264501e59900000000000000000000
2008-09-19 10:10:45.87 spid16s UPDATE "timesheet_cache" SET
"last_updated" = (DateDiff(second, '01-01-1970 00:00:00.0', convert(char(8), GetDate(), 112)) + (DateDiff(ms, convert(char(8), GetDate(), 112), GetDate()) / 1000.0))
WHERE "table_name" = 'user_lockout'
2008-09-19 10:10:45.87 spid16s frame procname=adhoc line=1 stmtstart=68 sqlhandle=0x0200000094864d06dd6324bfc2df78f3aa6a4e78e2ca22b0
2008-09-19 10:10:45.87 spid16s INSERT INTO "user_lockout" VALUES (@P1, @P2, @P3)
2008-09-19 10:10:45.87 spid16s frame procname=unknown line=1 sqlhandle=0x000000000000000000000000000000000000000000000000
2008-09-19 10:10:45.87 spid16s unknown
2008-09-19 10:10:45.87 spid16s inputbuf
2008-09-19 10:10:45.87 spid16s (@P1 char(8),@P2 int,@P3 char(12))INSERT INTO "user_lockout" VALUES (@P1, @P2, @P3)
2008-09-19 10:10:45.87 spid16s process id=process92ee38 taskpriority=0 logused=2204 waitresource=RID: 5:1:571:8 waittime=890 ownerId=57579553 transactionname=implicit_transaction lasttranstarted=2008-09-19T10:10:44.890 XDES=0x47ed1c8 lockMode=U schedulerid=3 kpid=6344 status=suspended spid=54 sbid=0 ecid=0 priority=0 transcount=2 lastbatchstarted=2008-09-19T10:10:44.970 lastbatchcompleted=2008-09-19T10:10:44.953 hostname=TEST hostpid=7680 loginname=tsuser isolationlevel=read committed (2) xactid=57579553 currentdb=5 lockTimeout=4294967295 clientoption1=671219744 clientoption2=128058
2008-09-19 10:10:45.87 spid16s executionStack
2008-09-19 10:10:45.87 spid16s frame procname=dbTest.tsuser.jxc_128 line=10 stmtstart=454 stmtend=930 sqlhandle=0x030005001ccecc20d3274501e59900000000000000000000
2008-09-19 10:10:45.87 spid16s UPDATE "timesheet_cache" SET
"last_updated" = (DateDiff(second, '01-01-1970 00:00:00.0', convert(char(8), GetDate(), 112)) + (DateDiff(ms, convert(char(8), GetDate(), 112), GetDate()) / 1000.0))
WHERE "table_name" = 'user_time_sheets'
2008-09-19 10:10:45.87 spid16s frame procname=adhoc line=1 stmtstart=236 sqlhandle=0x020000009b35bf0998802ca49b5158febd040b571f5bab96
2008-09-19 10:10:45.87 spid16s UPDATE "user_time_sheets" SET "id_sheet" = @P1 ,"id_timesheet" = @P2 ,"id_user" = @P3 ,"pname" = @P4 ,"state" = @P5 ,"start_date" = @P6 ,"end_date" = @P7 ,"id_domain" = @P8 ,"id_approver" = NULL ,"level" = @P9 ,"reserved1" = NULL WHERE "user_time_sheets"."id_sheet" = @P10
2008-09-19 10:10:45.87 spid16s frame procname=unknown line=1 sqlhandle=0x000000000000000000000000000000000000000000000000
2008-09-19 10:10:45.87 spid16s unknown
2008-09-19 10:10:45.87 spid16s inputbuf
2008-09-19 10:10:45.87 spid16s (@P1 char(32),@P2 char(6),@P3 char(8),@P4 char(23),@P5 int,@P6 char(8),@P7 char(8),@P8 char(16),@P9 int,@P10 char(32))UPDATE "user_time_sheets" SET "id_sheet" = @P1 ,"id_timesheet" = @P2 ,"id_user" = @P3 ,"pname" = @P4 ,"state" = @P5 ,"start_date" = @P6 ,"end_date" = @P7 ,"id_domain" = @P8 ,"id_approver" = NULL ,"level" = @P9 ,"reserved1" = NULL WHERE "user_time_sheets"."id_sheet" = @P10
2008-09-19 10:10:45.87 spid16s resource-list
2008-09-19 10:10:45.87 spid16s ridlock fileid=1 pageid=571 dbid=5 objectname=dbTest.tsuser.timesheet_cache id=lock2926a800 mode=X associatedObjectId=72057594066042880
2008-09-19 10:10:45.87 spid16s owner-list
2008-09-19 10:10:45.87 spid16s owner id=process9294c8 mode=X
2008-09-19 10:10:45.87 spid16s waiter-list
2008-09-19 10:10:45.87 spid16s waiter id=process92ee38 mode=U requestType=wait
2008-09-19 10:10:45.87 spid16s ridlock fileid=1 pageid=571 dbid=5 objectname=dbTest.tsuser.timesheet_cache id=lock30b480c0 mode=X associatedObjectId=72057594066042880
2008-09-19 10:10:45.87 spid16s owner-list
2008-09-19 10:10:45.87 spid16s owner id=process92ee38 mode=X
2008-09-19 10:10:45.87 spid16s waiter-list
2008-09-19 10:10:45.87 spid16s waiter id=process9294c8 mode=U requestType=wait
Thanks
David
September 19, 2008 at 5:52 am
Ok, the deadlock is occurring in the procedure "dbTest.tsuser.jxc_158". It looks like both processes are running the same proc.
It looks like there's an update (line 10) (UPDATE "timesheet_cache" SET "last_updated" ...) followed by a piece of dynamic SQL (as indicated by the line that reads procname = adhoc line = 1)
It looks like the object that the deadlock occurs on is "dbTest.tsuser.timesheet_cache" and it appears that both processes have a RID lock (no clustered index?) in exclusive mode and are wanting a different rid lock in update mode, which the other process happens to have.
It also looks like you have implicit transactions on, so all locks will be held until a commit if fired. (transactionname=implicit_transaction)
Is that any help?
If you would like some help in fixing it, can you post that proc please and the definitions and indexes of the following tables. Also please check to see if there are triggers on the tables.
timesheet_cache
user_time_sheets
user_lockout
Gail Shaw
Microsoft Certified Master: SQL Server, MVP, M.Sc (Comp Sci)
SQL In The Wild: Discussions on DB performance with occasional diversions into recoverability
Viewing 9 posts - 1 through 8 (of 8 total)
You must be logged in to reply to this topic. Login to reply