improving performance of spQueryHistory

If you are having a problem using Vault, post a message here.

Moderator: SourceGear

Post Reply
nmcalpin
Posts: 38
Joined: Mon Nov 01, 2004 10:06 am

improving performance of spQueryHistory

Post by nmcalpin » Fri Feb 20, 2009 1:57 pm

Doing a history on a particular branch in our vault DB is taking about six minutes (it actually results in a vault error of "A database error has occurred (FailDbFault)") but reviewing the logs shows it to merely be a timeout, and a sql profiler run reveals the real issue:

This SP call:

dbo.spqueryhistory @userid=2,@repid=1,@txid=49956,@objid=121555,@objprops=1,@fullpath=N'$/Dn/Nbt/Nbt',@recursive=1,@separator=N'/',@splitchar=N',',@sortlist=N'2147418115',@rowlimit=1000,@showlabels=1

Is taking about six minutes to run.

The machine we're running on is not an optimized SQL server (see specs at bottom of this post); but it's not bad either. Any hints/ideas for additional indexing or ways to fix this issue?

thanks!

the machine itself has two dual-core processors (opteron 2212's) for a total of four cores; 4gb of RAM, and the entire sgvault DB is on a 3-disc raid 5 array (10,000rpm SAS drives) on a hardware controller with 256mb of cache; windows server 2003, sql server 2005. The SgVault DB is around 9gb in size. Running vault 3.5.

I ran the above SP call in the tuning advisor software and it had no recommendations, but i don't know if that's because the SP itself is encrypted.

lbauer
Posts: 9736
Joined: Tue Dec 16, 2003 1:25 pm
Location: SourceGear

Re: improving performance of spQueryHistory

Post by lbauer » Fri Feb 20, 2009 4:31 pm

You can increase the <SqlCommandTimeout>360</SqlCommandTimeout> value in the Vault.config file in the VaultService directory. Change it to 3600 or even 7200.

If the branch still fails, we'd like to see a copy of the server log. The Vault server log is sgvault.log and is in %windir%\temp\sgvault on the server machine.

Send the logs zipped up to support at sourcegear.com, Attn: Linda. Please include a link to this forum post.
Linda Bauer
SourceGear
Technical Support Manager

nmcalpin
Posts: 38
Joined: Mon Nov 01, 2004 10:06 am

Re: improving performance of spQueryHistory

Post by nmcalpin » Mon Feb 23, 2009 9:33 pm

I already understand that this is a timeout issue (see my first post); so I understand that increasing the timeout value would prevent the error.

What I'm asking is if there is anything we can do to improve the overall time it takes for this stored procedure to run? I can't analyze the SP myself to determine what additional indexing or optimization would be helpful because sourcegear has encrypted the content of the SP.

lbauer
Posts: 9736
Joined: Tue Dec 16, 2003 1:25 pm
Location: SourceGear

Re: improving performance of spQueryHistory

Post by lbauer » Mon Mar 02, 2009 10:59 am

What I'm asking is if there is anything we can do to improve the overall time it takes for this stored procedure to run?
I've consulted with our developers, and there's currently no way to improve the performance of spQueryHistory.

I've logged feature request 14027 to look into this in a future release.
Linda Bauer
SourceGear
Technical Support Manager

nmcalpin
Posts: 38
Joined: Mon Nov 01, 2004 10:06 am

Re: improving performance of spQueryHistory

Post by nmcalpin » Wed Mar 04, 2009 9:39 am

That's great for a future release, but unfortunately it doesn't help us in our current situation.

Can the developers please comment on what this SP does - I realize the source is protected, but perhaps they could at least tell us what tables/fields are involved so I can determine if I can add some indexing to our particular DB to solve this problem? I can't do anything on my own because SG encrypted this SP.

jeremy_sg
Posts: 1821
Joined: Thu Dec 18, 2003 11:39 am
Location: Sourcegear
Contact:

Re: improving performance of spQueryHistory

Post by jeremy_sg » Thu Mar 05, 2009 1:50 pm

Unfortunately, spQueryHistory is one of our largest and most complicated stored procedures. It touches almost every table. We are always looking at ways to make it faster. In fact, in the years since since 3.5, we've done several passes at speeding it up. I would suggest that upgrading may give you a speedup. It depends a lot on what your table sizes are, and what your history query is.

Another thing to try is to vary your history query. Try deselecting all actions except for Add. Does the query run really fast? What if you select all actions except for labels?
Subscribe to the Fortress/Vault blog

mry
Posts: 4
Joined: Tue Oct 06, 2009 5:43 am

Re: improving performance of spQueryHistory

Post by mry » Tue Oct 06, 2009 6:58 am

We've gotten the same problem where getting the history for a project has started to timeout. After investigating the problem, it appears there's something not quite right with how spqueryhistory is performed. We recently merged two repositories (exported from our small repository and imported into our main repository). It was after we did this that one of the projects started to time out when viewing the history (in the main repository), but getting the same history in the small repository works fine (the transaction takes 3-7 secs to perform instead of timing out after 360 secs). We haven't done any changes to the project in question, so the histories are identical. Both repositories share the same MS SQL Server (ver 09.00.3042) database. We're using Vault version 4.1.1 (18060).
Now, disabling the Branch action from the history query speeds things up considerably. I have no clue why this matters though, since we've never branched the project from anywhere. We have branched the project into a new project at one point, but that shouldn't affect the history of the original project.

The three tests were as follows
1) History gotten from small repository
2) History gotten from main repository (all actions enabled)
3) History gotten from main repository (branch action disabled, all other actions enabled)
All tests are 100% reproducible, however the times differ +/- a couple secs each try.

