Strange vault client slowdowns

[stevek2]

I'm using Vault 4.1.3 on a Vista x64 machine. I have several changed files in my pending changes tab. After a few minutes (5? 10?) of inactivity, I right-click on one of the files and do "Show Differences". The client then prints "Retrieving repository structure information from the server", which takes about 18 seconds (and, strangely, it's often about 18 seconds). However, this file is a pretty small file, and my analysis on the server shows that there's really nothing going on (I have quad CPUs, dual RAID drives, and 7GB of RAM, and the disks pretty much stay idle and the SQL and W3P processes do not consume much CPU or perform much I/O).

After I've performed a "Show Difference", then the next one is usually pretty fast, on the order of 1 second or less. Then after waiting a while, it goes back to the 18-second wait.

I have attached the client log at the bottom of the message, with my comments inserted with '-----'. The strange thing is that the time required for the GetRepositoryStructure() to complete varies widely, from <1 second, to 7 seconds, to 18 seconds, but for no apparent reason -- in each case the repository revision (9133) has not been changed, as you can see, and I was running Disk Performance counters and also SysInternal's "ProcMon" on the server while these requests were made, and they show very little going on on the server -- which I would expect if the tree was cached in server RAM. Also, I looked in the event log and the IIS worker was not being reset or anything like that. I didn't have server logging turned on.

Any thoughts? It sure looks like some cached information is being discarded or something.

Thanks,
Steve

=== CLIENT LOG ===

