vault client getting stuck for long period of time

nmcalpin · Post by **nmcalpin** » Wed Mar 29, 2006 7:02 pm

vault 3.1.7 (client/server), W2K server, SQL Server 2000

We are noticing that sometimes remote users (i.e. users at remote sites on the internet) will get extremely long pauses of the vault GUI client. The vault GUi client appears frozen at this time - hourglassed and clicking does nothing. We have only noted this freeze in a specifc project folder which happens to contain about 20 binaries ranging in size from 100kb to 5mb. Sometimes if you wait long enough, vault comes back and carries on, and sometimes my remote user gives up and end-tasks after many minutes. One user has waited at least 10 minutes before giving up.

Any thoughts or ideas? This problem is erratic and is not 100% reproducible on command. Local LAN users (local to the vault server) seem to have no problems whatsoever.

relevant section of a client log, slightly cleansed:

Code: Select all

2:43:29 PM <get>: [Main:492] ProcessGetFileRequests started
2:43:29 PM <get>: [Main:492] UpdateThread started
2:43:29 PM <get>: [Main:492] In download loop, tries left: 2
2:43:29 PM <get>: [Main:492] Server Request: GetFileInfo path: $/<ProjectPath>/CafTrn.bpl, request version: 103, request base version 0,  request target objverid: 0
2:43:29 PM <get>: [Main:492] Server Request: GetFileInfo path: $/<ProjectPath>/CafSec.bpl, request version: 93, request base version 0,  request target objverid: 0
2:43:29 PM <get>: [Main:492] Server Request: GetFileInfo path: $/<ProjectPath>/CafUtils.bpl, request version: 79, request base version 0,  request target objverid: 0
2:43:29 PM <get>: [Main:492] Server Request: GetFileInfo path: $/<ProjectPath>/CafSqm.bpl, request version: 95, request base version 0,  request target objverid: 0
2:43:29 PM <get>: [Main:492] Server Request: GetFileInfo path: $/<ProjectPath>/CafRpc.bpl, request version: 144, request base version 0,  request target objverid: 0
2:43:29 PM <get>: [Main:492] Server Request: GetFileInfo path: $/<ProjectPath>/CAFService01.exe, request version: 197, request base version 0,  request target objverid: 0
2:43:29 PM <get>: [Main:492] Server Request: GetFileInfo path: $/<ProjectPath>/CafDta.bpl, request version: 101, request base version 0,  request target objverid: 0
2:43:29 PM <get>: [Main:492] Server Request: GetFileInfo path: $/<ProjectPath>/CafTbl.bpl, request version: 129, request base version 0,  request target objverid: 0
2:43:29 PM <get>: [Main:492] Server Request: GetFileInfo path: $/<ProjectPath>/CafNbt.bpl, request version: 116, request base version 0,  request target objverid: 0
2:43:29 PM <get>: [Main:492] Server Request: GetFileInfo path: $/<ProjectPath>/CafCvc.bpl, request version: 90, request base version 0,  request target objverid: 0
2:43:29 PM <get>: [Main:492] Server Request: GetFileInfo path: $/<ProjectPath>/CafLog.bpl, request version: 81, request base version 0,  request target objverid: 0
2:43:29 PM <connection>: [Main:492] BeginDownloadFiles started.
2:43:30 PM <connection>: [Main:492] BeginDownloadFiles finished.
2:43:30 PM <get>: [Main:492] BeginDownloadFiles called, downloadID: 7576a28a-9247-4715-b329-3f7c393fb7fd
2:43:30 PM <get>: [Main:492] Server Response: GetFileInfo request path: $/<ProjectPath>/CafTrn.bpl, response status: 1590, response version: 103, response objverid: 243745, response objverid: 229228543
2:43:30 PM <get>: [Main:492] Server Response: GetFileInfo request path: $/<ProjectPath>/CafSec.bpl, response status: 1590, response version: 93, response objverid: 243452, response objverid: 1643477616
2:43:30 PM <get>: [Main:492] Server Response: GetFileInfo request path: $/<ProjectPath>/CafUtils.bpl, response status: 1590, response version: 79, response objverid: 244119, response objverid: 1109851949
2:43:30 PM <get>: [Main:492] Server Response: GetFileInfo request path: $/<ProjectPath>/CafSqm.bpl, response status: 1590, response version: 95, response objverid: 243691, response objverid: 3656158229
2:43:30 PM <get>: [Main:492] Server Response: GetFileInfo request path: $/<ProjectPath>/CafRpc.bpl, response status: 1590, response version: 144, response objverid: 244024, response objverid: 714726290
2:43:30 PM <get>: [Main:492] Server Response: GetFileInfo request path: $/<ProjectPath>/CAFService01.exe, response status: 1590, response version: 197, response objverid: 244152, response objverid: 3906432800
2:43:30 PM <get>: [Main:492] Server Response: GetFileInfo request path: $/<ProjectPath>/CafDta.bpl, response status: 1590, response version: 101, response objverid: 244068, response objverid: 634488562
2:43:30 PM <get>: [Main:492] Server Response: GetFileInfo request path: $/<ProjectPath>/CafTbl.bpl, response status: 1590, response version: 129, response objverid: 243894, response objverid: 3321682994
2:43:30 PM <get>: [Main:492] Server Response: GetFileInfo request path: $/<ProjectPath>/CafNbt.bpl, response status: 1590, response version: 116, response objverid: 243604, response objverid: 4262681813
2:43:30 PM <get>: [Main:492] Server Response: GetFileInfo request path: $/<ProjectPath>/CafCvc.bpl, response status: 1590, response version: 90, response objverid: 243393, response objverid: 1320884788
2:43:30 PM <get>: [Main:492] Server Response: GetFileInfo request path: $/<ProjectPath>/CafLog.bpl, response status: 1590, response version: 81, response objverid: 243347, response objverid: 3874579250
2:43:30 PM <get>: [Main:492] Creating file download stream
2:43:30 PM <connection>: [Main:492] GetDownloadFileStream started.
2:43:30 PM <connection>: [Main:492] GetDownloadFileStream finished.
2:43:30 PM <get>: [Main:492] File download stream created
2:43:30 PM <connection>: [Main:492] ReadDownloadFileFromStream started.
2:43:36 PM <connection>: [Main:492] ReadDownloadFileFromStream finished.
2:43:36 PM <get>: [Main:492] Download stream: read one new file, sending for processing
2:43:36 PM <eol>: [Main:492] File has EOL None.  WorkingFolderOptions.OverrideNativeEOL is None. NativeEOL is CRLF
2:43:36 PM <eol>: [Main:492] No EOL conversion performed onC:\<LocalTemp>\CafTrn.bpl
2:43:36 PM <connection>: [Main:492] ReadDownloadFileFromStream started.
2:44:53 PM <connection>: [Main:492] ReadDownloadFileFromStream finished.
2:44:53 PM <get>: [Main:492] Download stream: read one new file, sending for processing
2:44:53 PM <eol>: [Main:492] File has EOL None.  WorkingFolderOptions.OverrideNativeEOL is None. NativeEOL is CRLF
2:44:54 PM <eol>: [Main:492] No EOL conversion performed onC:\<LocalTemp>\CafSec.bpl
2:44:54 PM <connection>: [Main:492] ReadDownloadFileFromStream started.
2:45:04 PM <connection>: [Main:492] ReadDownloadFileFromStream finished.
2:45:04 PM <get>: [Main:492] Download stream: read one new file, sending for processing
2:45:04 PM <eol>: [Main:492] File has EOL None.  WorkingFolderOptions.OverrideNativeEOL is None. NativeEOL is CRLF
2:45:04 PM <eol>: [Main:492] No EOL conversion performed onC:<Path>\<filename.BPL>
2:45:04 PM <connection>: [Main:492] ReadDownloadFileFromStream started.
2:46:35 PM <connection>: [Main:492] ReadDownloadFileFromStream finished.
2:46:35 PM <get>: [Main:492] Download stream: read one new file, sending for processing
2:46:35 PM <eol>: [Main:492] File has EOL None.  WorkingFolderOptions.OverrideNativeEOL is None. NativeEOL is CRLF
2:46:35 PM <eol>: [Main:492] No EOL conversion performed onC:\<Path>\<filename.BPL>
2:46:35 PM <connection>: [Main:492] ReadDownloadFileFromStream started.
2:47:26 PM <mutex>: [GUIClientWorkerThread:3908] Took mutex 1080
2:47:26 PM <mutex>: [GUIClientWorkerThread:3908] Released mutex 1080
2:47:26 PM <mutex>: [GUIClientWorkerThread:3908] Took mutex 1084
2:47:26 PM <mutex>: [GUIClientWorkerThread:3908] Released mutex 1084
2:47:28 PM <mutex>: [GUIClientWorkerThread:3908] Took mutex 1080
2:47:28 PM <mutex>: [GUIClientWorkerThread:3908] Released mutex 1080
2:47:28 PM <mutex>: [GUIClientWorkerThread:3908] Took mutex 1084
2:47:28 PM <mutex>: [GUIClientWorkerThread:3908] Released mutex 1084
2:47:40 PM <mutex>: [GUIClientWorkerThread:3908] Took mutex 1080
2:47:40 PM <mutex>: [GUIClientWorkerThread:3908] Released mutex 1080
2:47:40 PM <mutex>: [GUIClientWorkerThread:3908] Took mutex 1084
2:47:40 PM <mutex>: [GUIClientWorkerThread:3908] Released mutex 1084