Here are excerpts from the sql server logs:

Code: Select all

Test  StartTime       EndTime             Duration     Reads    Writes
1)    16:19:18.310    16:19:22.557           4 sec    144794        24
2)    16:34:15.687    16:40:15.683    6 min, 0 sec   6273555        65
3)    16:52:58.133    16:53:01.977           3 sec    333185       200

1) exec dbo.spqueryhistory @userid=326,@repid=4,@txid=108170,@objid=18026,@objprops=1,@fullpath=N'$/Network configurators/7231-NetTool DeviceNet/SW/trunk',@recursive=1,@separator=N'/',@splitchar=N',',@sortlist=N'2147418115',@rowlimit=1000,@showlabels=1
2) exec dbo.spqueryhistory @userid=326,@repid=3,@txid=110868,@objid=131988,@objprops=1,@fullpath=N'$/PC Applications/Network configurators/7231-NetTool DeviceNet/SW/trunk',@recursive=1,@separator=N'/',@splitchar=N',',@sortlist=N'2147418115',@rowlimit=1000,@showlabels=1
3) exec dbo.spqueryhistory @userid=326,@repid=3,@txid=110868,@objid=131988,@objprops=1,@fullpath=N'$/PC Applications/Network configurators/7231-NetTool DeviceNet/SW/trunk',@recursive=1,@separator=N'/',@splitchar=N',',@itemtypelist=N'70,10,70,10,60,80,120,130,140,150,220,150,220,210,170,180,190,160,230,90,200,202,201',@sortlist=N'2147418115',@rowlimit=1000,@showlabels=1
There's a huge number of reads going on when it times out, so it looks like it for some reason queries larger parts of the database than necessary when branch action is enabled.

lbauer
Posts: 9736
Joined: Tue Dec 16, 2003 1:25 pm
Location: SourceGear

Re: improving performance of spQueryHistory

Post by lbauer » Tue Oct 06, 2009 1:44 pm

I did a Show History with and without the Branch checked, and I had a large branch in my repository. It made no difference. Perhaps the import history is causing this.

