Merge - Adding items to your pending change set forever

asills · Post by **asills** » Wed Oct 12, 2005 8:51 am

So I've been doing a few merges lately and they've been relatively unbearable. I go through the wizard and everything happens quickly (get, compare, merge) then when it gets to the final step "Adding items to your pending change set" it takes a ridiculous amount of time to complete.

The UI stops responding and I just let it sit for a few minutes. Wondering why a merge of 4 existing files and 1 new file has been taking 5+ minutes to "add items to my pending change set" I open task manager which shows VaultGUIClient.exe varying between 0 and 14% CPU usage continually (with the server at 0). Waiting another 5 or so minutes and it finally finishes.

My basic question is what is happening in this step to take 10 minutes? Could there be something weird with the size of my repository or the amount of history? Is this normal? Sometimes this last step is quick but on these projects I'm merging (which happen to be the oldest projects we have, 3+ years old with a huge history) are really slow on this last step.

asills · Post by **asills** » Wed Oct 12, 2005 9:14 am

I enabled logging and did a merge that had only a single file from a single folder. I have nothing in my change set except 3 other merges for a total of 9 modified files and 3 added files (all from the same $/Branches/R&D folder).

Source:
$/Branches/R & D - Worfklow Service Providers/Globeranger.Event.Workflow.Designer.App

Target:
$/Event/Source/Globeranger.Event.Workflow.Designer.App

Only one file in the root changed. Note the ONLY thing I did with the GUI client was login then merge. I stupidly enabled stack traces on my log file so it's now 21MB (and didn't exist before I did this) so it's a bit too large to attach, but this is what I see in it (sorry, really long):

10/12/2005 9:57:53 AM <wf>: [GUIClientWorkerThread:4352] wf V:\vss_plat2\Branches\R & D - Workflow Service Provider\Globeranger.Event.Workflow.Designer.App mutex locked
10/12/2005 9:57:53 AM <mutex>: [GUIClientWorkerThread:4352] Released mutex 988
10/12/2005 9:57:53 AM <wf>: [GUIClientWorkerThread:4352] wf V:\vss_plat2\Branches\R & D - Workflow Service Provider\Globeranger.Event.Workflow.Designer.App mutex released
10/12/2005 9:57:53 AM <wf>: [GUIClientWorkerThread:4352] wf for V:\vss_plat2\Branches\R & D - Workflow Service Provider\Globeranger.Event.Workflow.Designer.App created
10/12/2005 9:57:58 AM <mutex>: [GUIClientWorkerThread:4352] Created mutex 504
10/12/2005 9:57:58 AM <mutex>: [GUIClientWorkerThread:4352] Took mutex 504
10/12/2005 9:57:58 AM <wf>: [GUIClientWorkerThread:4352] wf V:\vss_plat2\Event\Source\Globeranger.Event.Workflow.Designer.App mutex locked
10/12/2005 9:57:58 AM <mutex>: [GUIClientWorkerThread:4352] Released mutex 504
10/12/2005 9:57:58 AM <wf>: [GUIClientWorkerThread:4352] wf V:\vss_plat2\Event\Source\Globeranger.Event.Workflow.Designer.App mutex released
10/12/2005 9:57:58 AM <wf>: [GUIClientWorkerThread:4352] wf for V:\vss_plat2\Event\Source\Globeranger.Event.Workflow.Designer.App created
...
10/12/2005 9:58:00 AM <wf>: [GUIClientWorkerThread:4352] wf V:\vss_plat2\Event\Source\Globeranger.Event.Workflow.Designer.App\Skins mutex locked
...
10/12/2005 9:58:00 AM <wf>: [GUIClientWorkerThread:4352] wf V:\vss_plat2\Event\Source\Globeranger.Event.Workflow.Designer.App\Skins mutex released
... (a LOT)
10/12/2005 9:58:18 AM <get>: [GUIClientWorkerThread:4352] Server Response: GetFileInfo request path: Globeranger.Event.Workflow.Designer.App/ProjectCanvasForm.cs, response status: 1590, response version: 135, response objverid: 991508, response objverid: 3707461140
10/12/2005 9:58:18 AM <get>: [GUIClientWorkerThread:4352] Creating file download stream
10/12/2005 9:58:18 AM <connection>: [GUIClientWorkerThread:4352] GetDownloadFileStream started.
10/12/2005 9:58:18 AM <connection>: [GUIClientWorkerThread:4352] GetDownloadFileStream finished.
10/12/2005 9:58:18 AM <get>: [GUIClientWorkerThread:4352] File download stream created
10/12/2005 9:58:18 AM <connection>: [GUIClientWorkerThread:4352] ReadDownloadFileFromStream started.
...
10/12/2005 9:58:18 AM <connection>: [GUIClientWorkerThread:4352] EndDownloadFiles started.
... (a LOT)
10/12/2005 9:58:22 AM <checkoutlist>: [GUIClientWorkerThread:4352] Path $/Branches/IRIS.AleComponentsEP/Globeranger.Core.UI.EventMonitor/UserControlChartGraph.resx, User sjaganathan, LockType 1, Hostname gr100050/globeranger.com.pvt, LocalPath V:\vss_plat2\Core\Source\Globeranger.Core.UI.EventMonitor\UserControlChartGraph.resx, LockedWhen 5/18/2005 11:32:52 AM, MiscInfo
... (a LOT)
10/12/2005 9:58:22 AM <checkoutlist>: [GUIClientWorkerThread:4352]
Path
$/Playground/sjaganathan/Globeranger.ExpansionPacks.Ale.Palletizer.Workflow/Runtime/PalletCommands.cs, User sjaganathan, LockType 1, Hostname gr100050/globeranger.com.pvt, LocalPath V:\vss_plat2\Playground\IRIS\Globeranger.ExpansionPacks.Ale.Palletizer.Workflow\Runtime\PalletCommands.cs, LockedWhen 8/5/2005 4:17:03 PM, MiscInfo
... (a LOT)
10/12/2005 9:58:22 AM <checkoutlist>: [GUIClientWorkerThread:4352] Path $/iMotion/Source/iMotion.BinaryDeviceAdapter.Installs/MergeModules/iMotionGlobeRangerInputOutputLineListenerAdapter_v1.0.0/iMotionGlobeRangerInputOutputLineListenerAdapter_v1.0.0/ISLocalRadioButton.idt, User epearson, LockType 2, Hostname gr100044/globeranger.com.pvt, LocalPath V:\vss_plat2\iMotion\Source\iMotion.BinaryDeviceAdapter.Installs\MergeModules\iMotionGlobeRangerInputOutputLineListenerAdapter_v1.0.0\iMotionGlobeRangerInputOutputLineListenerAdapter_v1.0.0\ISLocalRadioButton.idt, LockedWhen 9/22/2005 12:53:08 PM, MiscInfo