relevant snip of the server log for the same occurence (times mismatch slightly due to server/client time mismatch and a timezone difference, but are for the same logical timeframe), also slightly cleansed.

Code: Select all

3:33:35 PM  Login 
3:33:36 PM  GetUserList returned: Success 
3:33:36 PM  GetUserOptions returned: Success 
3:33:39 PM  GetRepositories returned: Success 
3:33:40 PM  Getting repository Structure-> Rep ID: 1 Base: 28116 Target: -1 
3:33:40 PM  TreeManager: cache matches repository revision and folder security hasn't changed.  Returning cached tree, revID 28118 
3:33:40 PM  VaultServiceAPI::GetRepositoryTreeDelta() UserID:3 RepID:1 Base:28116 Target:28118  Calling VaultRepUtil.DiffRepTrees() - in-memory tree diff. 
3:33:40 PM  GetRepositoryStructure returned: Success 
3:33:41 PM  Getting list of checkout changes. 
3:33:41 PM  TreeManager: cache matches repository revision and folder security hasn't changed.  Returning cached tree, revID 28118 
3:33:41 PM  VaultServiceAPI::GetCheckoutListChanges() Status:0 UserID:3 RepID:1 FolderSecurity:True BaseList:14151 Target List:0 RefreshFlag:True 
3:33:41 PM  GetCheckOutListChanges returned: Success 
3:33:42 PM  GetUserEmailOptions returned Success 
3:33:42 PM  TreeManager: cache matches repository revision and folder security hasn't changed.  Returning cached tree, revID 28118 
3:33:42 PM  ListWatchers returned Success 
3:33:43 PM  ListCloakedObjects returned: Success 
3:33:44 PM  GetRepositoryOptions returned: Success 
3:33:45 PM  GetRepositories returned: Success 
3:33:59 PM  TreeManager: cache matches repository revision and folder security hasn't changed.  Returning cached tree, revID 28118 
3:33:59 PM  BeginLabelQuery returned: Success 
3:34:00 PM  GetLabelQueryItems returned: Success 
3:34:00 PM  GetLabelQueryItems returned: Success 
3:34:04 PM  EndLabelQuery returned: Success 
3:34:10 PM  TreeManager: cache matches repository revision and folder security hasn't changed.  Returning cached tree, revID 28118 
3:34:12 PM  BeginHistoryQuery returned: Success 
3:34:13 PM  GetHistoryQueryItems returned: Success 
3:34:22 PM  Getting folder structure. 
3:34:22 PM  TreeManager: cache matches repository revision and folder security hasn't changed.  Returning cached tree, revID 28118 
3:34:23 PM  GetFolderStructure returned: Success 
3:35:02 PM  TreeManager: cache matches repository revision and folder security hasn't changed.  Returning cached tree, revID 28118 
3:35:02 PM  FindVersionsByCRCs returned: Success 
3:35:02 PM  GetObjectVersionList returned: Success 
3:35:03 PM  GetObjectVersionList returned: Success 
3:35:03 PM  GetObjectVersionList returned: Success 
3:35:03 PM  GetObjectVersionList returned: Success 
3:35:04 PM  GetObjectVersionList returned: Success 
3:35:04 PM  GetObjectVersionList returned: Success 
3:35:05 PM  GetObjectVersionList returned: Success 
3:35:05 PM  GetObjectVersionList returned: Success 
3:35:05 PM  GetObjectVersionList returned: Success 
3:35:06 PM  GetObjectVersionList returned: Success 
3:35:06 PM  GetObjectVersionList returned: Success 
3:35:07 PM  Beginning file download 
3:35:07 PM  TreeManager: cache matches repository revision and folder security hasn't changed.  Returning cached tree, revID 28118 
3:35:07 PM  VaultLib.VaultRequestGetFile returned: SuccessRequireFileDownload 
3:35:07 PM  VaultLib.VaultRequestGetFile returned: SuccessRequireFileDownload 
3:35:07 PM  VaultLib.VaultRequestGetFile returned: SuccessRequireFileDownload 
3:35:07 PM  VaultLib.VaultRequestGetFile returned: SuccessRequireFileDownload 
3:35:07 PM  VaultLib.VaultRequestGetFile returned: SuccessRequireFileDownload 
3:35:07 PM  VaultLib.VaultRequestGetFile returned: SuccessRequireFileDownload 
3:35:07 PM  VaultLib.VaultRequestGetFile returned: SuccessRequireFileDownload 
3:35:07 PM  VaultLib.VaultRequestGetFile returned: SuccessRequireFileDownload 
3:35:07 PM  VaultLib.VaultRequestGetFile returned: SuccessRequireFileDownload 
3:35:07 PM  VaultLib.VaultRequestGetFile returned: SuccessRequireFileDownload 
3:35:07 PM  VaultLib.VaultRequestGetFile returned: SuccessRequireFileDownload 
3:35:07 PM  BeginDownloadFiles returned: Success 
3:35:07 PM  VaultFileDownload starting 
3:35:07 PM  Downloading delta for $/<ProjectPath>/CafTrn.bpl from 0 to 243745 
3:35:07 PM  Downloading delta for $/<ProjectPath>/CafSec.bpl from 0 to 243452 
3:35:07 PM  Downloading delta for $/<ProjectPath>/CafUtils.bpl from 0 to 244119 
3:35:07 PM  Downloading delta for $/<ProjectPath>/CafSqm.bpl from 0 to 243691 
3:35:07 PM  Downloading delta for $/<ProjectPath>/CafRpc.bpl from 0 to 244024 
3:35:07 PM  Downloading delta for $/<ProjectPath>/CAFService01.exe from 0 to 244152 
3:35:07 PM  Downloading delta for $/<ProjectPath>/CafDta.bpl from 0 to 244068 
3:35:07 PM  Downloading delta for $/<ProjectPath>/CafTbl.bpl from 0 to 243894 
3:35:07 PM  Downloading delta for $/<ProjectPath>/CafNbt.bpl from 0 to 243604 
3:35:07 PM  Downloading delta for $/<ProjectPath>/CafCvc.bpl from 0 to 243393 
3:35:07 PM  Downloading delta for $/<ProjectPath>/CafLog.bpl from 0 to 243347 
3:35:08 PM  GetLatest wrote 0 bytes to the Response Stream