3/5/2009 11:42:40 AM <generic>: [<No Name>:5096] VaultGUIClient, Version=4.1.3.18336, Culture=neutral, PublicKeyToken=null
3/5/2009 11:42:40 AM <generic>: [<No Name>:5096] Enabled logging class <connection>
3/5/2009 11:42:40 AM <generic>: [<No Name>:5096] Enabled logging class <createrequest>
3/5/2009 11:42:40 AM <generic>: [<No Name>:5096] Enabled logging class <commit>
3/5/2009 11:42:40 AM <generic>: [<No Name>:5096] Enabled logging class <get>
3/5/2009 11:42:40 AM <generic>: [<No Name>:5096] Enabled logging class <refresh>
3/5/2009 11:42:40 AM <generic>: [<No Name>:5096] Enabled logging class <upload>
3/5/2009 11:42:41 AM <connection>: [GUIClientWorkerThread:4384] InitService started.
3/5/2009 11:42:42 AM <connection>: [GUIClientWorkerThread:4384] InitService finished.
3/5/2009 11:42:42 AM <connection>: [GUIClientWorkerThread:4384] Login started.
3/5/2009 11:42:43 AM <connection>: [GUIClientWorkerThread:4384] Login finished.
3/5/2009 11:42:43 AM <connection>: [GUIClientWorkerThread:4384] GetOptions started.
3/5/2009 11:42:43 AM <connection>: [Main:5096] GetUserList started.
3/5/2009 11:42:48 AM <connection>: [GUIClientWorkerThread:4384] GetOptions finished.
3/5/2009 11:42:48 AM <connection>: [GUIClientWorkerThread:4384] GetHistoryFavorites started.
3/5/2009 11:42:48 AM <connection>: [GUIClientWorkerThread:4384] GetHistoryFavorites finished.
3/5/2009 11:42:48 AM <connection>: [Main:5096] GetUserList finished.
3/5/2009 11:42:48 AM <connection>: [GUIClientWorkerThread:4384] GetServerVersionInfo started.
3/5/2009 11:42:48 AM <connection>: [GUIClientWorkerThread:4384] GetServerVersionInfo finished.
3/5/2009 11:42:48 AM <connection>: [GUIClientWorkerThread:4384] GetRepositories started.
3/5/2009 11:42:48 AM <connection>: [GUIClientWorkerThread:4384] GetRepositories finished.
3/5/2009 11:42:49 AM <refresh>: [GUIClientWorkerThread:4384] Deserialized CacheMember_Repository
3/5/2009 11:42:49 AM <refresh>: [GUIClientWorkerThread:4384] Refresh started
3/5/2009 11:42:49 AM <refresh>: [GUIClientWorkerThread:4384] delta passed in was null, retrieving one
3/5/2009 11:42:49 AM <refresh>: [GUIClientWorkerThread:4384] calling GetRepositoryStructure(1, 9133, -1, ref, 7/1/1850 12:00:00 AM)
3/5/2009 11:42:49 AM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure started.
3/5/2009 11:42:49 AM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure started
3/5/2009 11:42:49 AM <refresh>: [GUIClientWorkerThread:4384] Calling client service GetRepositoryStructure(1, 9133, -1, 7/1/1850 12:00:00 AM, ref, ref, ref)
3/5/2009 11:42:49 AM <refresh>: [GUIClientWorkerThread:4384] Client service GetRepositoryStructure returned: dtLatestCheck 7/1/1850 12:00:00 AM, nReturnDestRevision 9133, rd not null True
3/5/2009 11:42:49 AM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished
3/5/2009 11:42:49 AM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished.
3/5/2009 11:42:49 AM <refresh>: [GUIClientWorkerThread:4384] Serialized CacheMember_LastStructureGetTime
3/5/2009 11:42:49 AM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure returned: returnedRevision 9133, newLatestDate 7/1/1850 12:00:00 AM, delta not null: True
3/5/2009 11:42:49 AM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges started.
3/5/2009 11:42:50 AM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges finished.
3/5/2009 11:42:50 AM <refresh>: [GUIClientWorkerThread:4384] Applying server delta to the server-synched repository
3/5/2009 11:42:50 AM <refresh>: [GUIClientWorkerThread:4384] Done updating tree cache with pending changes. ServerReposRevID: 9133 PendingChangeRevID: 9133
3/5/2009 11:42:50 AM <refresh>: [GUIClientWorkerThread:4384] Repository.Update finished, calling SaveRepositoryIfNothingOnDisk()
3/5/2009 11:42:50 AM <refresh>: [GUIClientWorkerThread:4384] SaveIfNothingOnDisk: not saving
3/5/2009 11:42:50 AM <refresh>: [GUIClientWorkerThread:4384] Refreshing working folder associations from disk
3/5/2009 11:42:50 AM <refresh>: [GUIClientWorkerThread:4384] Refreshing all change set items without notify
3/5/2009 11:42:50 AM <refresh>: [GUIClientWorkerThread:4384] Calling UpdateKnownChanges_RefreshKnown with notify
3/5/2009 11:42:50 AM <refresh>: [GUIClientWorkerThread:4384] Calling NotifyTreeStructureChanged
3/5/2009 11:42:50 AM <refresh>: [GUIClientWorkerThread:4384] Refresh finished
3/5/2009 11:42:50 AM <connection>: [GUIClientWorkerThread:4384] GetUserEmailOptions started.
3/5/2009 11:42:50 AM <connection>: [GUIClientWorkerThread:4384] GetUserEmailOptions finished.
3/5/2009 11:42:50 AM <connection>: [GUIClientWorkerThread:4384] ListWatchers started.
3/5/2009 11:42:50 AM <connection>: [GUIClientWorkerThread:4384] ListWatchers finished.
3/5/2009 11:42:50 AM <connection>: [GUIClientWorkerThread:4384] ListCloakedObjects started.
3/5/2009 11:42:50 AM <connection>: [GUIClientWorkerThread:4384] ListCloakedObjects finished.
3/5/2009 11:42:50 AM <connection>: [GUIClientWorkerThread:4384] GetRepositoryOptions started.
3/5/2009 11:42:50 AM <connection>: [GUIClientWorkerThread:4384] GetRepositoryOptions finished.
3/5/2009 11:42:50 AM <connection>: [Main:5096] GetRepositories started.
3/5/2009 11:42:50 AM <connection>: [Main:5096] GetRepositories finished.
----- Vault has finished startup ----
----- I now do "Show Differences" on file #1 -----
----- This will complete very quickly ( < 1 second) -----
3/5/2009 11:44:13 AM <refresh>: [GUIClientWorkerThread:4384] Refresh started
3/5/2009 11:44:13 AM <refresh>: [GUIClientWorkerThread:4384] delta passed in was null, retrieving one
3/5/2009 11:44:13 AM <refresh>: [GUIClientWorkerThread:4384] calling GetRepositoryStructure(1, 9133, -1, ref, 7/1/1850 12:00:00 AM)
3/5/2009 11:44:13 AM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure started.
3/5/2009 11:44:13 AM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure started
3/5/2009 11:44:13 AM <refresh>: [GUIClientWorkerThread:4384] Calling client service GetRepositoryStructure(1, 9133, -1, 7/1/1850 12:00:00 AM, ref, ref, ref)
3/5/2009 11:44:13 AM <refresh>: [GUIClientWorkerThread:4384] Client service GetRepositoryStructure returned: dtLatestCheck 7/1/1850 12:00:00 AM, nReturnDestRevision 9133, rd not null True
3/5/2009 11:44:13 AM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished
3/5/2009 11:44:13 AM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished.
3/5/2009 11:44:13 AM <refresh>: [GUIClientWorkerThread:4384] Serialized CacheMember_LastStructureGetTime
3/5/2009 11:44:13 AM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure returned: returnedRevision 9133, newLatestDate 7/1/1850 12:00:00 AM, delta not null: True
3/5/2009 11:44:13 AM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges started.
3/5/2009 11:44:13 AM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges finished.
3/5/2009 11:44:13 AM <refresh>: [GUIClientWorkerThread:4384] Applying server delta to the server-synched repository
3/5/2009 11:44:13 AM <refresh>: [GUIClientWorkerThread:4384] Done updating tree cache with pending changes. ServerReposRevID: 9133 PendingChangeRevID: 9133
3/5/2009 11:44:13 AM <refresh>: [GUIClientWorkerThread:4384] Repository.Update finished, calling SaveRepositoryIfNothingOnDisk()
3/5/2009 11:44:13 AM <refresh>: [GUIClientWorkerThread:4384] SaveIfNothingOnDisk: not saving
3/5/2009 11:44:13 AM <refresh>: [GUIClientWorkerThread:4384] Refreshing working folder associations from disk
3/5/2009 11:44:13 AM <refresh>: [GUIClientWorkerThread:4384] Refreshing all change set items without notify
3/5/2009 11:44:13 AM <refresh>: [GUIClientWorkerThread:4384] Calling UpdateKnownChanges_RefreshKnown with notify
3/5/2009 11:44:13 AM <refresh>: [GUIClientWorkerThread:4384] Calling NotifyTreeStructureChanged
3/5/2009 11:44:13 AM <refresh>: [GUIClientWorkerThread:4384] Refresh finished
3/5/2009 11:44:13 AM <get>: [GUIClientWorkerThread:4384] ProcessGetFileRequests started
3/5/2009 11:44:13 AM <get>: [GUIClientWorkerThread:4384] UpdateThread started
3/5/2009 11:44:13 AM <get>: [GUIClientWorkerThread:4384] In download loop, tries left: 2
3/5/2009 11:44:13 AM <get>: [GUIClientWorkerThread:4384] Server Request: GetFileInfo path: $/dev/awusb/arch/mips/include/exception.h, request version: <no request>, request base version <no request>, request target objverid: <no request>
3/5/2009 11:44:13 AM <get>: [GUIClientWorkerThread:4384] ProcessGetFileRequests finished
----- Then an "auto refresh" begins -----
----- This GetRepositoryStructure() will take 7 seconds, although the previous one took < 1 second - why? -----
3/5/2009 11:52:48 AM <refresh>: [GUIClientWorkerThread:4384] Auto refresh begun
3/5/2009 11:52:48 AM <refresh>: [GUIClientWorkerThread:4384] Refresh started
3/5/2009 11:52:48 AM <refresh>: [GUIClientWorkerThread:4384] delta passed in was null, retrieving one
3/5/2009 11:52:48 AM <refresh>: [GUIClientWorkerThread:4384] calling GetRepositoryStructure(1, 9133, -1, ref, 7/1/1850 12:00:00 AM)
3/5/2009 11:52:48 AM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure started.
3/5/2009 11:52:48 AM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure started
3/5/2009 11:52:48 AM <refresh>: [GUIClientWorkerThread:4384] Calling client service GetRepositoryStructure(1, 9133, -1, 7/1/1850 12:00:00 AM, ref, ref, ref)
3/5/2009 11:53:05 AM <refresh>: [GUIClientWorkerThread:4384] Client service GetRepositoryStructure returned: dtLatestCheck 7/1/1850 12:00:00 AM, nReturnDestRevision 9133, rd not null True
3/5/2009 11:53:05 AM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished
3/5/2009 11:53:05 AM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished.
3/5/2009 11:53:05 AM <refresh>: [GUIClientWorkerThread:4384] Serialized CacheMember_LastStructureGetTime
3/5/2009 11:53:05 AM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure returned: returnedRevision 9133, newLatestDate 7/1/1850 12:00:00 AM, delta not null: True
3/5/2009 11:53:05 AM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges started.
3/5/2009 11:53:05 AM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges finished.
3/5/2009 11:53:05 AM <refresh>: [GUIClientWorkerThread:4384] Applying server delta to the server-synched repository
3/5/2009 11:53:05 AM <refresh>: [GUIClientWorkerThread:4384] Done updating tree cache with pending changes. ServerReposRevID: 9133 PendingChangeRevID: 9133
3/5/2009 11:53:05 AM <refresh>: [GUIClientWorkerThread:4384] Repository.Update finished, calling SaveRepositoryIfNothingOnDisk()
3/5/2009 11:53:05 AM <refresh>: [GUIClientWorkerThread:4384] SaveIfNothingOnDisk: not saving
3/5/2009 11:53:05 AM <refresh>: [GUIClientWorkerThread:4384] Refreshing working folder associations from disk
3/5/2009 11:53:05 AM <refresh>: [GUIClientWorkerThread:4384] Refreshing all change set items without notify
3/5/2009 11:53:05 AM <refresh>: [GUIClientWorkerThread:4384] Calling UpdateKnownChanges_RefreshKnown with notify
3/5/2009 11:53:05 AM <refresh>: [GUIClientWorkerThread:4384] Calling NotifyTreeStructureChanged
3/5/2009 11:53:05 AM <refresh>: [GUIClientWorkerThread:4384] Refresh finished
3/5/2009 11:53:05 AM <refresh>: [GUIClientWorkerThread:4384] Auto refresh finished
----- After a few minutes idle, I do another "Show Differences" on the same file #1 -----
----- This GetRepositoryStructure() will take 18 seconds. But the server isn't doing anything at this time! -----
3/5/2009 12:00:09 PM <refresh>: [GUIClientWorkerThread:4384] Refresh started
3/5/2009 12:00:09 PM <refresh>: [GUIClientWorkerThread:4384] delta passed in was null, retrieving one
3/5/2009 12:00:09 PM <refresh>: [GUIClientWorkerThread:4384] calling GetRepositoryStructure(1, 9133, -1, ref, 7/1/1850 12:00:00 AM)
3/5/2009 12:00:09 PM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure started.
3/5/2009 12:00:09 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure started
3/5/2009 12:00:09 PM <refresh>: [GUIClientWorkerThread:4384] Calling client service GetRepositoryStructure(1, 9133, -1, 7/1/1850 12:00:00 AM, ref, ref, ref)
3/5/2009 12:00:27 PM <refresh>: [GUIClientWorkerThread:4384] Client service GetRepositoryStructure returned: dtLatestCheck 7/1/1850 12:00:00 AM, nReturnDestRevision 9133, rd not null True
3/5/2009 12:00:27 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished
3/5/2009 12:00:27 PM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished.
3/5/2009 12:00:27 PM <refresh>: [GUIClientWorkerThread:4384] Serialized CacheMember_LastStructureGetTime
3/5/2009 12:00:27 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure returned: returnedRevision 9133, newLatestDate 7/1/1850 12:00:00 AM, delta not null: True
3/5/2009 12:00:27 PM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges started.
3/5/2009 12:00:27 PM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges finished.
3/5/2009 12:00:27 PM <refresh>: [GUIClientWorkerThread:4384] Applying server delta to the server-synched repository
3/5/2009 12:00:27 PM <refresh>: [GUIClientWorkerThread:4384] Done updating tree cache with pending changes. ServerReposRevID: 9133 PendingChangeRevID: 9133
3/5/2009 12:00:27 PM <refresh>: [GUIClientWorkerThread:4384] Repository.Update finished, calling SaveRepositoryIfNothingOnDisk()
3/5/2009 12:00:27 PM <refresh>: [GUIClientWorkerThread:4384] SaveIfNothingOnDisk: not saving
3/5/2009 12:00:27 PM <refresh>: [GUIClientWorkerThread:4384] Refreshing working folder associations from disk
3/5/2009 12:00:27 PM <refresh>: [GUIClientWorkerThread:4384] Refreshing all change set items without notify
3/5/2009 12:00:27 PM <refresh>: [GUIClientWorkerThread:4384] Calling UpdateKnownChanges_RefreshKnown with notify
3/5/2009 12:00:27 PM <refresh>: [GUIClientWorkerThread:4384] Calling NotifyTreeStructureChanged
3/5/2009 12:00:27 PM <refresh>: [GUIClientWorkerThread:4384] Refresh finished
3/5/2009 12:00:27 PM <get>: [GUIClientWorkerThread:4384] ProcessGetFileRequests started
3/5/2009 12:00:27 PM <get>: [GUIClientWorkerThread:4384] UpdateThread started
3/5/2009 12:00:27 PM <get>: [GUIClientWorkerThread:4384] In download loop, tries left: 2
3/5/2009 12:00:27 PM <get>: [GUIClientWorkerThread:4384] Server Request: GetFileInfo path: $/dev/awusb/arch/mips/include/exception.h, request version: <no request>, request base version <no request>, request target objverid: <no request>
3/5/2009 12:00:27 PM <get>: [GUIClientWorkerThread:4384] ProcessGetFileRequests finished
----- Another "auto refresh" begins, this one will also take 7 seconds -----
3/5/2009 12:02:48 PM <refresh>: [GUIClientWorkerThread:4384] Auto refresh begun
3/5/2009 12:02:48 PM <refresh>: [GUIClientWorkerThread:4384] Refresh started
3/5/2009 12:02:48 PM <refresh>: [GUIClientWorkerThread:4384] delta passed in was null, retrieving one
3/5/2009 12:02:48 PM <refresh>: [GUIClientWorkerThread:4384] calling GetRepositoryStructure(1, 9133, -1, ref, 7/1/1850 12:00:00 AM)
3/5/2009 12:02:48 PM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure started.
3/5/2009 12:02:48 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure started
3/5/2009 12:02:48 PM <refresh>: [GUIClientWorkerThread:4384] Calling client service GetRepositoryStructure(1, 9133, -1, 7/1/1850 12:00:00 AM, ref, ref, ref)
3/5/2009 12:03:05 PM <refresh>: [GUIClientWorkerThread:4384] Client service GetRepositoryStructure returned: dtLatestCheck 7/1/1850 12:00:00 AM, nReturnDestRevision 9133, rd not null True
3/5/2009 12:03:05 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished
3/5/2009 12:03:05 PM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished.
3/5/2009 12:03:05 PM <refresh>: [GUIClientWorkerThread:4384] Serialized CacheMember_LastStructureGetTime
3/5/2009 12:03:05 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure returned: returnedRevision 9133, newLatestDate 7/1/1850 12:00:00 AM, delta not null: True
3/5/2009 12:03:05 PM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges started.
3/5/2009 12:03:05 PM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges finished.
3/5/2009 12:03:05 PM <refresh>: [GUIClientWorkerThread:4384] Applying server delta to the server-synched repository
3/5/2009 12:03:05 PM <refresh>: [GUIClientWorkerThread:4384] Done updating tree cache with pending changes. ServerReposRevID: 9133 PendingChangeRevID: 9133
3/5/2009 12:03:05 PM <refresh>: [GUIClientWorkerThread:4384] Repository.Update finished, calling SaveRepositoryIfNothingOnDisk()
3/5/2009 12:03:05 PM <refresh>: [GUIClientWorkerThread:4384] SaveIfNothingOnDisk: not saving
3/5/2009 12:03:05 PM <refresh>: [GUIClientWorkerThread:4384] Refreshing working folder associations from disk
3/5/2009 12:03:05 PM <refresh>: [GUIClientWorkerThread:4384] Refreshing all change set items without notify
3/5/2009 12:03:05 PM <refresh>: [GUIClientWorkerThread:4384] Calling UpdateKnownChanges_RefreshKnown with notify
3/5/2009 12:03:05 PM <refresh>: [GUIClientWorkerThread:4384] Calling NotifyTreeStructureChanged
3/5/2009 12:03:05 PM <refresh>: [GUIClientWorkerThread:4384] Refresh finished
3/5/2009 12:03:05 PM <refresh>: [GUIClientWorkerThread:4384] Auto refresh finished
----- Then another "Show Differences" on a different file #2 a few minutes later -----
----- This one will take 17 seconds -----
3/5/2009 12:06:15 PM <refresh>: [GUIClientWorkerThread:4384] Refresh started
3/5/2009 12:06:15 PM <refresh>: [GUIClientWorkerThread:4384] delta passed in was null, retrieving one
3/5/2009 12:06:15 PM <refresh>: [GUIClientWorkerThread:4384] calling GetRepositoryStructure(1, 9133, -1, ref, 7/1/1850 12:00:00 AM)
3/5/2009 12:06:15 PM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure started.
3/5/2009 12:06:15 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure started
3/5/2009 12:06:15 PM <refresh>: [GUIClientWorkerThread:4384] Calling client service GetRepositoryStructure(1, 9133, -1, 7/1/1850 12:00:00 AM, ref, ref, ref)
3/5/2009 12:06:32 PM <refresh>: [GUIClientWorkerThread:4384] Client service GetRepositoryStructure returned: dtLatestCheck 7/1/1850 12:00:00 AM, nReturnDestRevision 9133, rd not null True
3/5/2009 12:06:32 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished
3/5/2009 12:06:32 PM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished.
3/5/2009 12:06:32 PM <refresh>: [GUIClientWorkerThread:4384] Serialized CacheMember_LastStructureGetTime
3/5/2009 12:06:32 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure returned: returnedRevision 9133, newLatestDate 7/1/1850 12:00:00 AM, delta not null: True
3/5/2009 12:06:32 PM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges started.
3/5/2009 12:06:32 PM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges finished.
3/5/2009 12:06:32 PM <refresh>: [GUIClientWorkerThread:4384] Applying server delta to the server-synched repository
3/5/2009 12:06:32 PM <refresh>: [GUIClientWorkerThread:4384] Done updating tree cache with pending changes. ServerReposRevID: 9133 PendingChangeRevID: 9133
3/5/2009 12:06:32 PM <refresh>: [GUIClientWorkerThread:4384] Repository.Update finished, calling SaveRepositoryIfNothingOnDisk()
3/5/2009 12:06:32 PM <refresh>: [GUIClientWorkerThread:4384] SaveIfNothingOnDisk: not saving
3/5/2009 12:06:32 PM <refresh>: [GUIClientWorkerThread:4384] Refreshing working folder associations from disk
3/5/2009 12:06:32 PM <refresh>: [GUIClientWorkerThread:4384] Refreshing all change set items without notify
3/5/2009 12:06:32 PM <refresh>: [GUIClientWorkerThread:4384] Calling UpdateKnownChanges_RefreshKnown with notify
3/5/2009 12:06:32 PM <refresh>: [GUIClientWorkerThread:4384] Calling NotifyTreeStructureChanged
3/5/2009 12:06:32 PM <refresh>: [GUIClientWorkerThread:4384] Refresh finished
3/5/2009 12:06:32 PM <get>: [GUIClientWorkerThread:4384] ProcessGetFileRequests started
3/5/2009 12:06:32 PM <get>: [GUIClientWorkerThread:4384] UpdateThread started
3/5/2009 12:06:32 PM <get>: [GUIClientWorkerThread:4384] In download loop, tries left: 2
3/5/2009 12:06:32 PM <get>: [GUIClientWorkerThread:4384] Server Request: GetFileInfo path: $/dev/awusb/arch/mips/include/cpu_def.h, request version: <no request>, request base version <no request>, request target objverid: <no request>
3/5/2009 12:06:32 PM <get>: [GUIClientWorkerThread:4384] ProcessGetFileRequests finished
----- Then "Show Differences" on file #2 again -----
----- The GetRepositoryStructure() is < 1 second, but the GetFileInfo() now takes 5 seconds -----
3/5/2009 12:08:24 PM <refresh>: [GUIClientWorkerThread:4384] Refresh started
3/5/2009 12:08:24 PM <refresh>: [GUIClientWorkerThread:4384] delta passed in was null, retrieving one
3/5/2009 12:08:24 PM <refresh>: [GUIClientWorkerThread:4384] calling GetRepositoryStructure(1, 9133, -1, ref, 7/1/1850 12:00:00 AM)
3/5/2009 12:08:24 PM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure started.
3/5/2009 12:08:24 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure started
3/5/2009 12:08:24 PM <refresh>: [GUIClientWorkerThread:4384] Calling client service GetRepositoryStructure(1, 9133, -1, 7/1/1850 12:00:00 AM, ref, ref, ref)
3/5/2009 12:08:42 PM <refresh>: [GUIClientWorkerThread:4384] Client service GetRepositoryStructure returned: dtLatestCheck 7/1/1850 12:00:00 AM, nReturnDestRevision 9133, rd not null True
3/5/2009 12:08:42 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished
3/5/2009 12:08:42 PM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished.
3/5/2009 12:08:42 PM <refresh>: [GUIClientWorkerThread:4384] Serialized CacheMember_LastStructureGetTime
3/5/2009 12:08:42 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure returned: returnedRevision 9133, newLatestDate 7/1/1850 12:00:00 AM, delta not null: True
3/5/2009 12:08:42 PM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges started.
3/5/2009 12:08:42 PM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges finished.
3/5/2009 12:08:42 PM <refresh>: [GUIClientWorkerThread:4384] Applying server delta to the server-synched repository
3/5/2009 12:08:42 PM <refresh>: [GUIClientWorkerThread:4384] Done updating tree cache with pending changes. ServerReposRevID: 9133 PendingChangeRevID: 9133
3/5/2009 12:08:42 PM <refresh>: [GUIClientWorkerThread:4384] Repository.Update finished, calling SaveRepositoryIfNothingOnDisk()
3/5/2009 12:08:42 PM <refresh>: [GUIClientWorkerThread:4384] SaveIfNothingOnDisk: not saving
3/5/2009 12:08:42 PM <refresh>: [GUIClientWorkerThread:4384] Refreshing working folder associations from disk
3/5/2009 12:08:42 PM <refresh>: [GUIClientWorkerThread:4384] Refreshing all change set items without notify
3/5/2009 12:08:42 PM <refresh>: [GUIClientWorkerThread:4384] Calling UpdateKnownChanges_RefreshKnown with notify
3/5/2009 12:08:42 PM <refresh>: [GUIClientWorkerThread:4384] Calling NotifyTreeStructureChanged
3/5/2009 12:08:42 PM <refresh>: [GUIClientWorkerThread:4384] Refresh finished
3/5/2009 12:08:42 PM <get>: [GUIClientWorkerThread:4384] ProcessGetFileRequests started
3/5/2009 12:08:42 PM <get>: [GUIClientWorkerThread:4384] UpdateThread started
3/5/2009 12:08:42 PM <get>: [GUIClientWorkerThread:4384] In download loop, tries left: 2
3/5/2009 12:08:42 PM <get>: [GUIClientWorkerThread:4384] Server Request: GetFileInfo path: $/dev/awusb/arch/mips/include/cpu_def.h, request version: <no request>, request base version <no request>, request target objverid: <no request>
3/5/2009 12:08:42 PM <get>: [GUIClientWorkerThread:4384] ProcessGetFileRequests finished
----- Then "Show Differences" on file #2 yet again -----
----- It takes almost no time -----
3/5/2009 12:08:47 PM <refresh>: [GUIClientWorkerThread:4384] Refresh started
3/5/2009 12:08:47 PM <refresh>: [GUIClientWorkerThread:4384] delta passed in was null, retrieving one
3/5/2009 12:08:47 PM <refresh>: [GUIClientWorkerThread:4384] calling GetRepositoryStructure(1, 9133, -1, ref, 7/1/1850 12:00:00 AM)
3/5/2009 12:08:47 PM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure started.
3/5/2009 12:08:47 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure started
3/5/2009 12:08:47 PM <refresh>: [GUIClientWorkerThread:4384] Calling client service GetRepositoryStructure(1, 9133, -1, 7/1/1850 12:00:00 AM, ref, ref, ref)
3/5/2009 12:08:47 PM <refresh>: [GUIClientWorkerThread:4384] Client service GetRepositoryStructure returned: dtLatestCheck 7/1/1850 12:00:00 AM, nReturnDestRevision 9133, rd not null True
3/5/2009 12:08:47 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished
3/5/2009 12:08:47 PM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished.
3/5/2009 12:08:47 PM <refresh>: [GUIClientWorkerThread:4384] Serialized CacheMember_LastStructureGetTime
3/5/2009 12:08:47 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure returned: returnedRevision 9133, newLatestDate 7/1/1850 12:00:00 AM, delta not null: True
3/5/2009 12:08:47 PM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges started.
3/5/2009 12:08:47 PM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges finished.
3/5/2009 12:08:47 PM <refresh>: [GUIClientWorkerThread:4384] Applying server delta to the server-synched repository
3/5/2009 12:08:47 PM <refresh>: [GUIClientWorkerThread:4384] Done updating tree cache with pending changes. ServerReposRevID: 9133 PendingChangeRevID: 9133
3/5/2009 12:08:47 PM <refresh>: [GUIClientWorkerThread:4384] Repository.Update finished, calling SaveRepositoryIfNothingOnDisk()
3/5/2009 12:08:47 PM <refresh>: [GUIClientWorkerThread:4384] SaveIfNothingOnDisk: not saving
3/5/2009 12:08:47 PM <refresh>: [GUIClientWorkerThread:4384] Refreshing working folder associations from disk
3/5/2009 12:08:47 PM <refresh>: [GUIClientWorkerThread:4384] Refreshing all change set items without notify
3/5/2009 12:08:47 PM <refresh>: [GUIClientWorkerThread:4384] Calling UpdateKnownChanges_RefreshKnown with notify
3/5/2009 12:08:47 PM <refresh>: [GUIClientWorkerThread:4384] Calling NotifyTreeStructureChanged
3/5/2009 12:08:47 PM <refresh>: [GUIClientWorkerThread:4384] Refresh finished
3/5/2009 12:08:47 PM <get>: [GUIClientWorkerThread:4384] ProcessGetFileRequests started
3/5/2009 12:08:47 PM <get>: [GUIClientWorkerThread:4384] UpdateThread started
3/5/2009 12:08:47 PM <get>: [GUIClientWorkerThread:4384] In download loop, tries left: 2
3/5/2009 12:08:47 PM <get>: [GUIClientWorkerThread:4384] Server Request: GetFileInfo path: $/dev/awusb/arch/mips/include/cpu_def.h, request version: <no request>, request base version <no request>, request target objverid: <no request>
3/5/2009 12:08:47 PM <get>: [GUIClientWorkerThread:4384] ProcessGetFileRequests finished
----- Then another "Show Differences" on the original file #1 -----
3/5/2009 12:08:51 PM <refresh>: [GUIClientWorkerThread:4384] Refresh started
3/5/2009 12:08:51 PM <refresh>: [GUIClientWorkerThread:4384] delta passed in was null, retrieving one
3/5/2009 12:08:51 PM <refresh>: [GUIClientWorkerThread:4384] calling GetRepositoryStructure(1, 9133, -1, ref, 7/1/1850 12:00:00 AM)
3/5/2009 12:08:51 PM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure started.
3/5/2009 12:08:51 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure started
3/5/2009 12:08:51 PM <refresh>: [GUIClientWorkerThread:4384] Calling client service GetRepositoryStructure(1, 9133, -1, 7/1/1850 12:00:00 AM, ref, ref, ref)
3/5/2009 12:08:51 PM <refresh>: [GUIClientWorkerThread:4384] Client service GetRepositoryStructure returned: dtLatestCheck 7/1/1850 12:00:00 AM, nReturnDestRevision 9133, rd not null True
3/5/2009 12:08:51 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished
3/5/2009 12:08:51 PM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished.
3/5/2009 12:08:51 PM <refresh>: [GUIClientWorkerThread:4384] Serialized CacheMember_LastStructureGetTime
3/5/2009 12:08:51 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure returned: returnedRevision 9133, newLatestDate 7/1/1850 12:00:00 AM, delta not null: True
3/5/2009 12:08:51 PM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges started.
3/5/2009 12:08:51 PM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges finished.
3/5/2009 12:08:51 PM <refresh>: [GUIClientWorkerThread:4384] Applying server delta to the server-synched repository
3/5/2009 12:08:51 PM <refresh>: [GUIClientWorkerThread:4384] Done updating tree cache with pending changes. ServerReposRevID: 9133 PendingChangeRevID: 9133
3/5/2009 12:08:51 PM <refresh>: [GUIClientWorkerThread:4384] Repository.Update finished, calling SaveRepositoryIfNothingOnDisk()
3/5/2009 12:08:51 PM <refresh>: [GUIClientWorkerThread:4384] SaveIfNothingOnDisk: not saving
3/5/2009 12:08:51 PM <refresh>: [GUIClientWorkerThread:4384] Refreshing working folder associations from disk
3/5/2009 12:08:51 PM <refresh>: [GUIClientWorkerThread:4384] Refreshing all change set items without notify
3/5/2009 12:08:51 PM <refresh>: [GUIClientWorkerThread:4384] Calling UpdateKnownChanges_RefreshKnown with notify
3/5/2009 12:08:51 PM <refresh>: [GUIClientWorkerThread:4384] Calling NotifyTreeStructureChanged
3/5/2009 12:08:51 PM <refresh>: [GUIClientWorkerThread:4384] Refresh finished
3/5/2009 12:08:51 PM <get>: [GUIClientWorkerThread:4384] ProcessGetFileRequests started
3/5/2009 12:08:51 PM <get>: [GUIClientWorkerThread:4384] UpdateThread started
3/5/2009 12:08:51 PM <get>: [GUIClientWorkerThread:4384] In download loop, tries left: 2
3/5/2009 12:08:51 PM <get>: [GUIClientWorkerThread:4384] Server Request: GetFileInfo path: $/dev/awusb/arch/mips/include/exception.h, request version: <no request>, request base version <no request>, request target objverid: <no request>
3/5/2009 12:08:51 PM <get>: [GUIClientWorkerThread:4384] ProcessGetFileRequests finished
----- Another "auto refresh" begins, this one will take 18 seconds -----
3/5/2009 12:12:47 PM <refresh>: [GUIClientWorkerThread:4384] Auto refresh begun
3/5/2009 12:12:47 PM <refresh>: [GUIClientWorkerThread:4384] Refresh started
3/5/2009 12:12:47 PM <refresh>: [GUIClientWorkerThread:4384] delta passed in was null, retrieving one
3/5/2009 12:12:47 PM <refresh>: [GUIClientWorkerThread:4384] calling GetRepositoryStructure(1, 9133, -1, ref, 7/1/1850 12:00:00 AM)
3/5/2009 12:12:47 PM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure started.
3/5/2009 12:12:47 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure started
3/5/2009 12:12:47 PM <refresh>: [GUIClientWorkerThread:4384] Calling client service GetRepositoryStructure(1, 9133, -1, 7/1/1850 12:00:00 AM, ref, ref, ref)
3/5/2009 12:13:05 PM <refresh>: [GUIClientWorkerThread:4384] Client service GetRepositoryStructure returned: dtLatestCheck 7/1/1850 12:00:00 AM, nReturnDestRevision 9133, rd not null True
3/5/2009 12:13:05 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished
3/5/2009 12:13:05 PM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished.
3/5/2009 12:13:05 PM <refresh>: [GUIClientWorkerThread:4384] Serialized CacheMember_LastStructureGetTime
3/5/2009 12:13:05 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure returned: returnedRevision 9133, newLatestDate 7/1/1850 12:00:00 AM, delta not null: True
3/5/2009 12:13:05 PM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges started.
3/5/2009 12:13:05 PM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges finished.
3/5/2009 12:13:05 PM <refresh>: [GUIClientWorkerThread:4384] Applying server delta to the server-synched repository
3/5/2009 12:13:05 PM <refresh>: [GUIClientWorkerThread:4384] Done updating tree cache with pending changes. ServerReposRevID: 9133 PendingChangeRevID: 9133
3/5/2009 12:13:05 PM <refresh>: [GUIClientWorkerThread:4384] Repository.Update finished, calling SaveRepositoryIfNothingOnDisk()
3/5/2009 12:13:05 PM <refresh>: [GUIClientWorkerThread:4384] SaveIfNothingOnDisk: not saving
3/5/2009 12:13:05 PM <refresh>: [GUIClientWorkerThread:4384] Refreshing working folder associations from disk
3/5/2009 12:13:05 PM <refresh>: [GUIClientWorkerThread:4384] Refreshing all change set items without notify
3/5/2009 12:13:05 PM <refresh>: [GUIClientWorkerThread:4384] Calling UpdateKnownChanges_RefreshKnown with notify
3/5/2009 12:13:05 PM <refresh>: [GUIClientWorkerThread:4384] Calling NotifyTreeStructureChanged
3/5/2009 12:13:05 PM <refresh>: [GUIClientWorkerThread:4384] Refresh finished
3/5/2009 12:13:05 PM <refresh>: [GUIClientWorkerThread:4384] Auto refresh finished
----- Another "auto refresh" begins, this one will take 17 seconds -----
3/5/2009 12:22:48 PM <refresh>: [GUIClientWorkerThread:4384] Auto refresh begun
3/5/2009 12:22:48 PM <refresh>: [GUIClientWorkerThread:4384] Refresh started
3/5/2009 12:22:48 PM <refresh>: [GUIClientWorkerThread:4384] delta passed in was null, retrieving one
3/5/2009 12:22:48 PM <refresh>: [GUIClientWorkerThread:4384] calling GetRepositoryStructure(1, 9133, -1, ref, 7/1/1850 12:00:00 AM)
3/5/2009 12:22:48 PM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure started.
3/5/2009 12:22:48 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure started
3/5/2009 12:22:48 PM <refresh>: [GUIClientWorkerThread:4384] Calling client service GetRepositoryStructure(1, 9133, -1, 7/1/1850 12:00:00 AM, ref, ref, ref)
3/5/2009 12:23:05 PM <refresh>: [GUIClientWorkerThread:4384] Client service GetRepositoryStructure returned: dtLatestCheck 7/1/1850 12:00:00 AM, nReturnDestRevision 9133, rd not null True
3/5/2009 12:23:05 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished
3/5/2009 12:23:05 PM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished.
3/5/2009 12:23:05 PM <refresh>: [GUIClientWorkerThread:4384] Serialized CacheMember_LastStructureGetTime
3/5/2009 12:23:05 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure returned: returnedRevision 9133, newLatestDate 7/1/1850 12:00:00 AM, delta not null: True
3/5/2009 12:23:05 PM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges started.
3/5/2009 12:23:05 PM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges finished.
3/5/2009 12:23:05 PM <refresh>: [GUIClientWorkerThread:4384] Applying server delta to the server-synched repository
3/5/2009 12:23:05 PM <refresh>: [GUIClientWorkerThread:4384] Done updating tree cache with pending changes. ServerReposRevID: 9133 PendingChangeRevID: 9133
3/5/2009 12:23:05 PM <refresh>: [GUIClientWorkerThread:4384] Repository.Update finished, calling SaveRepositoryIfNothingOnDisk()
3/5/2009 12:23:05 PM <refresh>: [GUIClientWorkerThread:4384] SaveIfNothingOnDisk: not saving
3/5/2009 12:23:05 PM <refresh>: [GUIClientWorkerThread:4384] Refreshing working folder associations from disk
3/5/2009 12:23:05 PM <refresh>: [GUIClientWorkerThread:4384] Refreshing all change set items without notify
3/5/2009 12:23:05 PM <refresh>: [GUIClientWorkerThread:4384] Calling UpdateKnownChanges_RefreshKnown with notify
3/5/2009 12:23:05 PM <refresh>: [GUIClientWorkerThread:4384] Calling NotifyTreeStructureChanged
3/5/2009 12:23:05 PM <refresh>: [GUIClientWorkerThread:4384] Refresh finished
3/5/2009 12:23:05 PM <refresh>: [GUIClientWorkerThread:4384] Auto refresh finished
----- Another "auto refresh" begins, this one will take 17 seconds -----
3/5/2009 12:32:48 PM <refresh>: [GUIClientWorkerThread:4384] Auto refresh begun
3/5/2009 12:32:48 PM <refresh>: [GUIClientWorkerThread:4384] Refresh started
3/5/2009 12:32:48 PM <refresh>: [GUIClientWorkerThread:4384] delta passed in was null, retrieving one
3/5/2009 12:32:48 PM <refresh>: [GUIClientWorkerThread:4384] calling GetRepositoryStructure(1, 9133, -1, ref, 7/1/1850 12:00:00 AM)
3/5/2009 12:32:48 PM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure started.
3/5/2009 12:32:48 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure started
3/5/2009 12:32:48 PM <refresh>: [GUIClientWorkerThread:4384] Calling client service GetRepositoryStructure(1, 9133, -1, 7/1/1850 12:00:00 AM, ref, ref, ref)
3/5/2009 12:33:05 PM <refresh>: [GUIClientWorkerThread:4384] Client service GetRepositoryStructure returned: dtLatestCheck 7/1/1850 12:00:00 AM, nReturnDestRevision 9133, rd not null True
3/5/2009 12:33:05 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished
3/5/2009 12:33:05 PM <connection>: [GUIClientWorkerThread:4384] GetRepositoryStructure finished.
3/5/2009 12:33:05 PM <refresh>: [GUIClientWorkerThread:4384] Serialized CacheMember_LastStructureGetTime
3/5/2009 12:33:05 PM <refresh>: [GUIClientWorkerThread:4384] GetRepositoryStructure returned: returnedRevision 9133, newLatestDate 7/1/1850 12:00:00 AM, delta not null: True
3/5/2009 12:33:05 PM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges started.
3/5/2009 12:33:05 PM <connection>: [GUIClientWorkerThread:4384] GetCheckOutListChanges finished.
3/5/2009 12:33:05 PM <refresh>: [GUIClientWorkerThread:4384] Applying server delta to the server-synched repository
3/5/2009 12:33:05 PM <refresh>: [GUIClientWorkerThread:4384] Done updating tree cache with pending changes. ServerReposRevID: 9133 PendingChangeRevID: 9133
3/5/2009 12:33:05 PM <refresh>: [GUIClientWorkerThread:4384] Repository.Update finished, calling SaveRepositoryIfNothingOnDisk()
3/5/2009 12:33:05 PM <refresh>: [GUIClientWorkerThread:4384] SaveIfNothingOnDisk: not saving
3/5/2009 12:33:05 PM <refresh>: [GUIClientWorkerThread:4384] Refreshing working folder associations from disk
3/5/2009 12:33:05 PM <refresh>: [GUIClientWorkerThread:4384] Refreshing all change set items without notify
3/5/2009 12:33:05 PM <refresh>: [GUIClientWorkerThread:4384] Calling UpdateKnownChanges_RefreshKnown with notify
3/5/2009 12:33:05 PM <refresh>: [GUIClientWorkerThread:4384] Calling NotifyTreeStructureChanged
3/5/2009 12:33:05 PM <refresh>: [GUIClientWorkerThread:4384] Refresh finished
3/5/2009 12:33:05 PM <refresh>: [GUIClientWorkerThread:4384] Auto refresh finished