--

So the first part is obviously it comparing the two sets of files and retrieving them. Then it uploads some files. Then it starts looking at files all over my repository with those <checkoutlist> entries (my box is not gr100050). My log file is 47MB now so I don't doubt it is taking a look at just about everything in this repository.

asills · Post by **asills** » Wed Oct 12, 2005 9:17 am

Oh and there's roughly 800 checkouts in this repository right now (if that helps any).

dan · Post by **dan** » Wed Oct 12, 2005 11:59 am

How many items are in your pending change set?

Also, which version of Vault are you running? We made some speed ups to pending change set processing and scanning in later 3.1.x releases so they might help if you are on an earlier release.

asills · Post by **asills** » Wed Oct 12, 2005 12:08 pm

When I started I had zero items in my pending change set. The first merge took ~8 minutes to complete at 0. The rest took about the same amount and my pending change set count went up to 10.

My Vault version is 3.1.0 (3494) on both the client and server.

dan · Post by **dan** » Wed Oct 12, 2005 12:21 pm

Oops - I meant to say later 3.0.x releases, so what you have should be sufficient.

This is likely something related to your repository or your setup, as this is not normal behavior. This isn't to say it isn't a Vault problem, just that it seems to manifest itself for you setup.

One thing to try: If you login as yourself on a different machine and do the same thing, are there any differences?

ericsink · Post by **ericsink** » Wed Oct 12, 2005 12:46 pm

There is a section of your client log file I would like to see. Does your client log file have lines which look like the following?

Code: Select all

Before: Execute
(maybe some other stuff)
After: Execute
(maybe some other stuff)
Before: UpdateKnownChanges_All
(maybe some other stuff)
After: UpdateKnownChanges_All

Note that each line will prefixed with the usual stuff you see in the client log, including probably the word "mergebranches".

asills · Post by **asills** » Wed Oct 12, 2005 12:52 pm

Like I said I had the stack traces on so the file is huge. Here are the specific lines you requested along with the line number in the file I found them at.

line 80110
10/12/2005 9:58:23 AM <mergebranches>: [GUIClientWorkerThread:4352] Before: Execute
line 80577
10/12/2005 9:58:23 AM <mergebranches>: [GUIClientWorkerThread:4352] After: Execute
line 80712
10/12/2005 9:58:23 AM <mergebranches>: [GUIClientWorkerThread:4352] Before: UpdateKnownChanges_All
line 674173
10/12/2005 10:04:36 AM <mergebranches>: [GUIClientWorkerThread:4352] After: UpdateKnownChanges_All

There's about 590,000 lines in between the last before and after.

Dan, I'm sorry I haven't gotten a chance to do what you requested yet.

asills · Post by **asills** » Wed Oct 12, 2005 2:01 pm

Okay, I went to another developer's machine and tried it under my login and it was incredibly fast (every file in the repository had an Unknown status).

I undid and logged in under his login (where very few files have an Unknown status like mine) and experienced the same problem.

ericsink · Post by **ericsink** » Thu Oct 13, 2005 9:21 am

OK. I think I understand what's happening, but I'd like a bit more info. Any chance I could have the whole client log file?

If so, email me to make arrangements to transfer the file. If you compress it, it might get through as an email attachment.

eric@sourcegear.com

Thanks.

asills · Post by **asills** » Thu Oct 13, 2005 9:27 am

Sent.

ericsink · Post by **ericsink** » Thu Oct 13, 2005 9:47 am

OK. I think I know what's wrong.

The problem causes no actual harm, other than the fact that it takes an absurdly long time to do something so simple.

I hope to get a fix into an upcoming 3.1.x maintenance release, but it would be imprudent for me to promise that just yet. This is one of those fixes where it will take me 3 minutes to make the fix and 3 days to be absolutely certain that I didn't make things worse.

Thanks.

asills · Post by **asills** » Tue Nov 01, 2005 3:59 pm

So the latest release contains the fix for this?

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

ericsink · Post by **ericsink** » Tue Nov 01, 2005 4:45 pm

asills wrote:So the latest release contains the fix for this?

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

Yes.

lbauer · Post by **lbauer** » Tue Nov 01, 2005 4:45 pm

According to our bug database, this was fixed for 3.1.3.