full logs available to sourcegear staff (let me know where to send it).

lbauer · Post by **lbauer** » Wed Mar 29, 2006 8:29 pm

Local LAN users (local to the vault server) seem to have no problems whatsoever.

If only remote users are experiencing hangs, this points to network issues.

This snippet appears to be a download that didn't download anything:

3:35:07 PM Downloading delta for $/<ProjectPath>/CafTbl.bpl from 0 to 243894
3:35:07 PM Downloading delta for $/<ProjectPath>/CafNbt.bpl from 0 to 243604
3:35:07 PM Downloading delta for $/<ProjectPath>/CafCvc.bpl from 0 to 243393
3:35:07 PM Downloading delta for $/<ProjectPath>/CafLog.bpl from 0 to 243347
3:35:08 PM GetLatest wrote 0 bytes to the Response Stream

Send log files to Linda at Sourcegear.com. Let me know the time the event occurred, the username and the specific operation that preceded the hang. Client and server logs should match up. Thanks.

nmcalpin · Post by **nmcalpin** » Thu Mar 30, 2006 10:52 am

I have new information on this issue from one of my developers. I think this may NOT be a "LAN vs WAN" user issue, but is perhaps instead because the WAN users are QA/QC users and use vault very differently from our developers.

Anyways, here is the additional information from my developer:

