Trace Flag 1222.. duplicate infomation in error log ?

  • Hi

    I wonder if you can help me , looking at the results stored in the error log after an update statement was involved in a deadlock

    In the execution stack there is the frame procname which contains the sql from execution plan

    Then is shows the sql with values

    Then is shows the input buffer which as far as I can see just repeats the previous frame procname i.e the sql with values

    Am I missing something ? , is this always duplicated or is it purely in this scenario

    many thanks Jack

  • Could you post the example you are talking about?

    [font="Times New Roman"]Erland Sommarskog, SQL Server MVP, www.sommarskog.se[/font]

  • of course, sorry apologies I should have done that in the first place

    08/07/2013 12:35:56,spid27s,Unknown,AND PurchaseOrderID = 1255 ;

    08/07/2013 12:35:56,spid27s,Unknown,WHERE ProductID = 448

    08/07/2013 12:35:56,spid27s,Unknown,SET OrderQty = 4

    08/07/2013 12:35:56,spid27s,Unknown,UPDATE Purchasing.PurchaseOrderDetail

    08/07/2013 12:35:56,spid27s,Unknown,inputbuf

    08/07/2013 12:35:56,spid27s,Unknown,AND PurchaseOrderID = 1255 ;

    08/07/2013 12:35:56,spid27s,Unknown,WHERE ProductID = 448

    08/07/2013 12:35:56,spid27s,Unknown,SET OrderQty = 4

    08/07/2013 12:35:56,spid27s,Unknown,UPDATE Purchasing.PurchaseOrderDetail

    08/07/2013 12:35:56,spid27s,Unknown,frame procname=adhoc line=3 stmtstart=8 sqlhandle=0x02000000d6a32b33ada89dd491584f1c1e69f3ded5d310a7

    08/07/2013 12:35:56,spid27s,Unknown,UPDATE [Purchasing].[PurchaseOrderDetail] set [OrderQty] = @1 WHERE [ProductID]=@2 AND [PurchaseOrderID]=@3

    08/07/2013 12:35:56,spid27s,Unknown,frame procname=adhoc line=3 stmtstart=64 sqlhandle=0x02000000d0c7f31a30fb1ad425c34357fe8ef6326793e7aa

    08/07/2013 12:35:56,spid27s,Unknown,executionStack

    08/07/2013 12:35:56,spid27s,Unknown,process id=process4429048 taskpriority=0 logused=356 waitresource=KEY: 32:72057594046578688 (4ab5f0d47ad5) waittime=2056 ownerId=53899 transactionname=user_transaction lasttranstarted=2013-08-07T12:35:40.593 XDES=0x18c675620 lockMode=U schedulerid=5 kpid=5624 status=suspended spid=56 sbid=0 ecid=0 priority=0 trancount=3 4

    08/07/2013 12:35:56,spid27s,Unknown,process-list

    08/07/2013 12:35:56,spid27s,Unknown,deadlock victim=process4429048

    08/07/2013 12:35:56,spid27s,Unknown,deadlock-list

    08/07/2013 12:35:21,spid57,Unknown,DBCC TRACEON 1222<c/> server process ID (SPID) 57. This is an informational message only; no user action is required.

  • It is not always so similar. If I had a stored procedure DeadLockDB.dbo.CauseDeadlockWithUpdate, that contained the statement

    UPDATE DeadLockTable SET DeadLockFloat=RAND()*@HavocFactor

    and that statement was involved in a deadlock when I called the stored procedure from the ad-hoc query

    WHILE 1=1

    BEGIN

    EXEC CauseDeadLockWithUpdate @HavocFactor=98

    END

    Then the first entry in the stack trace would show the UPDATE statement from within the stored procedure (and frame procname would = DeadLockDB.dbo.CauseDeadLockWithUpdate).

    The next would have the EXEC line from the ad-hoc query (and frame procname would = adhoc), and then the inputbuf at the top of the stack trace would just contain the entire ad-hoc query.

    I hope that I didn't muddy the waters even more 😉

    Cheers!

  • To add what Jacob says, look closer at the output (and note that for some reason you have posted it upside-down, so read from the bottom):

    08/07/2013 12:35:56,spid27s,Unknown,AND PurchaseOrderID = 1255 ;

    08/07/2013 12:35:56,spid27s,Unknown,WHERE ProductID = 448

    08/07/2013 12:35:56,spid27s,Unknown,SET OrderQty = 4

    08/07/2013 12:35:56,spid27s,Unknown,UPDATE Purchasing.PurchaseOrderDetail

    08/07/2013 12:35:56,spid27s,Unknown,inputbuf

    08/07/2013 12:35:56,spid27s,Unknown,AND PurchaseOrderID = 1255 ;

    08/07/2013 12:35:56,spid27s,Unknown,WHERE ProductID = 448

    08/07/2013 12:35:56,spid27s,Unknown,SET OrderQty = 4

    08/07/2013 12:35:56,spid27s,Unknown,UPDATE Purchasing.PurchaseOrderDetail

    08/07/2013 12:35:56,spid27s,Unknown,frame procname=adhoc line=3 stmtstart=8

    That is, first you have the stack frame (and there could be several if there are nested procedures) and then you have the inputbuffer. Since this is an ad-hoc statement, they are the same.

    [font="Times New Roman"]Erland Sommarskog, SQL Server MVP, www.sommarskog.se[/font]

Viewing 5 posts - 1 through 4 (of 4 total)

You must be logged in to reply to this topic. Login to reply