Vault Pro 5.1 SQL deadlocks

[jdpalmer]

We are experiencing SQL deadlocks with Vault Pro v5.1. The deadlocks seem to occur most often when retrieving history on a folder. I can't cause the error on demand, but they occur a couple of times per day; sometimes several times a day. I don't see the deadlocks in the sgvault.log on the server, either.

(I have a separate post regarding System.OutOfMemoryException exceptions, but they don't occur at the same time as the OutOfMemoryException errors.)

I've traced the last several deadlocks to the stored procedure spqueryhistory:

Code: Select all

Deadlocked processes:	
  Victim process:	99
  Object blocked:	Index/(Key) 2

SPID:           99
Lock details:   dbid: 2, object id: 2, index id: 1
Statement type: INSERT Line #: 49	

SQL query fragment:
  RPC Event: dbo.spqueryhistory;1

Client Information
Vault Professional Client Version: 5.1.1.19216
.NET Framework Version: 2.0.50727.5444
Operating System: Microsoft Windows 7 Professional
Service Pack: 1.0
OS Version: 6.1.7601
Total Physical Memory: 7.99 GB
Time Zone: (UTC-06:00) Central Time (US & Canada)

Server Information
Server Version: 5.1.1.19216
.NET Framework Version: 2.0.50727.3620
Operating System: Microsoft(R) Windows(R) Server 2003, Standard Edition
Service Pack: 2.0
OS Version: 5.2.3790
Timezone: (GMT-06:00) Central Time (US & Canada)
SQL Version: Microsoft SQL Server 2000 - 8.00.2055 (Intel X86)

License Information
3 serial number(s):
1 of 3: 2 web-only users, permanent
2 of 3: 13 full users, permanent
3 of 3: 1 full users, permanent

Please advise.

[Beth]

One thing that should help both issues you've posted is to check your SQL maintenance plan. We have suggested maintenance posted here: http://support.sourcegear.com/viewtopic.php?t=2924.

What might help track this down is to have the Vault server log in Debug mode and then when the deadlock happens, try to line it up with which user is running a history query. The Debug mode is set in the Vault admin web page under the logging link. After you change it from Quiet to Debug, you might want to also change the Archiving to Daily to keep the log small. When you click Save, the application pool will recycle causing users to be kicked out of Vault, so you may need to give them some forewarning.

[jdpalmer]

Thanks for the suggestions. I'll enable debug-level logging and see what was happening during the next deadlock.

We already have a script that rebuilds all indexes every Sunday, and I just ran DBCC CHECKDB and found no errors:

Code: Select all

CHECKDB found 0 allocation errors and 0 consistency errors in database 'sgdragnet'.

CHECKDB found 0 allocation errors and 0 consistency errors in database 'sgmaster'.

CHECKDB found 0 allocation errors and 0 consistency errors in database 'sgvault'.

[Beth]

You will probably want to add the defrag and update statistics that are mentioned in the article I linked to as well.

Once you have some logging from during a deadlock, just let me know. You can post it here and remove it later, or send an it to support at sourcegear.com (attn: Beth) with a link to this forum thread.

[jdpalmer]

Very interesting -- the deadlocks don't register as an error in the Vault server log! I enabled tracing on our SQL Server, and I can create the deadlock by simply pulling up history in the Vault client on a few folders. (It doesn't always do it.) It does not show any error in the Vault client. I had assumed that other users were the ones seeing the error, because I get notified whenever there's a SQL deadlock (in any database).

Also interesting: only one SQL SPID appears to be involved. I'm used to seeing two SPIDs involved in a deadlock. It takes two to tango.

Deadlocked processes
SPID: 89
Victim: Victim process
Lock details: dbid: 2, object id: 2, index id: 1
Statement type: UPDATE Line #: 44
SQL query fragment: RPC Event: dbo.spqueryhistory;1

FYI, dbid 2 is tempdb.

SQL trace:

Code: Select all