Code: Select all


Steve : I can explain why that's happening
Steve : part of the problem is that Vault freaks out a bit when you move files around
Steve : one of the things I sometimes do is replace files in the _Installations folder from the main dev with ones from a branch
Steve : they have the same filenames, but according to Vault they are different files
Steve : so when a user goes to use that folder, Vault has to figure out what version of those files that the user has
Steve : and that can cause things to hang

Is there any known problems in this regard, where users are GLV'ing a folder where the files on vault have the same names, but are VERY different (they might be historically related, or they might not be) as the previous file of the same name?

In simplified terms, start with vault folder "A" and GLV it on workstation 1. Then, using workstation 2, remove all the files from vault in folder A, replace them with all new files of the same names but entirely different content. Now, go back to workstation 1 and work in that folder (perhaps GLV it). that seems to be where our problem occurs.

Our _Installations folder is a folder that we share various files into from elsewhere on the vault tree in order to build installations. So if we want to update the installer/installation of our product software, we might replace half the files in the _Installations folder with files from an entirely different part of the tree (by sharing them in), but which have the same file names.

lbauer · Post by **lbauer** » Fri Mar 31, 2006 9:07 am

This can affect performance, though may not fully explain the long "freeze" period. Copying files into working directories makes them out of sync with the baselines. See this link for details about how the baselines and working folders are handled in the Vault Client:

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

There could be slowdowns caused by the Vault server calculating the delta (difference) between the client's version of the tree and the latest tree.

We'd like to see a copy of the server log in debug mode, with the username(s) and times in the log that correspond to the "freeze," so we know where to look.