We'd like to see a copy of a debug Vault Server log when you run the history with and without Branch checked. The Vault Server log is called sgvault.log and is in %windir%\temp\sgvault on the server machine. You can enable debug server logging in the Admin Web Client under Server Settings->Logging->Log Level. Let me know what time in the log you did the queries.

Send the log zipped up to support at sourcegear.com, Attn: Linda. Please include a link to this forum post.
Linda Bauer
SourceGear
Technical Support Manager

lbauer
Posts: 9736
Joined: Tue Dec 16, 2003 1:25 pm
Location: SourceGear

Re: improving performance of spQueryHistory

Post by lbauer » Tue Oct 06, 2009 4:26 pm

We'd also suggest running SQL Server maintenance on the sgvault database, particulary rebuilding and defragging the indices:

http://support.sourcegear.com/viewtopic.php?t=2924

Let us know if that helps.
Linda Bauer
SourceGear
Technical Support Manager

mry
Posts: 4
Joined: Tue Oct 06, 2009 5:43 am

Re: improving performance of spQueryHistory

Post by mry » Wed Oct 07, 2009 5:25 am

Maintenance is done on the sql database every weekend.
The project is fairly small - it's slightly over 1000 files in it, most files having a single revision. There are some labels, but no branches, so the history is very straightforward.
It isn't a database performance issue per se - when it times out it does more or less the same number of read accesses per second that it does when it doesn't time out (see below), so the database performance isn't really suffering. The problem is that at the point of timeout, it has done over 20 times as many accesses to retrieve the exact same history.
Also, as noted in my first post, this only occurs on a few of our projects (we have a couple hundred in the main repository, even if most projects are very small). The majority doesn't show this problem (however it both happens on projects imported from the small repository and projects origin in the main repository).

DB read performance (consider that the transaction are +/- a few secs in practice giving a fairly large range for the speed)
1) 144794 reads in 4 sec = 36198 reads/s
2) 6273555 reads in 360 sec = 17426 reads/s
3) 333185 reads in 3 sec = 111061 reads/s


