November 29, 2019 at 5:27 pm
Background:
I have a simple audit log table with over 26 million rows that grows at a rate of 365,000 records a week. Records are only inserted and selected - never updated or deleted. It has a cluster PK that is an int identity insert column and a few single column indexes - the full schema for the table is below. I have one stored procedure where all INSERTs to the table are execute from and then multiple stored procedures that SELECT records from the table, all with (nolock) hits. We then have many different in-house written C# .NET applications from websites to APIs to system services that all call the single insert stored procedure via an in-house created data access library style DLL (simple C# wrapper functions to unify connection strings and error reporting back to application code). Code for this insert stored procedure is also included below.
Issue:
We get deadlocks during peek usage times through the day. How is this possible in an insert only table with only one access point? I feel I am missing something obvious!
Following is a list of what I have tried to date to fix:
I have attached the deadlock xml trace record as well.
<deadlock>
<victim-list>
<victimProcess id="process23e7cea6ca8"/>
<victimProcess id="process23e8b067468"/>
</victim-list>
<process-list>
<process id="process23e7cea6ca8" taskpriority="0" logused="0" waitresource="OBJECT: 10:108066963:0 " waittime="5566" ownerId="817135339" transactionname="INSERT" lasttranstarted="2019-11-20T09:10:05.043" XDES="0x23c525dca48" lockMode="X" schedulerid="10" kpid="4608" status="suspended" spid="275" sbid="0" ecid="0" priority="0" trancount="2" lastbatchstarted="2019-11-20T09:10:05.057" lastbatchcompleted="2019-11-20T09:10:05.047" lastattention="1900-01-01T00:00:00.047" clientapp=".Net SqlClient Data Provider" hostname="RD0003FF97353C" hostpid="17292" loginname="starlord" isolationlevel="read committed (2)" xactid="817135339" currentdb="10" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
<executionStack>
<frame procname="RHINReferrals.dbo.uspAddAuditLogByID" line="38" stmtstart="1934" stmtend="2704" sqlhandle="0x03000a000de9803eb10093000bab000001000000000000000000000000000000000000000000000000000000"> INSERT INTO tblAuditLog ( LogDetails, CallingSource, LogEventID, EventDateTime, RHINUserID, OrganizationID, TableName, TableRecordID, AppName, HostName, UserName ) VALUES ( @LogDetails, @CallingSource, @LogEventID, GetDate(), @RHINUserID, @OrganizationID, @TableName, @TableRecordID, @AppName, @HostName, @UserName </frame>
</executionStack>
<inputbuf> Proc [Database Id = 10 Object Id = 1048635661] </inputbuf>
</process>
<process id="process23e8b067468" taskpriority="0" logused="0" waitresource="OBJECT: 10:108066963:0 " waittime="7782" ownerId="817134361" transactionname="INSERT" lasttranstarted="2019-11-20T09:10:02.823" XDES="0x23c7520e408" lockMode="X" schedulerid="10" kpid="11392" status="suspended" spid="259" sbid="0" ecid="0" priority="0" trancount="2" lastbatchstarted="2019-11-20T09:10:02.827" lastbatchcompleted="2019-11-20T09:10:02.840" lastattention="1900-01-01T00:00:00.840" clientapp=".Net SqlClient Data Provider" hostname="RD0003FF97353C" hostpid="17292" loginname="starlord" isolationlevel="read committed (2)" xactid="817134361" currentdb="10" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
<executionStack>
<frame procname="RHINReferrals.dbo.uspAddAuditLogByID" line="38" stmtstart="1934" stmtend="2704" sqlhandle="0x03000a000de9803eb10093000bab000001000000000000000000000000000000000000000000000000000000"> INSERT INTO tblAuditLog ( LogDetails, CallingSource, LogEventID, EventDateTime, RHINUserID, OrganizationID, TableName, TableRecordID, AppName, HostName, UserName ) VALUES ( @LogDetails, @CallingSource, @LogEventID, GetDate(), @RHINUserID, @OrganizationID, @TableName, @TableRecordID, @AppName, @HostName, @UserName </frame>
</executionStack>
<inputbuf> Proc [Database Id = 10 Object Id = 1048635661]
</inputbuf>
</process>
<process id="process23ab3c73848" taskpriority="0" logused="0" waitresource="OBJECT: 10:108066963:0 " waittime="9715" ownerId="817131594" transactionname="INSERT" lasttranstarted="2019-11-20T09:10:00.747" XDES="0x23d11b9e408" lockMode="X" schedulerid="11" kpid="11684" status="suspended" spid="261" sbid="0" ecid="0" priority="0" trancount="2" lastbatchstarted="2019-11-20T09:10:00.737" lastbatchcompleted="2019-11-20T09:10:00.747" lastattention="1900-01-01T00:00:00.747" clientapp=".Net SqlClient Data Provider" hostname="RD0003FF97353C" hostpid="17292" loginname="starlord" isolationlevel="read committed (2)" xactid="817131594" currentdb="10" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
<executionStack>
<frame procname="RHINReferrals.dbo.uspAddAuditLogByID" line="38" stmtstart="1934" stmtend="2704" sqlhandle="0x03000a000de9803eb10093000bab000001000000000000000000000000000000000000000000000000000000"> INSERT INTO tblAuditLog ( LogDetails, CallingSource, LogEventID, EventDateTime, RHINUserID, OrganizationID, TableName, TableRecordID, AppName, HostName, UserName ) VALUES ( @LogDetails, @CallingSource, @LogEventID, GetDate(), @RHINUserID, @OrganizationID, @TableName, @TableRecordID, @AppName, @HostName, @UserName </frame>
</executionStack>
<inputbuf> Proc [Database Id = 10 Object Id = 1048635661]
</inputbuf>
</process>
<process id="process23e77a008c8" taskpriority="0" logused="0" waitresource="OBJECT: 10:108066963:9 " waittime="311" ownerId="817128749" transactionname="INSERT" lasttranstarted="2019-11-20T09:09:58.273" XDES="0x23cefdec408" lockMode="X" \
="3" kpid="1036" status="suspended" spid="260" sbid="0" ecid="0" priority="0" trancount="2" lastbatchstarted="2019-11-20T09:09:58.283" lastbatchcompleted="2019-11-20T09:09:58.277" lastattention="1900-01-01T00:00:00.277" clientapp=".Net SqlClient Data Provider" hostname="RD0003FF97353C" hostpid="17292" loginname="starlord" isolationlevel="read committed (2)" xactid="817128749" currentdb="10" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
<executionStack>
<frame procname="RHINReferrals.dbo.uspAddAuditLogByID" line="38" stmtstart="1934" stmtend="2704" sqlhandle="0x03000a000de9803eb10093000bab000001000000000000000000000000000000000000000000000000000000"> INSERT INTO tblAuditLog ( LogDetails, CallingSource, LogEventID, EventDateTime, RHINUserID, OrganizationID, TableName, TableRecordID, AppName, HostName, UserName ) VALUES ( @LogDetails, @CallingSource, @LogEventID, GetDate(), @RHINUserID, @OrganizationID, @TableName, @TableRecordID, @AppName, @HostName, @UserName </frame>
</executionStack>
<inputbuf> Proc [Database Id = 10 Object Id = 1048635661] </inputbuf>
</process>
</process-list>
<resource-list>
<objectlock lockPartition="0" objid="108066963" subresource="FULL" dbid="10" objectname="RHINReferrals.dbo.tblAuditLog" id="lock23a819cd880" mode="X" associatedObjectId="108066963">
<owner-list>
<owner id="process23ab3c73848" mode="X" requestType="wait"/>
</owner-list>
<waiter-list>
<waiter id="process23e7cea6ca8" mode="X" requestType="wait"/>
</waiter-list>
</objectlock>
<objectlock lockPartition="0" objid="108066963" subresource="FULL" dbid="10" objectname="RHINReferrals.dbo.tblAuditLog" id="lock23a819cd880" mode="X" associatedObjectId="108066963"><owner-list>
<owner id="process23ab3c73848" mode="X" requestType="wait"/>
</owner-list>
<waiter-list>
<waiter id="process23e8b067468" mode="X" requestType="wait"/>
</waiter-list>
</objectlock>
<objectlock lockPartition="0" objid="108066963" subresource="FULL" dbid="10" objectname="RHINReferrals.dbo.tblAuditLog" id="lock23a819cd880" mode="X" associatedObjectId="108066963">
<owner-list>
<owner id="process23e77a008c8" mode="X"/>
</owner-list>
<waiter-list>
<waiter id="process23ab3c73848" mode="X" requestType="wait"/>
</waiter-list>
</objectlock>
<objectlock lockPartition="9" objid="108066963" subresource="FULL" dbid="10" objectname="RHINReferrals.dbo.tblAuditLog" id="lock23bf9ef5c00" mode="IX" associatedObjectId="108066963">
<owner-list>
<owner id="process23e8b067468" mode="IX"/>
</owner-list>
<waiter-list>
<waiter id="process23e77a008c8" mode="X" requestType="wait"/>
</waiter-list>
</objectlock>
</resource-list>
</deadlock>
/**********************************************************************************************************
Purpose:Adds an Audit log record
History:
20191119 Zach Finn:created
20191120 Zach Finn:added detailed logging
**********************************************************************************************************/
ALTER PROCEDURE [dbo].[uspAddAuditLogByID]
(
@LogEventID int,
@LogDetails varchar(1000),
@CallingSource varchar(100),
@AppName varchar(100),
@TableName varchar(255) = 'Referrals',
@TableRecordID int,
@HostName varchar(100) = NULL,
@UserName varchar(100) = NULL,
@RHINUserID int = NULL,
@OrganizationID int = NULL,
@ErrorMsg varchar(2000) = NULL OUTPUT
)
AS
DECLARE
@ReturnCodeint = 0,
@SPName varchar(50) = 'uspAddAuditLogByID';
SET NOCOUNT ON
IF @RHINUserID = 0
BEGIN
SET @RHINUserID = NULL
END
IF @OrganizationID = 0
BEGIN
SET @OrganizationID = NULL
END
BEGIN TRY
INSERT INTO tblAuditLog (
LogDetails,
CallingSource,
LogEventID,
EventDateTime,
RHINUserID,
OrganizationID,
TableName,
TableRecordID,
AppName,
HostName,
UserName
) VALUES (
@LogDetails,
@CallingSource,
@LogEventID,
GetDate(),
@RHINUserID,
@OrganizationID,
@TableName,
@TableRecordID,
@AppName,
@HostName,
@UserName
)
SET @ReturnCode = @@Error
END TRY
BEGIN CATCH
SET @ReturnCode = ERROR_NUMBER()
SET @ErrorMsg = @SPName + ': ' + Cast(@ReturnCode AS varchar(10)) + ': ' + ERROR_MESSAGE() + ': exec uspAddAuditLogByID @LogEventID=' + Cast(@LogEventID AS varchar(20)) + ' ,@LogDetails=''' + Isnull(@LogDetails, '') + ''' ,@CallingSource=''' + Isnull(@CallingSource, '') + ''' ,@AppName=''' + Isnull(@AppName, '') + ''' ,@TableName=' + Isnull(@TableName, '') + ' ,@TableRecordID=' + Cast(@TableRecordID AS varchar(20)) + ' ,@HostName=''' + Isnull(@HostName, '') + ''' ,@UserName=''' + Isnull(@UserName, '') + ''' ,@RHINUserID=' + Cast(ISNULL(@RHINUserID,'') AS varchar(20)) + ' ,@OrganizationID=' + Cast(Isnull(@OrganizationID, '') AS varchar(20))
END CATCH;
IF Len(@ErrorMsg) > 0
EXEC uspAddEventLog
@LogDetails = @ErrorMsg,
@CallingSource = @CallingSource,
@LogEvent = 'Database Error'
RETURN @ReturnCode
CREATE TABLE [dbo].[tblAuditLog](
[AuditLogID] [int] IDENTITY(1,1) NOT NULL,
[LogDetails] [varchar](1000) NULL,
[CallingSource] [varchar](100) NULL,
[LogEventID] [int] NOT NULL,
[EventDateTime] [smalldatetime] NOT NULL,
[RHINUserID] [int] NULL,
[SessionToken] [varchar](255) NULL,
[TableName] [varchar](255) NULL,
[TableRecordID] [int] NULL,
[AppName] [varchar](100) NOT NULL,
[HostName] [varchar](100) NULL,
[UserName] [varchar](100) NULL,
[DBHostID] [varchar](50) NULL,
[DBHostName] [varchar](100) NULL,
[DBUserName] [varchar](100) NULL,
[DBSystemUser] [varchar](100) NOT NULL,
[OrganizationID] [int] NULL,
CONSTRAINT [PK_AuditLog_AuditLogID2019] PRIMARY KEY CLUSTERED
(
[AuditLogID] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = OFF, ALLOW_PAGE_LOCKS = OFF, FILLFACTOR = 95) ON [PRIMARY]
) ON [PRIMARY]
GO
ALTER TABLE [dbo].[tblAuditLog] ADD CONSTRAINT [DF_AuditLog_DateTime2019] DEFAULT (getdate()) FOR [EventDateTime]
GO
ALTER TABLE [dbo].[tblAuditLog] ADD CONSTRAINT [DF_AuditLog_SystemUser2019] DEFAULT (suser_sname()) FOR [DBSystemUser]
GO
CREATE NONCLUSTERED INDEX [IX_AuditLog_LogEventIDID2019] ON [dbo].[tblAuditLog]
(
[LogEventID] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, SORT_IN_TEMPDB = OFF, DROP_EXISTING = OFF, ONLINE = OFF, ALLOW_ROW_LOCKS = OFF, ALLOW_PAGE_LOCKS = OFF, FILLFACTOR = 90) ON [PRIMARY]
GO
CREATE NONCLUSTERED INDEX [IX_AuditLog_RHINUserID2019] ON [dbo].[tblAuditLog]
(
[RHINUserID] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, SORT_IN_TEMPDB = OFF, DROP_EXISTING = OFF, ONLINE = OFF, ALLOW_ROW_LOCKS = OFF, ALLOW_PAGE_LOCKS = OFF, FILLFACTOR = 80) ON [PRIMARY]
GO
CREATE NONCLUSTERED INDEX [IX_AuditLog_TableRecordID2019] ON [dbo].[tblAuditLog]
(
[TableRecordID] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, SORT_IN_TEMPDB = OFF, DROP_EXISTING = OFF, ONLINE = OFF, ALLOW_ROW_LOCKS = OFF, ALLOW_PAGE_LOCKS = OFF, FILLFACTOR = 80) ON [PRIMARY]
GO
ALTER TABLE [dbo].[tblAuditLog] ADD CONSTRAINT [PK_AuditLog_AuditLogID2019] PRIMARY KEY CLUSTERED
(
[AuditLogID] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, SORT_IN_TEMPDB = OFF, IGNORE_DUP_KEY = OFF, ONLINE = OFF, ALLOW_ROW_LOCKS = OFF, ALLOW_PAGE_LOCKS = OFF, FILLFACTOR = 95) ON [PRIMARY]
GO
ALTER TABLE [dbo].[tblAuditLog] ADD CONSTRAINT [DF_AuditLog_DateTime2019] DEFAULT (getdate()) FOR [EventDateTime]
GO
ALTER TABLE [dbo].[tblAuditLog] ADD CONSTRAINT [DF_AuditLog_SystemUser2019] DEFAULT (suser_sname()) FOR [DBSystemUser]
GO
November 29, 2019 at 7:33 pm
Several things that would/should help. You can implement / not implement each one as you see fit:
Use nonclustered indexes on any Id columns you need to look up by, because those are by definition single-value lookups.
2. Encode these columns:
[CallingSource], [TableName], [AppName], [HostName], [UserName], [DBHostID], [DBHostName], [DBUserName], [DBSystemUser]
That is, use an id rather than a string to represent their values. That will greatly reduce row size. A single conversion table could be used for all these string columns.
3. Set "DATA_COMPRESSION = PAGE" to reduce I/O.
4. [General thoughts]
I can't see off the top of my head how deadlocks are resulting from SELECTs with NOLOCK specified, so it must be the INSERTs, most likely related to nonclus indexes. Make sure all nonclus indexes are explicitly specified as UNIQUE by adding the $IDENTITY column to the end of the index keys.
SQL DBA,SQL Server MVP(07, 08, 09) A socialist is someone who will give you the shirt off *someone else's* back.
Viewing 2 posts - 1 through 1 (of 1 total)
You must be logged in to reply to this topic. Login to reply