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.
improving performance of spQueryHistory
Moderator: SourceGear
Re: improving performance of spQueryHistory
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.
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
SourceGear
Technical Support Manager
Re: improving performance of spQueryHistory
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.
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.
Re: improving performance of spQueryHistory
I've consulted with our developers, and there's currently no way to improve the performance of spQueryHistory.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 logged feature request 14027 to look into this in a future release.
Linda Bauer
SourceGear
Technical Support Manager
SourceGear
Technical Support Manager
Re: improving performance of spQueryHistory
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.
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.
Re: improving performance of spQueryHistory
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?
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
Re: improving performance of spQueryHistory
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:
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.
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
Re: improving performance of spQueryHistory
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.
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
SourceGear
Technical Support Manager
Re: improving performance of spQueryHistory
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.
http://support.sourcegear.com/viewtopic.php?t=2924
Let us know if that helps.
Linda Bauer
SourceGear
Technical Support Manager
SourceGear
Technical Support Manager
Re: improving performance of spQueryHistory
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).
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.
Re: improving performance of spQueryHistory
Is there anything else we can supply to aid in looking into the issue? More of the logs? Other testcases?
Re: improving performance of spQueryHistory
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.
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
SourceGear
Technical Support Manager
Re: improving performance of spQueryHistory
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.
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.
Re: improving performance of spQueryHistory
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.
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
SourceGear
Technical Support Manager