Here are excerpts the logs for the different tests (I've omitted all users except myself)
(I can email you more of the log if you like, but please let me know what parts of it are of interest - it's about 700mb in size for the last three weeks).

Code: Select all

Test1:
----2009-10-05 16:19:18      mry--DEV044(10.10.20.101)--SSL Disabled	ASMX: BeginHistoryQuery started. 
----2009-10-05 16:19:18      mry--DEV044(10.10.20.101)--SSL Disabled	DB: GetUserRepositoryLastChange started. 
----2009-10-05 16:19:18      mry--DEV044(10.10.20.101)--SSL Disabled	DB: GetUserRepositoryLastChange finished. 
----2009-10-05 16:19:18      mry--DEV044(10.10.20.101)--SSL Disabled	DB: GetLatestRepositoryInfo started. 
----2009-10-05 16:19:18      mry--DEV044(10.10.20.101)--SSL Disabled	DB: GetLatestRepositoryInfo finished. 
----2009-10-05 16:19:18      mry--DEV044(10.10.20.101)--SSL Disabled	TreeManager: cache matches repository revision and folder security hasn't changed.  Returning cached tree, revID 108170 
----2009-10-05 16:19:18      mry--DEV044(10.10.20.101)--SSL Disabled	DB: GetUserSecurityRights started. 
----2009-10-05 16:19:18      mry--DEV044(10.10.20.101)--SSL Disabled	DB: GetUserSecurityRights finished. 
----2009-10-05 16:19:18      mry--DEV044(10.10.20.101)--SSL Disabled	DB: QueryHistory started. 
----2009-10-05 16:19:22      mry--DEV044(10.10.20.101)--SSL Disabled	DB: QueryHistory finished. 
----2009-10-05 16:19:22      mry--DEV044(10.10.20.101)--SSL Disabled	BeginHistoryQuery returned: Success 
----2009-10-05 16:19:22      mry--DEV044(10.10.20.101)--SSL Disabled	ASMX: BeginHistoryQuery finished. 
----2009-10-05 16:19:22      mry--DEV044(10.10.20.101)--SSL Disabled	ASMX: GetHistoryQueryItems started. 
----2009-10-05 16:19:22      mry--DEV044(10.10.20.101)--SSL Disabled	GetHistoryQueryItems returned: Success 
----2009-10-05 16:19:22      mry--DEV044(10.10.20.101)--SSL Disabled	ASMX: GetHistoryQueryItems finished. 
----2009-10-05 16:19:31      mry--DEV044(10.10.20.101)--SSL Disabled	ASMX: EndHistoryQuery started. 
----2009-10-05 16:19:31      mry--DEV044(10.10.20.101)--SSL Disabled	EndHistoryQuery returned: Success 
----2009-10-05 16:19:31      mry--DEV044(10.10.20.101)--SSL Disabled	ASMX: EndHistoryQuery finished. 



Test2:
----2009-10-05 16:34:15      mry--DEV044(10.10.20.101)--SSL Disabled	ASMX: BeginHistoryQuery started. 
----2009-10-05 16:34:15      mry--DEV044(10.10.20.101)--SSL Disabled	DB: GetUserRepositoryLastChange started. 
----2009-10-05 16:34:15      mry--DEV044(10.10.20.101)--SSL Disabled	DB: GetUserRepositoryLastChange finished. 
----2009-10-05 16:34:15      mry--DEV044(10.10.20.101)--SSL Disabled	DB: GetLatestRepositoryInfo started. 
----2009-10-05 16:34:15      mry--DEV044(10.10.20.101)--SSL Disabled	DB: GetLatestRepositoryInfo finished. 
----2009-10-05 16:34:15      mry--DEV044(10.10.20.101)--SSL Disabled	TreeManager: cache matches repository revision and folder security hasn't changed.  Returning cached tree, revID 110868 
----2009-10-05 16:34:15      mry--DEV044(10.10.20.101)--SSL Disabled	DB: QueryHistory started. 
----2009-10-05 16:40:15      mry--DEV044(10.10.20.101)--SSL Disabled	System.Data.SqlClient.SqlException: Timeout expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
   at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
   at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
   at System.Data.SqlClient.SqlDataReader.ConsumeMetaData()
   at System.Data.SqlClient.SqlDataReader.get_MetaData()
   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
   at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior)
   at VaultServiceSQL.VaultSqlSCC.QueryHistory(VaultSqlConn conn, Int32 nUserID, Int32 nRowLimit, Int64 nTxID, VaultHistoryQueryRequest hqr, SqlDataReader& dr)    at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
   at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
   at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
   at System.Data.SqlClient.SqlDataReader.ConsumeMetaData()
   at System.Data.SqlClient.SqlDataReader.get_MetaData()
   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
   at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior)
   at VaultServiceSQL.VaultSqlSCC.QueryHistory(VaultSqlConn conn, Int32 nUserID, Int32 nRowLimit, Int64 nTxID, VaultHistoryQueryRequest hqr, SqlDataReader& dr)
----2009-10-05 16:40:15      mry--DEV044(10.10.20.101)--SSL Disabled	BeginHistoryQuery returned: FailDBFault 



