March 26, 2014 at 7:42 am
Hi All,
We are having a problem with deadlocks created by vendor software; these deadlocks are writing to the error log frequently and not giving us any new information, so we'd like to disable them from being logged. The server is an in-house quasi-production server, so serious damage would be done if errors were not logged for a while.
Each "entry" takes up about 30 lines, and we have hundreds of "entries".
Any help is much appreciated.
~ Jeff
March 26, 2014 at 8:01 am
Looks like you've got 1204 and/or 1222 trace flags turned ON.
By default, SQL server won't log deadlock details in the SQL Server Error log. SQL Server basically sends "Msg 1205, Level 13, State 51, Line 3
Transaction (Process ID xx) was deadlocked on {xxx} resources with another process and has been chosen as the deadlock victim. Rerun the transaction." message to the client...
So, disabling those trace flags should stop logging these dead lock related details in the Error log.
BTW, the best thing to do here is to fix the root cause which is causing the deadlocks in the first place 🙂
March 26, 2014 at 8:04 am
Can you post an example?
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
March 26, 2014 at 8:21 am
Here's one (Kaspersky AntiVirus):
deadlock-list
deadlock victim=process5c1ddc8
process-list
process id=process5c1ddc8 taskpriority=0 logused=304 waitresource=KEY: 25:72057608316911616 (e41265cf7a76) waittime=914 ownerId=42667222210 transactionname=user_transaction lasttranstarted=2014-03-26T09:22:54.950 XDES=0x8c4675970 lockMode=X schedulerid=7 kpid=6228 status=suspended spid=364 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2014-03-26T09:22:54.950 lastbatchcompleted=2014-03-26T09:22:54.950 clientapp=Kaspersky Security Center hostname=KES-ADMIN hostpid=1472 loginname=MEDITECH\AAAdpappalardo isolationlevel=read committed (2) xactid=42667222210 currentdb=25 lockTimeout=4294967295 clientoption1=673316896 clientoption2=128056
executionStack
frame procname=KAV.dbo.sp_te_event_succeeded line=14 stmtstart=864 stmtend=984 sqlhandle=0x030019005764082e3cd5b80015a200000100000000000000
DELETE FROM TransEventsDetails WHERE nQueueId = @lQueueId;
inputbuf
Proc [Database Id = 25 Object Id = 772301911]
process id=processd3a2508 taskpriority=0 logused=3004688 waitresource=KEY: 25:72057608317566976 (e41265cf7a76) waittime=623 ownerId=42667222035 transactionname=DELETE lasttranstarted=2014-03-26T09:22:54.863 XDES=0x177519f970 lockMode=U schedulerid=2 kpid=12540 status=suspended spid=646 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2014-03-26T09:22:54.410 lastbatchcompleted=2014-03-26T09:22:43.417 clientapp=Kaspersky Security Center hostname=KES-ADMIN hostpid=1472 loginname=MEDITECH\AAAdpappalardo isolationlevel=read committed (2) xactid=42667222035 currentdb=25 lockTimeout=4294967295 clientoption1=673316896 clientoption2=128056
executionStack
frame procname=adhoc line=1 stmtstart=410 sqlhandle=0x020000001f3e2a1b3c14adb13e725c7fb6fb13c48324537d
DELETE TransEventsQueue FROM TransEventsQueue WHERE TransEventsQueue.processed = 1 AND record_time < @dtLimitRecordTime
frame procname=KAV.dbo.sp_ev_clean_old_events line=31 stmtstart=1580 stmtend=2320 sqlhandle=0x0300190073d3372a12d5b80015a200000100000000000000
EXEC ('DECLARE @dtLimitRecordTime DATETIME; SELECT @dtLimitRecordTime = MAX(record_time) FROM (SELECT TOP ' + @nTransEventsQueueCountToDelete + ' record_time FROM TransEventsQueue WHERE TransEventsQueue.processed = 1 ORDER BY record_time ASC) t1; DELETE TransEventsQueue FROM TransEventsQueue WHERE TransEventsQueue.processed = 1 AND record_time < @dtLimitRecordTime ')
frame procname=unknown line=1 sqlhandle=0x000000000000000000000000000000000000000000000000
unknown
inputbuf
Proc [Database Id = 25 Object Id = 708301683]
resource-list
keylock hobtid=72057608316911616 dbid=25 objectname=KAV.dbo.TransEventsDetails indexname=UX_TransEventsDetails__nQueueId id=lockc833200 mode=U associatedObjectId=72057608316911616
owner-list
owner id=processd3a2508 mode=S
waiter-list
waiter id=process5c1ddc8 mode=X requestType=convert
keylock hobtid=72057608317566976 dbid=25 objectname=KAV.dbo.TransEventsQueue indexname=PK__TransEve__DF98CDDD2839B111 id=lock1635c7a700 mode=X associatedObjectId=72057608317566976
owner-list
owner id=process5c1ddc8 mode=X
waiter-list
waiter id=processd3a2508 mode=U requestType=wait
BTW, I'm looking into creating index(es) on TransEventsQueue.processed (type is BIT) and/or record_time (type is DATETIME); I'm hoping that reducing execution time may help prevent blocks.
The source code for the procedure:
CREATE PROCEDURE sp_te_event_succeeded
@event_id UT_EVP_EVENT_ID,
@lQueueId BIGINT,
@record_time DATETIME,
@record_time_ms INT
AS SET NOCOUNT ON
SET @record_time = DATEADD(millisecond, @record_time_ms, @record_time);
BEGIN TRAN
IF( @lQueueId > 0 AND EXISTS( SELECT * FROM TransEventsQueue WHERE nId = @lQueueId ) )
BEGIN
UPDATE TransEventsQueue SET attempt_count = 1, processed = 1 WHERE nId = @lQueueId;
DELETE FROM TransEventsDetails WHERE nQueueId = @lQueueId;
END
ELSE
BEGIN
SET @lQueueId = NULL;
SELECT @lQueueId = TransEventsQueue.nId FROM TransEventsQueue WHERE TransEventsQueue.event_id = @event_id;
IF( @lQueueId IS NULL )
BEGIN
INSERT INTO TransEventsQueue(event_id, record_time, attempt_count, processed)
VALUES( @event_id, @record_time, 1, 1)
END
ELSE
BEGIN
UPDATE TransEventsQueue SET attempt_count = 1, processed = 1 WHERE nId = @lQueueId;
DELETE FROM TransEventsDetails WHERE nQueueId = @lQueueId;
END
END
COMMIT TRAN
~ Jeff
March 26, 2014 at 8:27 am
You've got traceflag 1222 turned on.
You can turn it off with DBCC TRACEOFF, but depending on how it was enabled it may come back.
Can you post the first 15 lines of your latest error log? (the earliest entries from when SQL was starting up)
Edit:
You probably want indexes on TransEventsQueue on the nld column, on TransEventsQueue on Processed and record_time (in that order, both as key columns) and on TransEventsDetails on nQueueID
Can't tell for sure from just what you posted, there may be existing indexes which you can expand instead.
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
March 26, 2014 at 8:32 am
The error log has been reinitialized. See the previous log for older entries.
Logging SQL Server messages in file 'H:\MSSQL10_50.MSSQLSERVER\MSSQL\Log\ERRORLOG'.
Authentication mode is MIXED.
System Manufacturer: 'HP', System Model: 'ProLiant DL385 G5p'.
Server process ID is 4580.
All rights reserved.
(c) Microsoft Corporation.
Microsoft SQL Server 2008 R2 (SP2) - 10.50.4276.0 (X64)
Feb 8 2013 10:37:00
Copyright (c) Microsoft Corporation
Enterprise Edition (64-bit) on Windows NT 6.0 <X64> (Build 6002: Service Pack 2)
<10 of these>
DBCC TRACEON 3604, server process ID (SPID) 336. This is an informational message only; no user action is required.
waiter id=process5c13708 mode=U requestType=wait <etc.>
March 26, 2014 at 8:35 am
Current indexes:
PK__TransEve__DF98CDDD2839B111UNIQUE CLUSTERED [nId] NULL
Seeks = 351616926Scans = 109342Lookups = 5
UX_TransEventsQueue__event_id UNIQUE NONCLUSTERED [event_id]NULL
Seeks = 101744259Scans = 0 Lookups = 0
March 26, 2014 at 8:35 am
Go back until you find an error log that has the startup details in it, that one is a re-initialised log.
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 8 posts - 1 through 7 (of 7 total)
You must be logged in to reply to this topic. Login to reply