11 May 2011 16:12:10  exec sp_reset_connection
11 May 2011 16:12:10  exec dbo.spgetuserrepositorylastchange @repid = 2
11 May 2011 16:12:10  SET TRANSACTION ISOLATION LEVEL READ COMMITTED;BEGIN TRANSACTION
11 May 2011 16:12:10  exec dbo.splockcheckoutlist @repid = 2, @locktype = 1
11 May 2011 16:12:10  exec dbo.spgetcurrentcheckoutinfo @repid = 2, @userid = 3
11 May 2011 16:12:10  COMMIT TRANSACTION
11 May 2011 16:12:11  exec sp_reset_connection
11 May 2011 16:12:11  exec dbo.spgetuserrepositorylastchange @repid = 2
11 May 2011 16:12:11  exec dbo.spgetlatestrepositoryinfo @repid = 2
11 May 2011 16:12:11  exec dbo.spgetusersecurityrights @repid = 2, @userid = 3, @txid = -1
11 May 2011 16:12:11  exec dbo.spqueryhistory @userid = 3, @repid = 2, @txid = 11038, @objid = 49662, @objprops = 1, @fullpath = N'$/1.DEV/SW/CustomerService', @recursive = 1, @separator = N'/', @splitchar = N',', @sortlist = N'2147418115', @rowlimit = 1000, @showlabels = 1

sgvault.log from that time:

Code: Select all

----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	ASMX: GetRepositoryStructure started. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	Getting repository Structure-> Rep ID: 2 Base: 11038 Target: -1 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: GetUserRepositoryLastChange started. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: GetUserRepositoryLastChange finished. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: GetLatestRepositoryInfo started. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: GetLatestRepositoryInfo finished. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	TreeManager: cache matches repository revision and folder security hasn't changed.  Returning cached tree, revID 11038 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: GetLastTreeSecurityChange started. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: GetLastTreeSecurityChange finished. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: GetUserSecurityRights started. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: GetUserSecurityRights finished. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	VaultServiceAPI::GetRepositoryTreeDelta() UserID:3 RepID:2 Base:11038 Target:11038  Calling VaultRepUtil.DiffRepTrees() - in-memory tree diff. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	ASMX: GetRepositoryStructure finished. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	GetRepositoryStructure returned: Success 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	Getting list of checkout changes. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	ASMX: GetCheckOutListChanges started. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: GetUserRepositoryLastChange started. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: GetUserRepositoryLastChange finished. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	Beginning SQL transaction 49788650 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	GetCheckoutListChanges: Transaction Started 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: LockCheckoutList started. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: CreateDBLockObject started. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: CreateDBLockObject finished. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: LockCheckoutList finished. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: GetCurrentCheckoutInfo started. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: GetCurrentCheckoutInfo finished. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	SQL transaction 49788650 successfully committed. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	GetCheckoutListChanges: Transaction Committed 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	GetCheckOutListChanges returned: Success 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	ASMX: GetCheckOutListChanges finished. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	ASMX: BeginHistoryQuery started. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: GetUserRepositoryLastChange started. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: GetUserRepositoryLastChange finished. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: GetLatestRepositoryInfo started. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: GetLatestRepositoryInfo finished. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	TreeManager: cache matches repository revision and folder security hasn't changed.  Returning cached tree, revID 11038 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: GetUserSecurityRights started. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: GetUserSecurityRights finished. 
----5/11/2011 4:12:10 PM     jpalmer--192.168.17.66--SSL Disabled	DB: QueryHistory started. 
----5/11/2011 4:12:16 PM     jpalmer--192.168.17.66--SSL Disabled	DB: QueryHistory finished.
----5/11/2011 4:12:16 PM     jpalmer--192.168.17.66--SSL Disabled	BeginHistoryQuery returned: Success 
----5/11/2011 4:12:16 PM     jpalmer--192.168.17.66--SSL Disabled	ASMX: BeginHistoryQuery finished. 
----5/11/2011 4:12:16 PM     jpalmer--192.168.17.66--SSL Disabled	ASMX: GetHistoryQueryItems started. 
----5/11/2011 4:12:16 PM     jpalmer--192.168.17.66--SSL Disabled	GetHistoryQueryItems returned: Success 
----5/11/2011 4:12:16 PM     jpalmer--192.168.17.66--SSL Disabled	ASMX: GetHistoryQueryItems finished. 

[Beth]

Usually unresolved deadlocks do get reported back to Vault and post in the server log.

The only indicator of the deadlock is through whatever you have capturing those deadlocks, right?

Do the users see any difference in Vault? Do they get disconnected or receive errors?

[jdpalmer]

That is correct: apparently the only trace of the deadlocks is from SQL Server itself; the Vault server log does not show them and the Vault clients are neither disconnected nor see any error.

[Beth]

We will look into this and see if we can determine what is causing the deadlocks.

Thank you for reporting this.