[Beth]

Some weird dates are showing here: newLatestDate 7/1/1850 12:00:00 . Check your client side time and your server. What check-in dates to items show in your repository?

[stevek2]

I thought that date was strange, too -- but both my client and server have the correct time and are within a second of each other, and a file I just checked in today shows the correct date & time for Local Date, Remote Date, and Modified Date.

[Beth]

Well, after doing some digging, the date appears to not be causing the issue I think. I'm digging for a few more ideas.

Could you put your server logging into debug mode? Once you save the setting change in the Vault admin web page, you will need to perform an iisreset by going to Start - Run and typing iisreset. Then do the same thing you did with the first post that shows the slowdown. Line up what happens on the client with what happens on the server. Could you post the data, or attach it, or send it in an email? If you email, send it to support at sourcegear.com (attn: Beth) with a link to this forum thread.

Also, could you open your GUI client, go to Help - Technical Support and post the information from there? That will tell me a little more about your environment.

[stevek2]

I've put the server into debug logging mode, and attached the two log files and the tech support info requested. The correlated 18-second delay occurs at 1:58:22pm in the client log and 1:58:24pm in the server log.

[jeremy_sg]

Here's what the client said:

Code: Select all

3/23/2009 1:58:22 PM <refresh>: [GUIClientWorkerThread:5752] Calling client service GetRepositoryStructure(1, 9403, -1, 7/1/1850 12:00:00 AM, ref, ref, ref)
3/23/2009 1:58:40 PM <refresh>: [GUIClientWorkerThread:5752] Client service GetRepositoryStructure returned: dtLatestCheck 7/1/1850 12:00:00 AM, nReturnDestRevision 9403, rd not null True

