Deadlock occurs with INSERT VALUES 2

[ousoonerjoe]

Using SQL 2008 R2

Over the past several months, we have developed a deadlock issue with our Audit table. We use the following at the beginning of all our stored procedures:

      [COLOR=#204A87]      BEGIN TRANSACTION[/color];
            [COLOR=#204A87]INSERT INTO[/color] Audit(ProcName, CmdType, Statement, ExecFrom, RecordIdNum, Arg1, Arg2, Arg3)
                      [COLOR=#204A87]VALUES[/color]('cst_Proc_Name, 'UPDATE', '', '', @RecId, @Arg1, @Arg2, @Arg3);
      [COLOR=#204A87]COMMIT TRANSACTION[/color];

This is a simple INSERT and an occasional SELECT. However, in almost all instances of the deadlock no SELECT was executed. Multiple INSERTs collided as the following results file show. My understanding is that the INSERTs should just "get in line" and process out in a First come First serve order. This example accounts for 95% of our deadlocks. It may not be the same offending stored procedure, but the offending statement is almost always the INSERT INTO Audit statement. I would appreciate any suggestions you may have. I've been banging my head against the wall for a while and the cleaning crew is starting to complain about the blood stains. Thank you.

logdate                 procInfo   ERRORLOG                                                                                                                                                                                                                                                        
----------------------- ---------- ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
2012-09-21 10:52:05.000 spid7s     Deadlock encountered .... Printing deadlock information                                                                                                                                                                                                         
2012-09-21 10:52:05.000 spid7s     Wait-for graph                                                                                                                                                                                                                                                  
2012-09-21 10:52:05.000 spid7s     NULL                                                                                                                                                                                                                                                            
2012-09-21 10:52:05.000 spid7s     Node:1
                                                                                                                                                                                                                                                        
2012-09-21 10:52:05.000 spid7s     OBJECT: 5:1584086221:0         CleanCnt:3 Mode:IX Flags: 0x1                                                                                                                                                                                                    
2012-09-21 10:52:05.000 spid7s      Grant List 2:                                                                                                                                                                                                                                                  
2012-09-21 10:52:05.000 spid7s        Owner:0x4425DC00 Mode: IX       Flg:0x40 Ref:1 Life:02000000 SPID:93 ECID:0 XactLockInfo: 0x5A224B18                                                                                                                                                         
2012-09-21 10:52:05.000 spid7s        SPID: 93 ECID: 0 Statement Type: INSERT Line #: 19                                                                                                                                                                                                           
2012-09-21 10:52:05.000 spid7s        Input Buf: RPC Event: Proc [Database Id = 5 Object Id = 862534752]                                                                                                                                                                                           
2012-09-21 10:52:05.000 spid7s     Requested by:                                                                                                                                                                                                                                                   
2012-09-21 10:52:05.000 spid7s       ResType:LockOwner Stype:'OR'Xdes:0x11A22280 Mode: X SPID:76 BatchID:0 ECID:0 TaskProxy:(0x19C96354) Value:0x3dafaac0 Cost:(0/0)                                                                                                                               
2012-09-21 10:52:05.000 spid7s     NULL                                                                                                                                                                                                                                                            
2012-09-21 10:52:05.000 spid7s     Node:2
                                                                                                                                                                                                                                                        
2012-09-21 10:52:05.000 spid7s     OBJECT: 5:1584086221:0         CleanCnt:3 Mode:IX Flags: 0x1                                                                                                                                                                                                    
2012-09-21 10:52:05.000 spid7s      Grant List 2:                                                                                                                                                                                                                                                  
2012-09-21 10:52:05.000 spid7s        Owner:0x4A4C2820 Mode: IX       Flg:0x40 Ref:1 Life:02000000 SPID:76 ECID:0 XactLockInfo: 0x11A222A8                                                                                                                                                         
2012-09-21 10:52:05.000 spid7s        SPID: 76 ECID: 0 Statement Type: INSERT Line #: 19                                                                                                                                                                                                           
2012-09-21 10:52:05.000 spid7s        Input Buf: RPC Event: Proc [Database Id = 5 Object Id = 862534752]                                                                                                                                                                                           
2012-09-21 10:52:05.000 spid7s     Requested by:                                                                                                                                                                                                                                                   
2012-09-21 10:52:05.000 spid7s       ResType:LockOwner Stype:'OR'Xdes:0x5A224AF0 Mode: X SPID:93 BatchID:0 ECID:0 TaskProxy:(0x19DFC354) Value:0x4425cfa0 Cost:(0/0)                                                                                                                               
2012-09-21 10:52:05.000 spid7s     NULL                                                                                                                                                                                                                                                            
2012-09-21 10:52:05.000 spid7s     Victim Resource Owner:                                                                                                                                                                                                                                          
2012-09-21 10:52:05.000 spid7s      ResType:LockOwner Stype:'OR'Xdes:0x11A22280 Mode: X SPID:76 BatchID:0 ECID:0 TaskProxy:(0x19C96354) Value:0x3dafaac0 Cost:(0/0)                                                                                                                                
2012-09-21 10:52:05.000 spid23s    deadlock-list                                                                                                                                                                                                                                                   
2012-09-21 10:52:05.000 spid23s     deadlock victim=process3bed8e8                                                                                                                                                                                                                                 
2012-09-21 10:52:05.000 spid23s      process-list                                                                                                                                                                                                                                                  
2012-09-21 10:52:05.000 spid23s       process id=process3bed8e8 taskpriority=0 logused=0 waitresource=OBJECT: 5:1584086221:0  waittime=448 ownerId=479458334 transactionname=user_transaction lasttranstarted=2012-09-21T10:52:04.553 XDES=0x11a22280 lockMode=X schedulerid=6 kpid=5360 status=sus
2012-09-21 10:52:05.000 spid23s        executionStack                                                                                                                                                                                                                                              
2012-09-21 10:52:05.000 spid23s         frame procname=UC.dbo.cstDoStageOnly line=19 stmtstart=1558 stmtend=1894 sqlhandle=0x03000500603c69331667dd00be9e00000100000000000000                                                                                                                      
2012-09-21 10:52:05.000 spid23s    INSERT INTO Audit(ProcName, CmdType, Statement, ExecFrom, RecordIdNum, Arg1, Arg2, Arg3)                                                                                                                                                                        
2012-09-21 10:52:05.000 spid23s    		VALUES('cstDoStageOnly', 'UPDATE', '', '', 0, @ronum, @stageno, @dtstaged);                                                                                                                                                                                   
2012-09-21 10:52:05.000 spid23s        inputbuf                                                                                                                                                                                                                                                    
2012-09-21 10:52:05.000 spid23s    Proc [Database Id = 5 Object Id = 862534752]                                                                                                                                                                                                                    
2012-09-21 10:52:05.000 spid23s       process id=processff3558 taskpriority=0 logused=0 waitresource=OBJECT: 5:1584086221:0  waittime=448 ownerId=479458335 transactionname=user_transaction lasttranstarted=2012-09-21T10:52:04.553 XDES=0x5a224af0 lockMode=X schedulerid=5 kpid=980 status=suspe
2012-09-21 10:52:05.000 spid23s        executionStack                                                                                                                                                                                                                                              
2012-09-21 10:52:05.000 spid23s         frame procname=UC.dbo.cstDoStageOnly line=19 stmtstart=1558 stmtend=1894 sqlhandle=0x03000500603c69331667dd00be9e00000100000000000000                                                                                                                      
2012-09-21 10:52:05.000 spid23s    INSERT INTO Audit(ProcName, CmdType, Statement, ExecFrom, RecordIdNum, Arg1, Arg2, Arg3)                                                                                                                                                                        
2012-09-21 10:52:05.000 spid23s    		VALUES('cstDoStageOnly', 'UPDATE', '', '', 0, @ronum, @stageno, @dtstaged);                                                                                                                                                                                   
2012-09-21 10:52:05.000 spid23s        inputbuf                                                                                                                                                                                                                                                    
2012-09-21 10:52:05.000 spid23s    Proc [Database Id = 5 Object Id = 862534752]                                                                                                                                                                                                                    
2012-09-21 10:52:05.000 spid23s      resource-list                                                                                                                                                                                                                                                 
2012-09-21 10:52:05.000 spid23s       objectlock lockPartition=0 objid=1584086221 subresource=FULL dbid=5 objectname=UC.dbo.Audit id=locke491b00 mode=IX associatedObjectId=1584086221                                                                                                             
2012-09-21 10:52:05.000 spid23s        owner-list                                                                                                                                                                                                                                                  
2012-09-21 10:52:05.000 spid23s         owner id=processff3558 mode=IX                                                                                                                                                                                                                             
2012-09-21 10:52:05.000 spid23s        waiter-list                                                                                                                                                                                                                                                 
2012-09-21 10:52:05.000 spid23s         waiter id=process3bed8e8 mode=X requestType=convert                                                                                                                                                                                                        
2012-09-21 10:52:05.000 spid23s       objectlock lockPartition=0 objid=1584086221 subresource=FULL dbid=5 objectname=UC.dbo.Audit id=locke491b00 mode=IX associatedObjectId=1584086221                                                                                                             
2012-09-21 10:52:05.000 spid23s        owner-list                                                                                                                                                                                                                                                  
2012-09-21 10:52:05.000 spid23s         owner id=process3bed8e8 mode=IX                                                                                                                                                                                                                            
2012-09-21 10:52:05.000 spid23s        waiter-list                                                                                                                                                                                                                                                 
2012-09-21 10:52:05.000 spid23s         waiter id=processff3558 mode=X requestType=convert
                                                                                                                                                                                                       

(51 rows affected)

--------------------------------------------------
“Crash programs fail because they are based on the theory that, with nine women pregnant, you can get a baby a month.” --Wernher von Braun
--------------------------------------------------

 

[Qik3Coder]

What kind of traffic are you seeing on that table?
Do you have foreign keys to other tables (that it has to go check)
Are there triggers on this table, which may be slowing the insert down?

I'm not sure of the correct terms for this next question, but you should be able to figure out what I mean:
Do your file pages have enough space to allow inserts without having to move records?
This depends on how your data is stored on disk, which is usually related to how your primary key (clustered) is set up.


Lodlaiden

You've got questions and source code. We want both!
Here at tek tips, we provide a hand up, not a hand out.

 

[ousoonerjoe]

Thank you for the reply, Qik3Coker.

Traffic is medium.
Foreign Keys = None.
Other Joins/Links = None.
Triggers, Functions = None.

As for the "File Pages", I think you are trying to refer to the Table Partitions and sizes:
The table size is approximately 162 MB,
1,476,091 rows since Jan 1, 2012,
and is all contained within a single partition.

Table Create Script with Indexes, Constraints, Triggers, etc.:

[COLOR=blue]CREATE TABLE[/color] [dbo].[Audit](
	[AuditId] [int] [COLOR=blue]IDENTITY[/color](1,1) NOT NULL,
	[ProcName] [[COLOR=blue]varchar[/color]](50) NOT NULL,
	[CmdType] [[COLOR=blue]varchar[/color]](50) NOT NULL,
	[Statement] [[COLOR=blue]varchar[/color]](4000) NOT NULL,
	[ExecFrom] [[COLOR=blue]varchar[/color]](50) NULL,
	[RecordIdNum] [[COLOR=blue]int[/color]] NOT NULL,
	[Arg1] [[COLOR=blue]varchar[/color]](255) NULL,
	[Arg2] [[COLOR=blue]varchar[/color]](255) NULL,
	[Arg3] [[COLOR=blue]varchar[/color]](255) NULL,
	[CreatedBy] [[COLOR=blue]varchar[/color]](50) NOT NULL,
	[CreateHost] [[COLOR=blue]varchar[/color]](255) NOT NULL,
	[CreateDate] [[COLOR=blue]datetime[/color]] NOT NULL,
 [COLOR=blue]CONSTRAINT[/color] [PK_Audit] [COLOR=blue]PRIMARY KEY CLUSTERED [/color]
(
	[AuditId] [COLOR=blue]ASC[/color]
)[COLOR=blue]WITH (PAD_INDEX  = OFF, STATISTICS_NORECOMPUTE  = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS  = ON, ALLOW_PAGE_LOCKS  = ON, FILLFACTOR[/color] = 90) [COLOR=blue]ON[/color] [PRIMARY]
) [COLOR=blue]ON[/color] [PRIMARY]

[COLOR=blue]GO

SET ANSI_PADDING OFF
GO

ALTER TABLE[/color] [dbo].[Audit] [COLOR=blue]ADD  CONSTRAINT[/color] [DF_Audit_RecordIdNum] [COLOR=blue] DEFAULT[/color] ((0)) [COLOR=blue]FOR[/color] [RecordIdNum]
GO

[COLOR=blue]ALTER TABLE[/color] [dbo].[Audit] [COLOR=blue]ADD  CONSTRAINT[/color] [DF_Audit_CreatedBy] [COLOR=blue] DEFAULT[/color] ([COLOR=magenta]suser_sname[/color]()) [COLOR=blue]FOR[/color] [CreatedBy]
GO

[COLOR=blue]ALTER TABLE[/color] [dbo].[Audit][COLOR=blue] ADD  CONSTRAINT[/color] [DF_Audit_CreateHost] [COLOR=blue] DEFAULT[/color] ([COLOR=magenta]host_name[/color]()) [COLOR=blue]FOR[/color] [CreateHost]
GO

[COLOR=blue]ALTER TABLE[/color] [dbo].[Audit] [COLOR=blue]ADD  CONSTRAINT[/color] [DF_Audit_CreateDate] [COLOR=blue] DEFAULT[/color] ([COLOR=magenta]getdate[/color]())[COLOR=blue] FOR[/color] [CreateDate]
GO

--------------------------------------------------
“Crash programs fail because they are based on the theory that, with nine women pregnant, you can get a baby a month.” --Wernher von Braun
--------------------------------------------------

 

[Qik3Coder]

I was actually talking about the "fillfactor". Tables with "Old"/static data are sometimes have a fillfactor of 100%, so that they take up the least amount of space, but this makes inserts take longer because they have to juggle the data.

How often do you re-index and recompute the statistics for the table? I've seen drastic improvements from these 2 actions. You many want these set up as job that runs 1x day/hour.

Lodlaiden

You've got questions and source code. We want both!
Here at tek tips, we provide a hand up, not a hand out.

 

[ousoonerjoe]

I have the Index Rebuilds every week with the database backup plan. I will add the Stats Rebuild to it and see if that helps things.

Thank you.

--------------------------------------------------
“Crash programs fail because they are based on the theory that, with nine women pregnant, you can get a baby a month.” --Wernher von Braun
--------------------------------------------------

 

[gmmastros]

Do you have your data file and log file on the same physical hard drive? If so, I would recommend putting them on separate disks.

When you run a statement that changes data (insert, update, or delete), SQL Server writes data to the log file before the data is changed, then changes the data, and then writes again to the log file to mark that it is done changing the data. If your data and log file are on the same disk, it will take longer to do all of this because the platters need to spin in to the correct positions. When the data and log file are on separate disks, the platters don't need to move as much and therefore the entire operation will be a bit faster.

Under normal circumstances, the time it takes to write to the disk is not an issue, but in your case, it could make a big difference.

In your particular case, you have an identity column as the primary key. This means that the data is sorted physically on the disk based on the AuditId column. When an insert occurs, SQL Server will lock the entire last page prior to writing to the log file, and then release the lock after the last log file write, so your last page is locked for the duration of the activity. Since you are using an identity column, every time you insert a row, it will always insert it to the end of the data which is on the last page.

Now, please don't misunderstand me, I'm not suggesting that the primary key identity column is the problem here. It's something else.

Can you run the following statements and let me know the output:

sp_helptrigger 'Audit'
sp_helpindex 'Audit'

-George
Microsoft SQL Server MVP
My Blogs
SQLCop
twitter
"The great things about standards is that there are so many to choose from." - Fortune Cookie Wisdom

 

[ousoonerjoe]

Thanks for the feedback, George.

Currently the Logs and Data are on the same drive, but the drive is part of a RAID setup. Does that not negate a great deal of the drive IO issues?

EXEC sp_helptrigger 'Audit'; = No Records Found
EXEC sp_helpindex 'Audit'; = PK_Audit clustered, unique, primary key located on PRIMARY AuditId


I really don't think it is hardware related. I could be completely wrong, but in terms of database size and access, this is a small (5GB) database with few (@ 150) users.

--------------------------------------------------
“Crash programs fail because they are based on the theory that, with nine women pregnant, you can get a baby a month.” --Wernher von Braun
--------------------------------------------------

 

[ousoonerjoe]

After further discussions with the Hardware guys. They are convinced that the RAID designs already give the same benefits as splitting the Logs and Data files. However, I can migrate tempdb off C: and get it over to the RAID area. That would be the biggest improvement I can make at this time.

--------------------------------------------------
“Crash programs fail because they are based on the theory that, with nine women pregnant, you can get a baby a month.” --Wernher von Braun
--------------------------------------------------

 

[gmmastros]

Your hardware guys are wrong. Certainly there are some raid designs that make accessing and saving the data faster, but it will still be slower than having 2 separate disks.

TempDB is not used during inserts, so it will likely not make any difference with the deadlock problem.

-George
Microsoft SQL Server MVP
My Blogs
SQLCop
twitter
"The great things about standards is that there are so many to choose from." - Fortune Cookie Wisdom

 

[TheBugSlayer]

Following along the lines of George's assessment, you should consider temporarily removing the primary key and see what happens. There are deadlocks obviously because there is concurrency. How many of the ~150 users are using apps that audit in this way at the same time?

How often do you use AuditID in your queries? It seems to me ProcName is a better primary key (clustered index) despite not being a numeric field. That way there is less chances of every insert locking the same page.

MCP SQL Server 2000, MCTS SQL Server 2005, MCTS SQL Server 2008 (DBD, DBA)

 

[ousoonerjoe]

Apologies for the delay in response.

After a couple of discussions with the powers that be, it would appear that we are going to be migrating to a VM Ware solution for our servers. Meaning, there will be no other discs to put things on. According to the test results that were given to me, "it will be a non-factor". Whether it is or isn't, is beyond my control now. So I have to find other ways to deal with this.

As for how often it is used? It is called once at the beginning of every stored procedure.

I tried removing all keys, indexes, etc from the table. The deadlocks actually increased. However, once I replaced the ROW and PAGE locking and added the Statistics Rebuild to the weekly backup processes (on 9-24), we haven't had a single deadlock on that table (hope I haven't jinxed it here). We're going through month end, and have some high activity runs this week, so I'll keep you posted.

--------------------------------------------------
“Crash programs fail because they are based on the theory that, with nine women pregnant, you can get a baby a month.” --Wernher von Braun
--------------------------------------------------

 

[gmmastros]

Unfortunately, a VM Ware solution may actually make things worse. If you have multiple servers on the same server, sharing the same disks, there will likely be more contention for the disks, not less. By auditing every stored procedure the way that you are, you are essentially causing a boat load of writes to the disk making the thing work pretty hard.

I've never worked with VMWare, but I do have a little experience with Hyper-V. I know that you can allocate separate drives just for a single server, and then you can put whatever you want on those drives. Drives are cheap. Having a separate drive for the log file and another for the Audit table would likely make a huge difference in performance, and therefore locks.

It seems like this decision is out of your hands (at least for now). Please remember this advice if the time comes where you are having deadlock issues again. Adding extra drives is a relatively cheap solution compared to VMWare licenses.

-George
Microsoft SQL Server MVP
My Blogs
SQLCop
twitter
"The great things about standards is that there are so many to choose from." - Fortune Cookie Wisdom

 

[ousoonerjoe]

Agreed, George. I wish there was more I could do, but it does seem that I am at my limits there.

I'm open to a better way of auditing actions. These entries have been a major source of CYA over the last couple of years to the point it is not going away now. It could be replaced, but not dropped. Ideally, what I would like is something at the database level that logged all stored procedures and the parameters with values passed to it.

--------------------------------------------------
“Crash programs fail because they are based on the theory that, with nine women pregnant, you can get a baby a month.” --Wernher von Braun
--------------------------------------------------