April 3, 2012 at 3:39 pm
In one of my PROD Server, in SQL Server Logs, I see these messages.
"pagelock fileid=1 pageid=3535848 dbid=8 objectname=dbVelocityMetadata.dbo.WorkQueue id=lock3ba0e4200 mode=S associatedObjectId=72057594108837888"
"waiter id=process5863948 mode=S requestType=wait"
"exchangeEvent id=Pipe268a18880 WaitType=e_waitPipeGetRow nodeId=10"
"deadlock victim=process5863948".
Seems like one of my jobs is definitely facing deadlock issues. I don't know how to figure out which job is getting facing this issue. I'm new to SQL Servers.
Can anyone please help me how to point out the respective job and trouble shoot this.
Thanks in advance.
April 3, 2012 at 4:15 pm
I enabled the trace 1222 on my server.
I just wanna figure out when and where this dead lock is occuring.
If anyone can help me walk through this, I can provide any information or details that you require that might be helpful.
thanks in advance.
April 3, 2012 at 4:16 pm
Hustler1986 (4/3/2012)
I enabled the trace 1222 on my server.I just wanna figure out when and where this dead lock is occuring.
If anyone can help me walk through this, I can provide any information or details that you require that might be helpful.
thanks in advance.
April 3, 2012 at 4:16 pm
Post the deadlock graph please.
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
April 3, 2012 at 7:08 pm
Please find the below error log.
04/03/2012 16:17:25,spid25s,Unknown,waiter id=processbd531708 mode=IX requestType=wait
04/03/2012 16:17:25,spid25s,Unknown,waiter-list
04/03/2012 16:17:25,spid25s,Unknown,owner-list
04/03/2012 16:17:25,spid25s,Unknown,pagelock fileid=1 pageid=3535848 dbid=8 objectname=dbVelocityMetadata.dbo.WorkQueue id=lock1ac021680 mode=S associatedObjectId=72057594108837888
04/03/2012 16:17:25,spid25s,Unknown,waiter id=process5863048 mode=IX requestType=wait
04/03/2012 16:17:25,spid25s,Unknown,waiter-list
04/03/2012 16:17:25,spid25s,Unknown,owner id=process627948 mode=S
04/03/2012 16:17:25,spid25s,Unknown,owner-list
04/03/2012 16:17:25,spid25s,Unknown,pagelock fileid=1 pageid=3535848 dbid=8 objectname=dbVelocityMetadata.dbo.WorkQueue id=lock1ac021680 mode=S associatedObjectId=72057594108837888
04/03/2012 16:17:25,spid25s,Unknown,waiter id=process627948 mode=S requestType=wait
04/03/2012 16:17:25,spid25s,Unknown,waiter-list
04/03/2012 16:17:25,spid25s,Unknown,owner id=process5863048 mode=IX
04/03/2012 16:17:25,spid25s,Unknown,owner id=processbd531708 mode=IX
04/03/2012 16:17:25,spid25s,Unknown,owner-list
04/03/2012 16:17:25,spid25s,Unknown,pagelock fileid=1 pageid=1688513 dbid=8 objectname=dbVelocityMetadata.dbo.WorkQueue id=lock3e51c1180 mode=IX associatedObjectId=72057594108837888
04/03/2012 16:17:25,spid25s,Unknown,resource-list
04/03/2012 16:17:25,spid25s,Unknown,EXEC dbo.InfaWorkFLowCompletionSet @InfaRunInstanceName = 'SUBSCRIPTIONCONTACT2_2_0_20120403155600__4F481909_EC9F_4698_8D7A_F926F2A01D'
04/03/2012 16:17:25,spid25s,Unknown,inputbuf
04/03/2012 16:17:25,spid25s,Unknown,unknown
04/03/2012 16:17:25,spid25s,Unknown,frame procname=unknown line=1 sqlhandle=0x000000000000000000000000000000000000000000000000
04/03/2012 16:17:25,spid25s,Unknown,EXEC dbo.InfaWorkFLowCompletionSet @InfaRunInstanceName = 'SUBSCRIPTIONCONTACT2_2_0_20120403155600__4F481909_EC9F_4698_8D7A_F926F2A01D'
04/03/2012 16:17:25,spid25s,Unknown,frame procname=adhoc line=1 sqlhandle=0x0100080043867c04001b7e85070000000000000000000000
04/03/2012 16:17:25,spid25s,Unknown,WHERE WorkQueueID = @WorkQueueID;
04/03/2012 16:17:25,spid25s,Unknown,<c/>LastUpdatedDate = GETDATE()
04/03/2012 16:17:25,spid25s,Unknown,<c/>LastUpdatedBY = SYSTEM_USER
04/03/2012 16:17:25,spid25s,Unknown,<c/>WorkQueueProcessingMSG = 'DataLoaded: ' + WorkQueueProcessingMSG
04/03/2012 16:17:25,spid25s,Unknown,<c/>WorkQueueEndWorkDate = GETDATE()
04/03/2012 16:17:25,spid25s,Unknown,<c/>WorkQueueStatusUTCDate = GETUTCDATE()
04/03/2012 16:17:25,spid25s,Unknown,<c/> WorkQueueStatusDate = GETDATE()
04/03/2012 16:17:25,spid25s,Unknown,SET WorkQueueStatus = 'DataLoaded'
04/03/2012 16:17:25,spid25s,Unknown,UPDATE [dbo].[WorkQueue]
04/03/2012 16:17:25,spid25s,Unknown,frame procname=dbVelocityMetadata.dbo.InfaWorkFLowCompletionSet line=175 stmtstart=11768 stmtend=12510 sqlhandle=0x03000800e58a96545994dd00a29f00000100000000000000
04/03/2012 16:17:25,spid25s,Unknown,executionStack
04/03/2012 16:17:25,spid25s,Unknown,process id=processbd531708 taskpriority=0 logused=592 waitresource=PAGE: 8:1:3535848 waittime=4721 ownerId=1551789430 transactionname=user_transaction lasttranstarted=2012-04-03T16:17:21.190 XDES=0x84e903950 lockMode=IX schedulerid=4 kpid=10456 status=suspended spid=85 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2012-04-03T16:17:21.190 lastbatchcompleted=2012-04-03T16:17:21.057 hostname=TK5BIINFMAPRD03 hostpid=10072 loginname=REDMOND\EDWSQLP isolationlevel=read committed (2) xactid=1551789430 currentdb=8 lockTimeout=4294967295 clientoption1=673185824 clientoption2=128056
04/03/2012 16:17:25,spid25s,Unknown,EXEC dbo.InfaWorkFLowCompletionSet @InfaRunInstanceName = 'ORDERLINEITEMHISTORY2_2_0_20120403155600__4C760596_209F_4956_A290_41CFE6C2D'
04/03/2012 16:17:25,spid25s,Unknown,inputbuf
04/03/2012 16:17:25,spid25s,Unknown,unknown
04/03/2012 16:17:25,spid25s,Unknown,frame procname=unknown line=1 sqlhandle=0x000000000000000000000000000000000000000000000000
04/03/2012 16:17:25,spid25s,Unknown,EXEC dbo.InfaWorkFLowCompletionSet @InfaRunInstanceName = 'ORDERLINEITEMHISTORY2_2_0_20120403155600__4C760596_209F_4956_A290_41CFE6C2D'
04/03/2012 16:17:25,spid25s,Unknown,frame procname=adhoc line=1 sqlhandle=0x010008000650c52ae0fadbc0030000000000000000000000
04/03/2012 16:17:25,spid25s,Unknown,WHERE WorkQueueID = @WorkQueueID;
04/03/2012 16:17:25,spid25s,Unknown,<c/>LastUpdatedDate = GETDATE()
04/03/2012 16:17:25,spid25s,Unknown,<c/>LastUpdatedBY = SYSTEM_USER
04/03/2012 16:17:25,spid25s,Unknown,<c/>WorkQueueProcessingMSG = 'DataLoaded: ' + WorkQueueProcessingMSG
04/03/2012 16:17:25,spid25s,Unknown,<c/>WorkQueueEndWorkDate = GETDATE()
04/03/2012 16:17:25,spid25s,Unknown,<c/>WorkQueueStatusUTCDate = GETUTCDATE()
04/03/2012 16:17:25,spid25s,Unknown,<c/> WorkQueueStatusDate = GETDATE()
04/03/2012 16:17:25,spid25s,Unknown,SET WorkQueueStatus = 'DataLoaded'
04/03/2012 16:17:25,spid25s,Unknown,UPDATE [dbo].[WorkQueue]
04/03/2012 16:17:25,spid25s,Unknown,frame procname=dbVelocityMetadata.dbo.InfaWorkFLowCompletionSet line=175 stmtstart=11768 stmtend=12510 sqlhandle=0x03000800e58a96545994dd00a29f00000100000000000000
04/03/2012 16:17:25,spid25s,Unknown,executionStack
04/03/2012 16:17:25,spid25s,Unknown,process id=process5863048 taskpriority=0 logused=592 waitresource=PAGE: 8:1:3535848 waittime=4797 ownerId=1551789413 transactionname=user_transaction lasttranstarted=2012-04-03T16:17:21.107 XDES=0x3d8f40e80 lockMode=IX schedulerid=14 kpid=11508 status=suspended spid=91 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2012-04-03T16:17:21.107 lastbatchcompleted=2012-04-03T16:17:21.063 hostname=TK5BIINFMAPRD04 hostpid=12660 loginname=REDMOND\EDWSQLP isolationlevel=read committed (2) xactid=1551789413 currentdb=8 lockTimeout=4294967295 clientoption1=673185824 clientoption2=128056
04/03/2012 16:17:25,spid25s,Unknown,EXEC WatchDogProcessRun
04/03/2012 16:17:25,spid25s,Unknown,inputbuf
04/03/2012 16:17:25,spid25s,Unknown,EXEC WatchDogProcessRun
04/03/2012 16:17:25,spid25s,Unknown,frame procname=adhoc line=1 sqlhandle=0x01000800a6ec4901c04ca488040000000000000000000000
04/03/2012 16:17:25,spid25s,Unknown,<c/>@Debug = @Debug
04/03/2012 16:17:25,spid25s,Unknown,EXECUTE dbo.WorkQueueStatusSyncSet @SystemSystemObjectName = @SystemSystemObjectName
04/03/2012 16:17:25,spid25s,Unknown,frame procname=dbVelocityMetadata.dbo.WatchDogProcessRun line=109 stmtstart=7988 stmtend=8226 sqlhandle=0x03000800b07ef775ccaed2000ba000000100000000000000
04/03/2012 16:17:25,spid25s,Unknown,LEFT JOIN
04/03/2012 16:17:25,spid25s,Unknown,ON dgt.DataGroupID = ftg.TableDataGroupID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.DataGroupTable dgt
04/03/2012 16:17:25,spid25s,Unknown,ON ftg.FileTemplateGroupID = ft.FileTemplateGroupID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.FileTemplateGroup ftg
04/03/2012 16:17:25,spid25s,Unknown,ON ft.FileTemplateID = fa.FileTemplateID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.FileTemplate ft
04/03/2012 16:17:25,spid25s,Unknown,ON fa.FileArrivalID = lf.FileArrivalID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.FileArrival fa
04/03/2012 16:17:25,spid25s,Unknown,ON lf.LoadFileID = lfr.LoadFileID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.CDCDataExtractor_LoadFile lf
04/03/2012 16:17:25,spid25s,Unknown,ON lfr.WorkQueueID = wq.WorkQueueID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.LoadFileRun lfr
04/03/2012 16:17:25,spid25s,Unknown,FROM dbo.WorkQueue wq
04/03/2012 16:17:25,spid25s,Unknown,<c/>IsProcessed = 0
04/03/2012 16:17:25,spid25s,Unknown,<c/>dgt.TableName
04/03/2012 16:17:25,spid25s,Unknown,<c/>fa.FullUNCFileName
04/03/2012 16:17:25,spid25s,Unknown,<c/>RunStatusCode = rwr.RUN_STATUS_CODE
04/03/2012 16:17:25,spid25s,Unknown,EXEC('SELECT wq.WorkQueueID
04/03/2012 16:17:25,spid25s,Unknown,<c/>IsProcessed)
04/03/2012 16:17:25,spid25s,Unknown,<c/>TableName
04/03/2012 16:17:25,spid25s,Unknown,<c/>FullUNCFileName
04/03/2012 16:17:25,spid25s,Unknown,<c/>RunStatusCode
04/03/2012 16:17:25,spid25s,Unknown,INSERT INTO @StatusNULLRunInstance (WorkQueueID
04/03/2012 16:17:25,spid25s,Unknown,frame procname=dbVelocityMetadata.dbo.WorkQueueStatusSyncSet line=226 stmtstart=20696 stmtend=24740 sqlhandle=0x03000800595fa967b7aed2000ba000000100000000000000
04/03/2012 16:17:25,spid25s,Unknown,WHERE WORKFLOW_NAME IN ('wfFileLoadInitialization'<c/>'wfPreLoa
04/03/2012 16:17:25,spid25s,Unknown,FROM InfaRepositoryOne.[PowerCenter02].dbo.OPB_WFLOW_RUN
04/03/2012 16:17:25,spid25s,Unknown,LEFT JOIN (SELECT RUNINST_NAME<c/> RID=ROW_NUMBER() OVER (PARTITION BY RUNINST_NAME ORDER BY WORKFLOW_RUN_ID DESC)<c/> RUN_STATUS_CODE
04/03/2012 16:17:25,spid25s,Unknown,ON dgt.DataGroupID = ftg.TableDataGroupID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.DataGroupTable dgt
04/03/2012 16:17:25,spid25s,Unknown,ON ftg.FileTemplateGroupID = ft.FileTemplateGroupID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.FileTemplateGroup ftg
04/03/2012 16:17:25,spid25s,Unknown,ON ft.FileTemplateID = fa.FileTemplateID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.FileTemplate ft
04/03/2012 16:17:25,spid25s,Unknown,ON fa.FileArrivalID = lf.FileArrivalID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.FileArrival fa
04/03/2012 16:17:25,spid25s,Unknown,ON lf.LoadFileID = lfr.LoadFileID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.CDCDataExtractor_LoadFile lf
04/03/2012 16:17:25,spid25s,Unknown,ON lfr.WorkQueueID = wq.WorkQueueID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.LoadFileRun lfr
04/03/2012 16:17:25,spid25s,Unknown,FROM dbo.WorkQueue wq
04/03/2012 16:17:25,spid25s,Unknown,<c/>IsProcessed = 0
04/03/2012 16:17:25,spid25s,Unknown,<c/>dgt.TableName
04/03/2012 16:17:25,spid25s,Unknown,<c/>fa.FullUNCFileName
04/03/2012 16:17:25,spid25s,Unknown,<c/>RunStatusCode = rwr.RUN_STATUS_CODE
04/03/2012 16:17:25,spid25s,Unknown,SELECT wq.WorkQueueID
04/03/2012 16:17:25,spid25s,Unknown,frame procname=adhoc line=1 sqlhandle=0x02000000977a1b344eaf61fb1f70bba0ad63915a3b152bd2
04/03/2012 16:17:25,spid25s,Unknown,executionStack
04/03/2012 16:17:25,spid25s,Unknown,process id=process627948 taskpriority=0 logused=0 waitresource=PAGE: 8:1:1688513 waittime=4564 ownerId=1551789046 transactionname=INSERT EXEC lasttranstarted=2012-04-03T16:17:20.833 XDES=0x6c2d13790 lockMode=S schedulerid=7 kpid=15580 status=suspended spid=76 sbid=0 ecid=0 priority=0 trancount=1 lastbatchstarted=2012-04-02T17:23:00.757 lastbatchcompleted=2012-04-02T17:23:00.750 clientapp=SQLAgent - TSQL JobStep (Job 0x7C518879A7C1324594014B9F1855FFB2 : Step 4) hostname=TK5BIVELMDS hostpid=5092 loginname=REDMOND\EDWSQLP isolationlevel=read committed (2) xactid=1551789046 currentdb=8 lockTimeout=4294967295 clientoption1=538968096 clientoption2=128056
04/03/2012 16:17:25,spid25s,Unknown,process-list
04/03/2012 16:17:25,spid25s,Unknown,deadlock victim=process627948[/highlight]
04/03/2012 16:17:25,spid25s,Unknown,deadlock-list
04/03/2012 13:27:56,spid73,Unknown,DBCC TRACEON 2861<c/> server process ID (SPID) 73. This is an informational message only; no user action is required.
04/03/2012 06:35:42,spid74,Unknown,DBCC TRACEON 2861<c/> server process ID (SPID) 74. This is an informational message only; no user action is required.
April 3, 2012 at 7:18 pm
My manager asked me investigate this and raise a email thread with complete analysis of issue. I just know only 2 points by looking the above error log. I don't want talk trash in the email thread. instead really want know what happened during operations of jobs.
May be if I need know like what are
id=process5863048
taskpriority=0
logused=592
waitresource=PAGE
waittime=4797 ownerId=1551789413
XDES=0x3d8f40e80
lockMode=IX
schedulerid=14
kpid=11508
status=suspended
spid=91
sbid=0
ecid=0
priority=0
trancount=2
Then I might have better chance to understand how this issue occurred.
April 3, 2012 at 7:48 pm
That graph looks incomplete. It's almost all SPID 25, so unless it's deadlocking itself, that won't fly well. Is that the full graph or did you edit it heavily? There's a lot of information I would normally expect to see not there.
Never stop learning, even if it hurts. Ego bruises are practically mandatory as you learn unless you've never risked enough to make a mistake.
For better assistance in answering your questions[/url] | Forum Netiquette
For index/tuning help, follow these directions.[/url] |Tally Tables[/url]
Twitter: @AnyWayDBA
April 3, 2012 at 10:04 pm
This is SQL Server Log for the whole day. This is all I have. I did not edit the log. The job kicks off an informatica workflow which does ETL for us. And then the ETL related information is updated in our Metadata tables like Workqueue from dbVelocityMetadata Database.
Date,Source,Severity,Message
04/03/2012 16:17:25,spid25s,Unknown,waiter id=processbd531708 mode=IX requestType=wait
04/03/2012 16:17:25,spid25s,Unknown,waiter-list
04/03/2012 16:17:25,spid25s,Unknown,owner-list
04/03/2012 16:17:25,spid25s,Unknown,pagelock fileid=1 pageid=3535848 dbid=8 objectname=dbVelocityMetadata.dbo.WorkQueue id=lock1ac021680 mode=S associatedObjectId=72057594108837888
04/03/2012 16:17:25,spid25s,Unknown,waiter id=process5863048 mode=IX requestType=wait
04/03/2012 16:17:25,spid25s,Unknown,waiter-list
04/03/2012 16:17:25,spid25s,Unknown,owner id=process627948 mode=S
04/03/2012 16:17:25,spid25s,Unknown,owner-list
04/03/2012 16:17:25,spid25s,Unknown,pagelock fileid=1 pageid=3535848 dbid=8 objectname=dbVelocityMetadata.dbo.WorkQueue id=lock1ac021680 mode=S associatedObjectId=72057594108837888
04/03/2012 16:17:25,spid25s,Unknown,waiter id=process627948 mode=S requestType=wait
04/03/2012 16:17:25,spid25s,Unknown,waiter-list
04/03/2012 16:17:25,spid25s,Unknown,owner id=process5863048 mode=IX
04/03/2012 16:17:25,spid25s,Unknown,owner id=processbd531708 mode=IX
04/03/2012 16:17:25,spid25s,Unknown,owner-list
04/03/2012 16:17:25,spid25s,Unknown,pagelock fileid=1 pageid=1688513 dbid=8 objectname=dbVelocityMetadata.dbo.WorkQueue id=lock3e51c1180 mode=IX associatedObjectId=72057594108837888
04/03/2012 16:17:25,spid25s,Unknown,resource-list
04/03/2012 16:17:25,spid25s,Unknown,EXEC dbo.InfaWorkFLowCompletionSet @InfaRunInstanceName = 'SUBSCRIPTIONCONTACT2_2_0_20120403155600__4F481909_EC9F_4698_8D7A_F926F2A01D'
04/03/2012 16:17:25,spid25s,Unknown,inputbuf
04/03/2012 16:17:25,spid25s,Unknown,unknown
04/03/2012 16:17:25,spid25s,Unknown,frame procname=unknown line=1 sqlhandle=0x000000000000000000000000000000000000000000000000
04/03/2012 16:17:25,spid25s,Unknown,EXEC dbo.InfaWorkFLowCompletionSet @InfaRunInstanceName = 'SUBSCRIPTIONCONTACT2_2_0_20120403155600__4F481909_EC9F_4698_8D7A_F926F2A01D'
04/03/2012 16:17:25,spid25s,Unknown,frame procname=adhoc line=1 sqlhandle=0x0100080043867c04001b7e85070000000000000000000000
04/03/2012 16:17:25,spid25s,Unknown,WHERE WorkQueueID = @WorkQueueID;
04/03/2012 16:17:25,spid25s,Unknown,<c/>LastUpdatedDate = GETDATE()
04/03/2012 16:17:25,spid25s,Unknown,<c/>LastUpdatedBY = SYSTEM_USER
04/03/2012 16:17:25,spid25s,Unknown,<c/>WorkQueueProcessingMSG = 'DataLoaded: ' + WorkQueueProcessingMSG
04/03/2012 16:17:25,spid25s,Unknown,<c/>WorkQueueEndWorkDate = GETDATE()
04/03/2012 16:17:25,spid25s,Unknown,<c/>WorkQueueStatusUTCDate = GETUTCDATE()
04/03/2012 16:17:25,spid25s,Unknown,<c/> WorkQueueStatusDate = GETDATE()
04/03/2012 16:17:25,spid25s,Unknown,SET WorkQueueStatus = 'DataLoaded'
04/03/2012 16:17:25,spid25s,Unknown,UPDATE [dbo].[WorkQueue]
04/03/2012 16:17:25,spid25s,Unknown,frame procname=dbVelocityMetadata.dbo.InfaWorkFLowCompletionSet line=175 stmtstart=11768 stmtend=12510 sqlhandle=0x03000800e58a96545994dd00a29f00000100000000000000
04/03/2012 16:17:25,spid25s,Unknown,executionStack
04/03/2012 16:17:25,spid25s,Unknown,process id=processbd531708 taskpriority=0 logused=592 waitresource=PAGE: 8:1:3535848 waittime=4721 ownerId=1551789430 transactionname=user_transaction lasttranstarted=2012-04-03T16:17:21.190 XDES=0x84e903950 lockMode=IX schedulerid=4 kpid=10456 status=suspended spid=85 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2012-04-03T16:17:21.190 lastbatchcompleted=2012-04-03T16:17:21.057 hostname=TK5BIINFMAPRD03 hostpid=10072 loginname=REDMOND\EDWSQLP isolationlevel=read committed (2) xactid=1551789430 currentdb=8 lockTimeout=4294967295 clientoption1=673185824 clientoption2=128056
04/03/2012 16:17:25,spid25s,Unknown,EXEC dbo.InfaWorkFLowCompletionSet @InfaRunInstanceName = 'ORDERLINEITEMHISTORY2_2_0_20120403155600__4C760596_209F_4956_A290_41CFE6C2D'
04/03/2012 16:17:25,spid25s,Unknown,inputbuf
04/03/2012 16:17:25,spid25s,Unknown,unknown
04/03/2012 16:17:25,spid25s,Unknown,frame procname=unknown line=1 sqlhandle=0x000000000000000000000000000000000000000000000000
04/03/2012 16:17:25,spid25s,Unknown,EXEC dbo.InfaWorkFLowCompletionSet @InfaRunInstanceName = 'ORDERLINEITEMHISTORY2_2_0_20120403155600__4C760596_209F_4956_A290_41CFE6C2D'
04/03/2012 16:17:25,spid25s,Unknown,frame procname=adhoc line=1 sqlhandle=0x010008000650c52ae0fadbc0030000000000000000000000
04/03/2012 16:17:25,spid25s,Unknown,WHERE WorkQueueID = @WorkQueueID;
04/03/2012 16:17:25,spid25s,Unknown,<c/>LastUpdatedDate = GETDATE()
04/03/2012 16:17:25,spid25s,Unknown,<c/>LastUpdatedBY = SYSTEM_USER
04/03/2012 16:17:25,spid25s,Unknown,<c/>WorkQueueProcessingMSG = 'DataLoaded: ' + WorkQueueProcessingMSG
04/03/2012 16:17:25,spid25s,Unknown,<c/>WorkQueueEndWorkDate = GETDATE()
04/03/2012 16:17:25,spid25s,Unknown,<c/>WorkQueueStatusUTCDate = GETUTCDATE()
04/03/2012 16:17:25,spid25s,Unknown,<c/> WorkQueueStatusDate = GETDATE()
04/03/2012 16:17:25,spid25s,Unknown,SET WorkQueueStatus = 'DataLoaded'
04/03/2012 16:17:25,spid25s,Unknown,UPDATE [dbo].[WorkQueue]
04/03/2012 16:17:25,spid25s,Unknown,frame procname=dbVelocityMetadata.dbo.InfaWorkFLowCompletionSet line=175 stmtstart=11768 stmtend=12510 sqlhandle=0x03000800e58a96545994dd00a29f00000100000000000000
04/03/2012 16:17:25,spid25s,Unknown,executionStack
04/03/2012 16:17:25,spid25s,Unknown,process id=process5863048 taskpriority=0 logused=592 waitresource=PAGE: 8:1:3535848 waittime=4797 ownerId=1551789413 transactionname=user_transaction lasttranstarted=2012-04-03T16:17:21.107 XDES=0x3d8f40e80 lockMode=IX schedulerid=14 kpid=11508 status=suspended spid=91 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2012-04-03T16:17:21.107 lastbatchcompleted=2012-04-03T16:17:21.063 hostname=TK5BIINFMAPRD04 hostpid=12660 loginname=REDMOND\EDWSQLP isolationlevel=read committed (2) xactid=1551789413 currentdb=8 lockTimeout=4294967295 clientoption1=673185824 clientoption2=128056
04/03/2012 16:17:25,spid25s,Unknown,EXEC WatchDogProcessRun
04/03/2012 16:17:25,spid25s,Unknown,inputbuf
04/03/2012 16:17:25,spid25s,Unknown,EXEC WatchDogProcessRun
04/03/2012 16:17:25,spid25s,Unknown,frame procname=adhoc line=1 sqlhandle=0x01000800a6ec4901c04ca488040000000000000000000000
04/03/2012 16:17:25,spid25s,Unknown,<c/>@Debug = @Debug
04/03/2012 16:17:25,spid25s,Unknown,EXECUTE dbo.WorkQueueStatusSyncSet @SystemSystemObjectName = @SystemSystemObjectName
04/03/2012 16:17:25,spid25s,Unknown,frame procname=dbVelocityMetadata.dbo.WatchDogProcessRun line=109 stmtstart=7988 stmtend=8226 sqlhandle=0x03000800b07ef775ccaed2000ba000000100000000000000
04/03/2012 16:17:25,spid25s,Unknown,LEFT JOIN
04/03/2012 16:17:25,spid25s,Unknown,ON dgt.DataGroupID = ftg.TableDataGroupID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.DataGroupTable dgt
04/03/2012 16:17:25,spid25s,Unknown,ON ftg.FileTemplateGroupID = ft.FileTemplateGroupID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.FileTemplateGroup ftg
04/03/2012 16:17:25,spid25s,Unknown,ON ft.FileTemplateID = fa.FileTemplateID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.FileTemplate ft
04/03/2012 16:17:25,spid25s,Unknown,ON fa.FileArrivalID = lf.FileArrivalID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.FileArrival fa
04/03/2012 16:17:25,spid25s,Unknown,ON lf.LoadFileID = lfr.LoadFileID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.CDCDataExtractor_LoadFile lf
04/03/2012 16:17:25,spid25s,Unknown,ON lfr.WorkQueueID = wq.WorkQueueID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.LoadFileRun lfr
04/03/2012 16:17:25,spid25s,Unknown,FROM dbo.WorkQueue wq
04/03/2012 16:17:25,spid25s,Unknown,<c/>IsProcessed = 0
04/03/2012 16:17:25,spid25s,Unknown,<c/>dgt.TableName
04/03/2012 16:17:25,spid25s,Unknown,<c/>fa.FullUNCFileName
04/03/2012 16:17:25,spid25s,Unknown,<c/>RunStatusCode = rwr.RUN_STATUS_CODE
04/03/2012 16:17:25,spid25s,Unknown,EXEC('SELECT wq.WorkQueueID
04/03/2012 16:17:25,spid25s,Unknown,<c/>IsProcessed)
04/03/2012 16:17:25,spid25s,Unknown,<c/>TableName
04/03/2012 16:17:25,spid25s,Unknown,<c/>FullUNCFileName
04/03/2012 16:17:25,spid25s,Unknown,<c/>RunStatusCode
04/03/2012 16:17:25,spid25s,Unknown,INSERT INTO @StatusNULLRunInstance (WorkQueueID
04/03/2012 16:17:25,spid25s,Unknown,frame procname=dbVelocityMetadata.dbo.WorkQueueStatusSyncSet line=226 stmtstart=20696 stmtend=24740 sqlhandle=0x03000800595fa967b7aed2000ba000000100000000000000
04/03/2012 16:17:25,spid25s,Unknown,WHERE WORKFLOW_NAME IN ('wfFileLoadInitialization'<c/>'wfPreLoa
04/03/2012 16:17:25,spid25s,Unknown,FROM InfaRepositoryOne.[PowerCenter02].dbo.OPB_WFLOW_RUN
04/03/2012 16:17:25,spid25s,Unknown,LEFT JOIN (SELECT RUNINST_NAME<c/> RID=ROW_NUMBER() OVER (PARTITION BY RUNINST_NAME ORDER BY WORKFLOW_RUN_ID DESC)<c/> RUN_STATUS_CODE
04/03/2012 16:17:25,spid25s,Unknown,ON dgt.DataGroupID = ftg.TableDataGroupID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.DataGroupTable dgt
04/03/2012 16:17:25,spid25s,Unknown,ON ftg.FileTemplateGroupID = ft.FileTemplateGroupID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.FileTemplateGroup ftg
04/03/2012 16:17:25,spid25s,Unknown,ON ft.FileTemplateID = fa.FileTemplateID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.FileTemplate ft
04/03/2012 16:17:25,spid25s,Unknown,ON fa.FileArrivalID = lf.FileArrivalID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.FileArrival fa
04/03/2012 16:17:25,spid25s,Unknown,ON lf.LoadFileID = lfr.LoadFileID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.CDCDataExtractor_LoadFile lf
04/03/2012 16:17:25,spid25s,Unknown,ON lfr.WorkQueueID = wq.WorkQueueID
04/03/2012 16:17:25,spid25s,Unknown,JOIN dbo.LoadFileRun lfr
04/03/2012 16:17:25,spid25s,Unknown,FROM dbo.WorkQueue wq
04/03/2012 16:17:25,spid25s,Unknown,<c/>IsProcessed = 0
04/03/2012 16:17:25,spid25s,Unknown,<c/>dgt.TableName
04/03/2012 16:17:25,spid25s,Unknown,<c/>fa.FullUNCFileName
04/03/2012 16:17:25,spid25s,Unknown,<c/>RunStatusCode = rwr.RUN_STATUS_CODE
04/03/2012 16:17:25,spid25s,Unknown,SELECT wq.WorkQueueID
04/03/2012 16:17:25,spid25s,Unknown,frame procname=adhoc line=1 sqlhandle=0x02000000977a1b344eaf61fb1f70bba0ad63915a3b152bd2
04/03/2012 16:17:25,spid25s,Unknown,executionStack
04/03/2012 16:17:25,spid25s,Unknown,process id=process627948 taskpriority=0 logused=0 waitresource=PAGE: 8:1:1688513 waittime=4564 ownerId=1551789046 transactionname=INSERT EXEC lasttranstarted=2012-04-03T16:17:20.833 XDES=0x6c2d13790 lockMode=S schedulerid=7 kpid=15580 status=suspended spid=76 sbid=0 ecid=0 priority=0 trancount=1 lastbatchstarted=2012-04-02T17:23:00.757 lastbatchcompleted=2012-04-02T17:23:00.750 clientapp=SQLAgent - TSQL JobStep (Job 0x7C518879A7C1324594014B9F1855FFB2 : Step 4) hostname=TK5BIVELMDS hostpid=5092 loginname=REDMOND\EDWSQLP isolationlevel=read committed (2) xactid=1551789046 currentdb=8 lockTimeout=4294967295 clientoption1=538968096 clientoption2=128056
04/03/2012 16:17:25,spid25s,Unknown,process-list
04/03/2012 16:17:25,spid25s,Unknown,deadlock victim=process627948
04/03/2012 16:17:25,spid25s,Unknown,deadlock-list
04/03/2012 13:27:56,spid73,Unknown,DBCC TRACEON 2861<c/> server process ID (SPID) 73. This is an informational message only; no user action is required.
04/03/2012 06:35:42,spid74,Unknown,DBCC TRACEON 2861<c/> server process ID (SPID) 74. This is an informational message only; no user action is required.
04/03/2012 02:08:21,Backup,Unknown,Database backed up. Database: SQLOPSDB<c/> creation date(time): 2012/02/13(18:46:53)<c/> pages dumped: 650<c/> first LSN: 79:8849:44<c/> last LSN: 79:8867:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'E:\BIHVDSSQLMDS\Backup\MSSQL\Bak\Dailybackup\SQLOPSDB\SQLOPSDB_backup_2012_04_03_020002_2661860.bak'}). This is an informational message only. No user action is required.
04/03/2012 02:08:20,Backup,Unknown,Database backed up. Database: dbVelocityMetadata<c/> creation date(time): 2011/06/20(15:06:11)<c/> pages dumped: 3652622<c/> first LSN: 5967:123159:76<c/> last LSN: 5967:135534:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'E:\BIHVDSSQLMDS\Backup\MSSQL\Bak\Dailybackup\dbVelocityMetadata\dbVelocityMetadata_backup_2012_04_03_020002_2349866.bak'}). This is an informational message only. No user action is required.
04/03/2012 02:00:35,Backup,Unknown,Database backed up. Database: dbVelocityFileMonitor<c/> creation date(time): 2011/06/20(15:05:08)<c/> pages dumped: 77451<c/> first LSN: 575:124055:153<c/> last LSN: 575:124116:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'E:\BIHVDSSQLMDS\Backup\MSSQL\Bak\Dailybackup\dbVelocityFileMonitor\dbVelocityFileMonitor_backup_2012_04_03_020002_2193869.bak'}). This is an informational message only. No user action is required.
04/03/2012 02:00:25,Backup,Unknown,Database backed up. Database: DSLGetDataClient<c/> creation date(time): 2011/10/05(09:55:05)<c/> pages dumped: 3603<c/> first LSN: 137:7381:37<c/> last LSN: 137:7397:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'E:\BIHVDSSQLMDS\Backup\MSSQL\Bak\Dailybackup\DSLGetDataClient\DSLGetDataClient_backup_2012_04_03_020002_1881875.bak'}). This is an informational message only. No user action is required.
04/03/2012 02:00:24,Backup,Unknown,Database backed up. Database: Operations<c/> creation date(time): 2011/06/20(14:59:42)<c/> pages dumped: 83862<c/> first LSN: 37504:42113:37<c/> last LSN: 37504:42129:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'E:\BIHVDSSQLMDS\Backup\MSSQL\Bak\Dailybackup\Operations\Operations_backup_2012_04_03_020002_1725878.bak'}). This is an informational message only. No user action is required.
04/03/2012 02:00:10,Backup,Unknown,Database backed up. Database: msdb<c/> creation date(time): 2010/04/02(17:35:08)<c/> pages dumped: 13454<c/> first LSN: 419146:14606:278<c/> last LSN: 419146:14732:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'E:\BIHVDSSQLMDS\Backup\MSSQL\Bak\Dailybackup\msdb\msdb_backup_2012_04_03_020002_1569881.bak'}). This is an informational message only. No user action is required.
04/03/2012 02:00:07,Backup,Unknown,Database backed up. Database: model<c/> creation date(time): 2003/04/08(09:13:36)<c/> pages dumped: 185<c/> first LSN: 82:22:37<c/> last LSN: 82:38:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'E:\BIHVDSSQLMDS\Backup\MSSQL\Bak\Dailybackup\model\model_backup_2012_04_03_020002_1101890.bak'}). This is an informational message only. No user action is required.
04/03/2012 02:00:04,Backup,Unknown,Database backed up. Database: master<c/> creation date(time): 2012/03/23(17:33:27)<c/> pages dumped: 378<c/> first LSN: 536:300:72<c/> last LSN: 536:332:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'E:\BIHVDSSQLMDS\Backup\MSSQL\Bak\Dailybackup\master\master_backup_2012_04_03_020002_0789896.bak'}). This is an informational message only. No user action is required.
04/03/2012 00:00:48,spid24s,Unknown,This instance of SQL Server has been using a process ID of 11368 since 3/23/2012 5:33:39 PM (local) 3/24/2012 12:33:39 AM (UTC). This is an informational message only; no user action is required.
April 4, 2012 at 12:47 am
Evil Kraig F (4/3/2012)
That graph looks incomplete. It's almost all SPID 25, so unless it's deadlocking itself, that won't fly well.
SPID 25 is the system spid responsible for writing out the deadlock graph, it's not part of the deadlock. If you look in the processes section (note the graph is upside down), you'll see spid 76, 91 and 85.
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
April 4, 2012 at 9:46 am
So do you need any other log? if yes. can you please tell me what it is and where can find it.
Gila Monster: The above log is from the SQL Server logs. I'm not sure where to check for processes in SQL Server logs.
April 4, 2012 at 9:55 am
It looks like SPID 76,85 and 91 are suspended. Not sure what process is responsible for it. Is it SPID 25?
April 4, 2012 at 10:01 am
Mac1986 (4/4/2012)
It looks like SPID 76,85 and 91 are suspended. Not sure what process is responsible for it. Is it SPID 25?
No. It's a deadlock, processes 76, 85 and 91 are blocking each other. 25 is just the deadlock detector. No other processes are involved.
I'll leave this one for Kraig when he wakes up.
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
April 4, 2012 at 10:44 am
When you asked for graph, were you referring to SQL Server Profiler graph?
April 4, 2012 at 10:51 am
Mac1986 (4/4/2012)
When you asked for graph, were you referring to SQL Server Profiler graph?
No. Referring to the deadlock graph in the error log. The one you posted this morning,
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
April 4, 2012 at 11:00 am
I see three different schedule IDs in there. Do you have three jobs running, potentially at the same time?
- Gus "GSquared", RSVP, OODA, MAP, NMVP, FAQ, SAT, SQL, DNA, RNA, UOI, IOU, AM, PM, AD, BC, BCE, USA, UN, CF, ROFL, LOL, ETC
Property of The Thread
"Nobody knows the age of the human race, but everyone agrees it's old enough to know better." - Anon
Viewing 15 posts - 1 through 15 (of 28 total)
You must be logged in to reply to this topic. Login to reply