The client log says that all 18 seconds were spent waiting on the server.

Here's what the server said:

Code: Select all

3/23/2009 1:58:24 PM	ASMX: GetRepositoryStructure started.
3/23/2009 1:58:24 PM	Getting repository Structure-> Rep ID: 1 Base: 9403 Target: -1
3/23/2009 1:58:24 PM	DB: GetUserRepositoryLastChange started.
3/23/2009 1:58:24 PM	DB: GetUserRepositoryLastChange finished.
3/23/2009 1:58:24 PM	DB: GetLatestRepositoryInfo started.
3/23/2009 1:58:24 PM	DB: GetLatestRepositoryInfo finished.
3/23/2009 1:58:24 PM	TreeManager: cache matches repository revision and folder security hasn't changed.  Returning cached tree, revID 9403
3/23/2009 1:58:24 PM	DB: GetLastTreeSecurityChange started.
3/23/2009 1:58:24 PM	DB: GetLastTreeSecurityChange finished.
3/23/2009 1:58:24 PM	VaultServiceAPI::GetRepositoryTreeDelta() UserID:2 RepID:1 Base:9403 Target:9403  Calling VaultRepUtil.DiffRepTrees() - in-memory tree diff.
3/23/2009 1:58:24 PM	ASMX: GetRepositoryStructure finished.

The server log says that it didn't get a request until second number 4, and returned a value in less than a second. The two machine clocks are not more than a second off (you can tell by matching the Login Finished in the client a server logs at 1:54:20). We've had reports of slowdowns when resuming connectivity before, The other reports were on 64 bit clients. Is that the case for you? Are you running the 64 bit server install?

[stevek2]

I am using the GUI client on Vista SP1 x64. The server is a Win2003 x64 machine, with the Vault64 4.1.3 server installed.

[jeremy_sg]

We honestly don't have a true solution to this problem yet, but I can recommend a workaround. Decrease your AutoRefresh time. (Tools->Options->General). More frequent refreshes will prevent the error.

Using a network monitor such as WireShark might help narrow down the problems, and I would very much like to see that data to help us determine the cause of this problem with 64bit machines.