Test3:
----2009-10-05 16:52:58      mry--DEV044(10.10.20.101)--SSL Disabled	ASMX: BeginHistoryQuery started. 
----2009-10-05 16:52:58      mry--DEV044(10.10.20.101)--SSL Disabled	DB: GetUserRepositoryLastChange started. 
----2009-10-05 16:52:58      mry--DEV044(10.10.20.101)--SSL Disabled	DB: GetUserRepositoryLastChange finished. 
----2009-10-05 16:52:58      mry--DEV044(10.10.20.101)--SSL Disabled	DB: GetLatestRepositoryInfo started. 
----2009-10-05 16:52:58      mry--DEV044(10.10.20.101)--SSL Disabled	DB: GetLatestRepositoryInfo finished. 
----2009-10-05 16:52:58      mry--DEV044(10.10.20.101)--SSL Disabled	TreeManager: cache matches repository revision and folder security hasn't changed.  Returning cached tree, revID 110868 
----2009-10-05 16:52:58      mry--DEV044(10.10.20.101)--SSL Disabled	DB: QueryHistory started. 
----2009-10-05 16:53:01      mry--DEV044(10.10.20.101)--SSL Disabled	DB: QueryHistory finished. 
----2009-10-05 16:53:01      mry--DEV044(10.10.20.101)--SSL Disabled	BeginHistoryQuery returned: Success 
----2009-10-05 16:53:01      mry--DEV044(10.10.20.101)--SSL Disabled	ASMX: BeginHistoryQuery finished. 
----2009-10-05 16:53:02      mry--DEV044(10.10.20.101)--SSL Disabled	ASMX: GetHistoryQueryItems started. 
----2009-10-05 16:53:02      mry--DEV044(10.10.20.101)--SSL Disabled	GetHistoryQueryItems returned: Success 
----2009-10-05 16:53:02      mry--DEV044(10.10.20.101)--SSL Disabled	ASMX: GetHistoryQueryItems finished. 
----2009-10-05 16:53:10      mry--DEV044(10.10.20.101)--SSL Disabled	ASMX: EndHistoryQuery started. 
----2009-10-05 16:53:10      mry--DEV044(10.10.20.101)--SSL Disabled	EndHistoryQuery returned: Success 
----2009-10-05 16:53:10      mry--DEV044(10.10.20.101)--SSL Disabled	ASMX: EndHistoryQuery finished.

mry
Posts: 4
Joined: Tue Oct 06, 2009 5:43 am

Re: improving performance of spQueryHistory

Post by mry » Fri Oct 16, 2009 2:26 am

Is there anything else we can supply to aid in looking into the issue? More of the logs? Other testcases?

lbauer
Posts: 9736
Joined: Tue Dec 16, 2003 1:25 pm
Location: SourceGear

Re: improving performance of spQueryHistory

Post by lbauer » Fri Oct 16, 2009 7:37 am

It would be helpful to have to have the full log:

We'd like to see a copy of a debug Vault Server log when you run the history with and without Branch checked. The Vault Server log is called sgvault.log and is in %windir%\temp\sgvault on the server machine. You can enable debug server logging in the Admin Web Client under Server Settings->Logging->Log Level. Let me know what time in the log you did the queries.

Send the log zipped up to support at sourcegear.com, Attn: Linda. Please include a link to this forum post.
Linda Bauer
SourceGear
Technical Support Manager

mry
Posts: 4
Joined: Tue Oct 06, 2009 5:43 am

Re: improving performance of spQueryHistory

Post by mry » Mon Oct 19, 2009 12:58 am

I already included the logs both with and without branch action selected in the previous post (the code block). I did omit other users, but the server load was comparable at the times for all the three tests.
Also, as I already stated, the full log is almost 700mb, which is much larger than I can email. If the excerpts aren't enough, please let me know what parts are of interest.

lbauer
Posts: 9736
Joined: Tue Dec 16, 2003 1:25 pm
Location: SourceGear

Re: improving performance of spQueryHistory

Post by lbauer » Tue Oct 20, 2009 7:04 am

Snippets aren't helpful, since we're not sure what we're looking for -- that's why we need the log that covers the full time period of the query. We're looking for patterns as well as errors.

If the log is too large, try this:

Rename the current sgvault log. Put logging in debug mode. Log into the server and do the history query. If the log is still to large to email, contact me for information about FTPing it to SourceGear. Email support at sourcegear.com, Attn: Linda. Please include a link to this forum post.
Linda Bauer
SourceGear
Technical Support Manager

Post Reply