PowerBuilder Performance issues

[jwolbeck]

Using the Debug setting I have identified some potential performance issues.

1) Opening PowerBuilder for the first time results in check status of the whole folder the Target file is located. In our case there is 400-500 objects that are checked for no reason (Most are image files). Can't this status check only get the Target file(s) status and open pbl? There certainly is no reason to get status on image files that are not inside of the pbls.

2) Checking out an object results in refresh of the entire pbl. I understand the need to status check the object I am checking out but why the entire pbl? Most of the time I open a pbl and wait for refresh status, then checkout object and have to wait for an entire refresh again.

3) Saving in PowerBuilder results in status check of the Targets folder then a status check of the entire pbl? Why does AgentSVN need to do anything when I save and I really am confused why my Target folder needs to be refreshed? Note I am not referring to doing a check-in but simply saving as I am working.

4) Expanding a PBL after PowerBuilder is idle past the "Status Refresh Rate" in the Workspace Properties. When expanding the PBL it refreshes all objects in the PBL as expected but once that finishes an hourglass shows and it appears to refresh status on everything in the Target folder. It also refreshes all open PBLs but that might be intended behavior. Again another instance where maybe only a refresh of the actual Target object pbt is required.

These are just 4 examples I took the time to document. Check-in, undo checkout etc all seem to do this unnecessary refresh status. These issues maybe do not seem like a big deal in smaller projects but we have close to 7,000 objects in one Target alone so the extra 30-45 seconds for every seemingly unnecessary refresh is frustrating and adds up throughout the day.

I will send you the 4 log files for my examples above. Each one I cleared the log file prior with debug enabled.

[jussij]

The first thing you need to check is to make sure that in normal operations the Agent SVN debug option is off otherwise things will run very slowly.

You also need to make sure the Agent SVN cache status option is on.

You could also try turning off the Agent SVN update status option. I would not expect that to not make much difference and for best results it should be on.

Finally, also try out the suggestions made here: viewtopic.php?f=11&t=7486

If none of those help then the next question would be who is instigating the refresh as I suspect it might in fact be PowerBuilder asking for these refresh requests.

I don't use PowerBuilder so my only real world test is Visual Studio and for that IDE I see no appreciable slowdown.

As a comparison consider the Zeus IDE software which is written in C/C++ using Visual Studio and is held in source control using Subversion and Agent SVN.

That Visual Studio solution is made up a dozen or so projects which in total consist of about 600-700 files and the entire solution is under source control.

workspace.png (14.81 KiB) Viewed 40819 times

1) Opening PowerBuilder for the first time results in check status of the whole folder the Target file is located. In our case there is 400-500 objects that are checked for no reason (Most are image files).

Opening that solution in Visual Studio happens in about 4-5 seconds and while that is happening I can see Agent SVN is being called to refresh the status.

2) Checking out an object results in refresh of the entire pbl.

Checking out a file takes about 1.5 seconds.

Checking in a file takes about 1.5 seconds.

Visual Studio also has an option to do a full source control status refresh and that action takes about 9 seconds for that 600-700 file solution.

4) Expanding a PBL after PowerBuilder is idle past the "Status Refresh Rate" in the Workspace Properties.

If I expand one of the Visual Studio project nodes, for the first time it does result in about a half second delay.

workspace_expand.png (16.08 KiB) Viewed 40819 times

Now I am not sure if is because of Agent SVN or Visual Studio but it is still only half a second and only for the first expansion.

When expanding the PBL it refreshes all objects in the PBL as expected but once that finishes an hourglass shows and it appears to refresh status on everything in the Target folder.

This to me suggests this is a PBL issue as it looks like PBL is doing superfluous status request.

In all cases PBL is always the driver of the request and Agent SVN just performs the tasks asked of it.

I will send you the 4 log files for my examples above. Each one I cleared the log file prior with debug enabled.

I will take a look at them and see if highlights anything.

Cheers Jussi

[jussij]

Looking at the log file for the Open PBL this is what it shows.

The Agent SVN initialize and open completed in less than a second:

Code: Select all

EX1_OpeningPB_AgentSVN.log (17)  [Mon Mar 28 14:21:13 2016] >> SccInitialize: Caller = 'PowerBuilder'
EX1_OpeningPB_AgentSVN.log (23)  [Mon Mar 28 14:21:13 2016] >> SccOpenProject
EX1_OpeningPB_AgentSVN.log (82)  [Mon Mar 28 14:21:13 2016] >> SccOpenProject Complete

As did the SccGetCommandOptions:

Code: Select all

EX1_OpeningPB_AgentSVN.log (84)  [Mon Mar 28 14:21:13 2016] >> SccGetCommandOptions
EX1_OpeningPB_AgentSVN.log (85)  [Mon Mar 28 14:21:13 2016] >> SCC_COMMAND_OPTIONS: Caller = 'PowerBuilder'  ppvOptions = 0
EX1_OpeningPB_AgentSVN.log (86)  [Mon Mar 28 14:21:13 2016] >> SCC_COMMAND_OPTIONS: Support for Advanced options.
EX1_OpeningPB_AgentSVN.log (88)  [Mon Mar 28 14:21:13 2016] >> SccGetCommandOptions
EX1_OpeningPB_AgentSVN.log (90)  [Mon Mar 28 14:21:13 2016] >> SccGetCommandOptions
EX1_OpeningPB_AgentSVN.log (92)  [Mon Mar 28 14:21:13 2016] >> SccGetCommandOptions
EX1_OpeningPB_AgentSVN.log (94)  [Mon Mar 28 14:21:13 2016] >> SccGetCommandOptions
EX1_OpeningPB_AgentSVN.log (96)  [Mon Mar 28 14:21:13 2016] >> SccGetCommandOptions
EX1_OpeningPB_AgentSVN.log (98)  [Mon Mar 28 14:21:13 2016] >> SccGetCommandOptions
EX1_OpeningPB_AgentSVN.log (100) [Mon Mar 28 14:21:13 2016] >> SccGetCommandOptions

The first SccQueryInfoEx for the PHDoc_Core folder completed about 1 second:

Code: Select all

EX1_OpeningPB_AgentSVN.log (102) [Mon Mar 28 14:21:13 2016] >> SccQueryInfoEx
EX1_OpeningPB_AgentSVN.log (103) [Mon Mar 28 14:21:13 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username JustinWolbeck update testscc.txt
EX1_OpeningPB_AgentSVN.log (104) [Mon Mar 28 14:21:13 2016] >> * Directory: c:\PHDoc_Source\CurrentVersion\PHDoc_Core
.... many lines of log file ....
EX1_OpeningPB_AgentSVN.log (151) [Mon Mar 28 14:21:14 2016] >> File: 'testscc.txt'  Status: 0x0

Some 4 seconds later PBL ran a SccQueryInfoEx for the PHDoc_Core\chs\phd_app folder and it completed about fifty two seconds later:

Code: Select all

EX1_OpeningPB_AgentSVN.log (  153) [Mon Mar 28 14:21:18 2016] >> SccQueryInfoEx
EX1_OpeningPB_AgentSVN.log (  154) [Mon Mar 28 14:21:18 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username JustinWolbeck --show-updates --verbose status --depth files --xml .
EX1_OpeningPB_AgentSVN.log (  155) [Mon Mar 28 14:21:18 2016] >> * Directory: c:\PHDoc_Source\CurrentVersion\PHDoc_Core\chs\phd_app\
.... many lines of log file ....
EX1_OpeningPB_AgentSVN.log (20660) [Mon Mar 28 14:22:10 2016] >> File: 'dailies.pbt'  Status: 0x1

Now I suspect a lot of that 52 seconds will be debug time as over 20,000 lines of debug was created by that one call.

If you turn off debugging how long does the project open take to complete

After PBL called the first SccQueryInfoEx it went away to do something for 4 seconds, so I'm assuming the second call would result in a similar, if not longer time delay. So at a minimum 8+ seconds of that startup time is PBL working through the status results return by Agent SVN.

Cheers Jussi

[jussij]

This is the log file for the checkout request.

The actual checkout took 1 second to complete:

Code: Select all

EX2_CheckoutSingleObjectAgentSVN.log ( 2) [Mon Mar 28 14:44:21 2016] >> SccCheckout
EX2_CheckoutSingleObjectAgentSVN.log (18) [Mon Mar 28 14:44:22 2016] >> Result: 0  Status Code: 4107 (0x100B)

That was followed by a SccQueryInfoEx request on the PHDoc_Core\chs\phd_nvo folder and that took 6 seconds to complete.

Code: Select all

EX2_CheckoutSingleObjectAgentSVN.log (  21) [Mon Mar 28 14:44:22 2016] >> SccQueryInfoEx
EX2_CheckoutSingleObjectAgentSVN.log (  22) [Mon Mar 28 14:44:22 2016] >> Loading cache...
EX2_CheckoutSingleObjectAgentSVN.log (  23) [Mon Mar 28 14:44:22 2016] >> Directory: c:\PHDoc_Source\CurrentVersion\PHDoc_Core\chs\phd_nvo\
EX2_CheckoutSingleObjectAgentSVN.log (  24) [Mon Mar 28 14:44:22 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username JustinWolbeck --show-updates --verbose status --depth files --xml .
EX2_CheckoutSingleObjectAgentSVN.log (  25) [Mon Mar 28 14:44:22 2016] >> * Directory: c:\PHDoc_Source\CurrentVersion\PHDoc_Core\chs\phd_nvo\
EX2_CheckoutSingleObjectAgentSVN.log (  26) [Mon Mar 28 14:44:22 2016] >> *     Valid: Yes
EX2_CheckoutSingleObjectAgentSVN.log (  27) [Mon Mar 28 14:44:24 2016] >> Result: 0  Status Code: 0 (0x0)
...... lots of log removed ....
EX2_CheckoutSingleObjectAgentSVN.log (3256) [Mon Mar 28 14:44:28 2016] >> File: 'nvo_pcclidwn.sru'  Status: 0x100B

But again I suspect a lot of that time is caused by the debug output as the actual Subversion call was completed in 2 seconds as shown below:

Code: Select all

EX2_CheckoutSingleObjectAgentSVN.log (  21) [Mon Mar 28 14:44:22 2016] >> SccQueryInfoEx
EX2_CheckoutSingleObjectAgentSVN.log (  22) [Mon Mar 28 14:44:22 2016] >> Loading cache...
EX2_CheckoutSingleObjectAgentSVN.log (  23) [Mon Mar 28 14:44:22 2016] >> Directory: c:\PHDoc_Source\CurrentVersion\PHDoc_Core\chs\phd_nvo\
EX2_CheckoutSingleObjectAgentSVN.log (  24) [Mon Mar 28 14:44:22 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username JustinWolbeck --show-updates --verbose status --depth files --xml .
EX2_CheckoutSingleObjectAgentSVN.log (  25) [Mon Mar 28 14:44:22 2016] >> * Directory: c:\PHDoc_Source\CurrentVersion\PHDoc_Core\chs\phd_nvo\
EX2_CheckoutSingleObjectAgentSVN.log (  26) [Mon Mar 28 14:44:22 2016] >> *     Valid: Yes
EX2_CheckoutSingleObjectAgentSVN.log (  27) [Mon Mar 28 14:44:24 2016] >> Result: 0  Status Code: 0 (0x0)

With the debug output disabled I would expect those two command to run in not much more than the time it takes to connect to Subversion and run the command which will be about 3 to 4 seconds in total.

Cheers Jussi

PS: The log shows that you do have updates enabled (i.e. --show-updates is used) which means the status is fetched from the Subversion server as well as the local working copy. So I suspect if you did turn off that option that 2 second turn around time to get the status off the server would go down to less than a second, but naturally that would mean the actual file status would not be truly reflected.

[jussij]

Looking at the expand log everything seems rather strange.

In that log there is nothing but repeated calls to SccQueryInfoEx.

Code: Select all

EX4_ExpandPBLOverRefreshTimeAgentSVN.log (    2) [Mon Mar 28 16:04:32 2016] >> SccQueryInfoEx
EX4_ExpandPBLOverRefreshTimeAgentSVN.log (    3) [Mon Mar 28 16:04:32 2016] >> SccQueryInfo
... over 170 line removed ....
EX4_ExpandPBLOverRefreshTimeAgentSVN.log (37437) [Mon Mar 28 16:05:18 2016] >> SccQueryInfoEx
EX4_ExpandPBLOverRefreshTimeAgentSVN.log (37438) [Mon Mar 28 16:05:18 2016] >> SccQueryInfo

All up SccQueryInfoEx gets called 88 times

If you look at the first status request that took 3 seconds to go to the server and get the status details:

Code: Select all

[Mon Mar 28 16:04:32 2016] >> SccQueryInfoEx
[Mon Mar 28 16:04:32 2016] >> SccQueryInfo
[Mon Mar 28 16:04:32 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username brianprom --show-updates --verbose status --depth files --xml .
[Mon Mar 28 16:04:32 2016] >> * Directory: C:\PHDoc_Source\PHDoc_V42\PHDoc_Core\chs\phd_elements\
[Mon Mar 28 16:04:32 2016] >> *     Valid: Yes
[Mon Mar 28 16:04:35 2016] >> Result: 0  Status Code: 0 (0x0)

The second one took 2 seconds:

Code: Select all

[Mon Mar 28 16:04:54 2016] >> SccQueryInfoEx
[Mon Mar 28 16:04:54 2016] >> SccQueryInfo
[Mon Mar 28 16:04:54 2016] >> Reloading cache...
[Mon Mar 28 16:04:54 2016] >> Directory: C:\PHDoc_Source\PHDoc_V42\PHDoc_Core\chs\phd_app\
[Mon Mar 28 16:04:54 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username brianprom --show-updates --verbose status --depth files --xml .
[Mon Mar 28 16:04:54 2016] >> * Directory: C:\PHDoc_Source\PHDoc_V42\PHDoc_Core\chs\phd_app\
[Mon Mar 28 16:04:54 2016] >> *     Valid: Yes
[Mon Mar 28 16:04:56 2016] >> Result: 0  Status Code: 0 (0x0)

and so on and so on.

If you add those multiple calls then it is certainly going to take a long time to complete

The big question is why is it calling SccQueryInfoEx 88 times

The other big question is why does that one expand action touch 9 directories as shown below

Code: Select all

EX4_ExpandPBLOverRefreshTimeAgentSVN.log (    5) [Mon Mar 28 16:04:32 2016] >> * Directory: C:\PHDoc_Source\PHDoc_V42\PHDoc_Core\chs\phd_elements\
EX4_ExpandPBLOverRefreshTimeAgentSVN.log (15025) [Mon Mar 28 16:04:54 2016] >> * Directory: C:\PHDoc_Source\PHDoc_V42\PHDoc_Core\chs\phd_app\
EX4_ExpandPBLOverRefreshTimeAgentSVN.log (20166) [Mon Mar 28 16:05:00 2016] >> * Directory: C:\PHDoc_Source\PHDoc_V42\PHDoc_Core\dailies\dailies\
EX4_ExpandPBLOverRefreshTimeAgentSVN.log (24583) [Mon Mar 28 16:05:04 2016] >> * Directory: C:\PHDoc_Source\PHDoc_V42\PHDoc_Core\security\
EX4_ExpandPBLOverRefreshTimeAgentSVN.log (29400) [Mon Mar 28 16:05:08 2016] >> * Directory: C:\PHDoc_Source\PHDoc_V42\PHDoc_Core\services\dequeuer\
EX4_ExpandPBLOverRefreshTimeAgentSVN.log (30062) [Mon Mar 28 16:05:09 2016] >> * Directory: C:\PHDoc_Source\PHDoc_V42\PHDoc_Core\sql center\
EX4_ExpandPBLOverRefreshTimeAgentSVN.log (30106) [Mon Mar 28 16:05:10 2016] >> * Directory: C:\PHDoc_Source\PHDoc_V42\PHDoc_Core\scheduling\scheduling\
EX4_ExpandPBLOverRefreshTimeAgentSVN.log (30690) [Mon Mar 28 16:05:11 2016] >> * Directory: C:\PHDoc_Source\PHDoc_V42\PHDoc_Core\chs\local_app\
EX4_ExpandPBLOverRefreshTimeAgentSVN.log (35287) [Mon Mar 28 16:05:16 2016] >> * Directory: C:\PHDoc_Source\PHDoc_V42\PHDoc_Core\sql center\utilities\

I have no idea why PBL would be doing this

Cheers Jussi

[jwolbeck]

I would agree that the times are exaggerated with debug on. I do not know what a SCC provider is required to do nor do I know how PowerBuilder works let alone the interaction between the two. I do know with Starteam we do not have these performance issues. Starteam also is using a SCC plugin.

There are no issues in Visual Studio (Our VS projects are much much smaller though) so lets not compare apples to oranges.

Lets just start with EX1: Are you saying that PowerBuilder asked AgentSVN to update status on the couple hundred image files? These files are not in PowerBuilder and are seemingly the reason for the majority of these performance issues. I am not sure what exactly PowerBuilder requested the plugin to update or if that request asked for the whole directory or simply a list of files.

I do know your code is creating the below command that results in the entire PBL being refreshed including objects not part of the Workspace.

Code: Select all

[Mon Mar 28 14:21:14 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username usr --show-updates --verbose status --depth files --xml .

This is just speculation since I cannot debug your plugin but I would assume PowerBuilder on open is asking SccQueryInfoEx for only the pbt file. Logically to me that is all that is needed. Maybe a single file is being passed in to refresh but your code is instead refreshing the entire folder?

To me if your plugin was no respecting requests for a single file to have its status refreshed that would explain all of the issues I outlined. I am not sure where the official SCC spec is but this one shows an array of files can be passed in to SccQueryInfo https://msdn.microsoft.com/en-us/library/bb165321.aspx

It is difficult to find information about the SCC API spec and I cannot find good documentation on how PowerBuilder implemented SCC.

[jussij]

I do not know what a SCC provider is required to do

That is spelled out by the MS-SCCI specification and all SccXXX functions shown in the log file are part of that specification.

nor do I know how PowerBuilder works let alone the interaction between the two.

One of the problems is PowerBuilder have their own version of the MS-SCCI specification but it is not publicly documented.

The SccQueryInfoEx is an addition made to the MS-SCCI by PowerBuilder for PowerBuilder but there is no public definition on how it is meant work

I do know with Starteam we do not have these performance issues. Starteam also is using a SCC plugin.

Obviously Starteam knows something more about PowerBuilder than we don't. They might even have the proper definition of the SccQueryInfoEx function

There are no issues in Visual Studio (Our VS projects are much much smaller though) so lets not compare apples to oranges.

The size of the project might be an issues but as I pointed out I have a 700+ file Visual Studio project and I see very little slow down.

I am not sure what exactly PowerBuilder requested the plugin to update or if that request asked for the whole directory or simply a list of files.

All the SccXXX function shown in the log are instances of PowerBuilder calling the plugin, requesting information.

Take your expand issue. PowerBuilder called the SccQueryInfoEx function 88 times asking for information. Why is it doing that

I do know your code is creating the below command that results in the entire PBL being refreshed including objects not part of the Workspace.

Lets consider this small section of the log that you are referring to:

Code: Select all

[Mon Mar 28 14:21:18 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username JustinWolbeck --show-updates --verbose status --depth files --xml .
[Mon Mar 28 14:21:18 2016] >> * Directory: c:\PHDoc_Source\CurrentVersion\PHDoc_Core\chs\phd_app\
[Mon Mar 28 14:21:18 2016] >> *     Valid: Yes
[Mon Mar 28 14:21:20 2016] >> Result: 0  Status Code: 0 (0x0)
[Mon Mar 28 14:21:21 2016] >> *** XML Parsing Started ***
[Mon Mar 28 14:21:21 2016] >>    File XML Details: ---------------------------------------------------------------------
[Mon Mar 28 14:21:21 2016] >>       File Path: upload_g.png
[Mon Mar 28 14:21:21 2016] >>       File Name: upload_g.png
[Mon Mar 28 14:21:21 2016] >>       (WC) Item: normal
[Mon Mar 28 14:21:21 2016] >>      (WC) Props: normal
[Mon Mar 28 14:21:21 2016] >>  Local Revision: 4712
[Mon Mar 28 14:21:21 2016] >>          Author: brianprom
[Mon Mar 28 14:21:21 2016] >> Change Revision: 4015
[Mon Mar 28 14:21:21 2016] >>    Locking Code: ' '
[Mon Mar 28 14:21:21 2016] >>    Local Status:  1 (0x1)  Repo Status: -1 (0xFFFFFFFF)  Final Status: 1 (0x1)  Lock Status: 0 (0x0)

The effective SVN command being run is this:

Code: Select all

svn.exe --show-updates --verbose status --depth files --xml .

Importantly that command is being run in this directory:

Code: Select all

c:\PHDoc_Source\CurrentVersion\PHDoc_Core\chs\phd_app\

The first thing I would do is use the DOS Shell button found in Agent SVN and run that exact same command in the exact same directory to see how long it takes to run.

Now the important thing to consider is the results for the upload_g.png shown above. In particular this output:

Code: Select all

[Mon Mar 28 14:21:21 2016] >>  Local Revision: 4712
[Mon Mar 28 14:21:21 2016] >>          Author: brianprom
[Mon Mar 28 14:21:21 2016] >> Change Revision: 4015

That output clearly shows the image is in the Subversion repo making it part of the project.

That file is in the same subversion local working copy as your other PowerBuilder files.

In other words it is in the same part of the Subversion tree as your PowerBuilder files.

As far as Subversion is concerned it is part of the project.

But this is very easy to change at your end by just turning off the cache option in Agent SVN.

That code is nothing more than Agent SVN caching the status of all the files in the folder by doing one trip to the subversion server, rather than doing one trip to the server for each file.

I would assume PowerBuilder on open is asking SccQueryInfoEx for only the pbt file. Logically to me that is all that is needed.

And that pbt file is in the same folder location in Subversion as all your image files.

To me if your plugin was no respecting requests for a single file to have its status refreshed

Turning off the cache option will make the plug-in work as you want.

Now doing that might indeed speed up this one particular example, but I suspect it will kill the performance for other examples.

All the caching in Agent SVN was specifically added for PowerBuilder to handle it's many thousands of status requests on individual objects.

You could also turn off the update status option and that too will probably give you a massive speed improvement as Agent SVN will no longer be going to the Subversion server to get the file status.

But naturally that means you will only be tracking the status of your files, not changes made by other users

It is difficult to find information about the SCC API spec and I cannot find good documentation on how PowerBuilder implemented SCC.

You have found the MS-SCCI definition: https://msdn.microsoft.com/en-us/library/bb165429.aspx

What you will not find is information on the SccQueryInfoEx function as that is something added by PowerBuilder itself

They mention it here but don't describe it in any detail: http://infocenter.sybase.com/archive/in ... HDAGBB.htm

Cheers Jussi

[jussij]

From this log file that you provided: EX1_OpeningPB_AgentSVN.log

There is this output:

Code: Select all

[Mon Mar 28 14:21:13 2016] >> ===================================================================
[Mon Mar 28 14:21:13 2016] >>        Agent SVN, Version 2.49
[Mon Mar 28 14:21:13 2016] >>        Xidicone P/L  Copyright (c)  2004-2015
[Mon Mar 28 14:21:13 2016] >>        All rights reserved
[Mon Mar 28 14:21:13 2016] >>        http:\\www.zeusedit.com
[Mon Mar 28 14:21:13 2016] >> ===================================================================

That indicates the version you are running is about six release old.

You need to update to the latest 2.55 release!

Cheers Jussi

[jussij]

Using the DOS Shell button found in the Agent SVN configuration utility could you see roughly how long these commands take to run.

You may need to run them two or three times to ensure the time are not effected by caching.

Code: Select all

  Command: svn.exe --show-updates --verbose status --depth files --xml nvo_phdprograms_tv.sru > test.xml
Directory: c:\PHDoc_Source\CurrentVersion\PHDoc_Core\chs\phd_app\

Code: Select all

  Command: svn.exe --show-updates --verbose status --depth files --xml . > test.xml
Directory: c:\PHDoc_Source\CurrentVersion\PHDoc_Core\chs\phd_app\

Code: Select all

Command: svn.exe --show-updates --verbose status --depth files --xml phd_app.pbt > test.xml
Directory: c:\PHDoc_Source\CurrentVersion\PHDoc_Core\

Code: Select all

Command: svn.exe --show-updates --verbose status --depth files --xml . > test.xml
Directory: c:\PHDoc_Source\CurrentVersion\PHDoc_Core\

NOTE: The piping to test.xml is used to reduce the effect of the slowdown caused by the console window itself.

Cheers Jussi

[jwolbeck]

Code: Select all

  Command: svn.exe --show-updates --verbose status --depth files --xml nvo_phdprograms_tv.sru > test.xml
Directory: c:\PHDoc_Source\CurrentVersion\PHDoc_Core\chs\phd_app\

Less than second maybe .5 seconds

Code: Select all

CODE: SELECT ALL
  Command: svn.exe --show-updates --verbose status --depth files --xml . > test.xml
Directory: c:\PHDoc_Source\CurrentVersion\PHDoc_Core\chs\phd_app\

Around 1 second.

Code: Select all

CODE: SELECT ALL
Command: svn.exe --show-updates --verbose status --depth files --xml phd_app.pbt > test.xml
Directory: c:\PHDoc_Source\CurrentVersion\PHDoc_Core\

Less than a second maybe .5 seconds

Code: Select all

CODE: SELECT ALL
Command: svn.exe --show-updates --verbose status --depth files --xml . > test.xml
Directory: c:\PHDoc_Source\CurrentVersion\PHDoc_Core\

Less than a second maybe .5 seconds

We are aware that individual commands do run a little slow as we are using the HTTP protocol.

I will outline an example below when opening PowerBuilder for the first time to clearly show the issue since disabling the cache reveals the true requests PowerBuilder is making.

AgentSVN Log with cache disabled:

Code: Select all

[Fri Apr 01 08:25:47 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr --show-updates --verbose status phd_app.pbt
[Fri Apr 01 08:25:47 2016] >> * Directory: C:\PHDoc_Source\CurrentVersion\PHDoc_Core\chs\phd_app\
[Fri Apr 01 08:25:48 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr update gf_readini.srf
[Fri Apr 01 08:25:48 2016] >> * Directory: c:\phdoc_source\currentversion\phdoc_core\chs\patch1
[Fri Apr 01 08:25:48 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr --show-updates --verbose status gf_readini.srf
[Fri Apr 01 08:25:48 2016] >> * Directory: c:\phdoc_source\currentversion\phdoc_core\chs\patch1\
[Fri Apr 01 08:25:49 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr update gf_checkversion.srf
[Fri Apr 01 08:25:49 2016] >> * Directory: c:\phdoc_source\currentversion\phdoc_core\chs\patch1
[Fri Apr 01 08:25:49 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr --show-updates --verbose status gf_checkversion.srf
[Fri Apr 01 08:25:49 2016] >> * Directory: c:\phdoc_source\currentversion\phdoc_core\chs\patch1\
[Fri Apr 01 08:25:50 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr --show-updates --verbose status d_test1.srd
[Fri Apr 01 08:25:50 2016] >> * Directory: C:\PHDoc_Source\CurrentVersion\PHDoc_Core\chs\patch1\
[Fri Apr 01 08:25:50 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr --show-updates --verbose status chs.pbt
[Fri Apr 01 08:25:50 2016] >> * Directory: C:\PHDoc_Source\CurrentVersion\PHDoc_Core\chs\local_app\
[Fri Apr 01 08:25:51 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr --show-updates --verbose status scheduling.pbt
[Fri Apr 01 08:25:51 2016] >> * Directory: C:\PHDoc_Source\CurrentVersion\PHDoc_Core\scheduling\scheduling\
[Fri Apr 01 08:25:51 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr --show-updates --verbose status sql_center.pbt
[Fri Apr 01 08:25:51 2016] >> * Directory: C:\PHDoc_Source\CurrentVersion\PHDoc_Core\sql center\
[Fri Apr 01 08:25:52 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr --show-updates --verbose status acs_dque.pbt
[Fri Apr 01 08:25:52 2016] >> * Directory: C:\PHDoc_Source\CurrentVersion\PHDoc_Core\services\dequeuer\
[Fri Apr 01 08:25:53 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr --show-updates --verbose status security.pbt
[Fri Apr 01 08:25:53 2016] >> * Directory: C:\PHDoc_Source\CurrentVersion\PHDoc_Core\security\
[Fri Apr 01 08:25:53 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr --show-updates --verbose status dailies.pbt
[Fri Apr 01 08:25:53 2016] >> * Directory: C:\PHDoc_Source\CurrentVersion\PHDoc_Core\dailies\dailies\

Explanation of why PowerBuilder is trying to refresh the above files:

Code: Select all

phd_app.pbt - Need to check status on the target files (Same as solution file in VS)
gr_readini.srf - Need to check status on this function file as it is in the PBL that is defaulted to open and all files are refreshed when a PBL is opened. Note this file is not in source control and that is why there are two calls.
gf_checkversion.srf  - Need to check status on this function file as it is in the PBL that is defaulted to open and all files are refreshed when a PBL is opened. Note this file is not in source control and that is why there are two calls.
d_test1.srd  - Need to check status on this function file as it is in the PBL that is defaulted to open and all files are refreshed when a PBL is opened
chs.pbt - We have multiple targets in the workspace so PB needs to check the status on all targets on open
scheduling.pbt  - We have multiple targets in the workspace so PB needs to check the status on all targets on open
sql_center.pbt  - We have multiple targets in the workspace so PB needs to check the status on all targets on open
acs_dque.pbt  - We have multiple targets in the workspace so PB needs to check the status on all targets on open
security.pbt  - We have multiple targets in the workspace so PB needs to check the status on all targets on open
dailies.pbt  - We have multiple targets in the workspace so PB needs to check the status on all targets on open

Take note the very small number of commands required to run in this instance and no Parsing XML required. The PBL that is defaulted to open is intentionally a PBL with 3 objects with 1 in source control.

Now let us breakdown the log with cache enabled. I closed PB and re-opened PB so I 100% know PB is requesting EXACTLY the same files be refreshed.

AgentSVN With Cache enabled:

Code: Select all

[Fri Apr 01 08:23:45 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr --show-updates --verbose status --depth files --xml .
[Fri Apr 01 08:23:45 2016] >> * Directory: C:\PHDoc_Source\CurrentVersion\PHDoc_Core\chs\phd_app\
[Fri Apr 01 08:23:47 2016] >> *** XML Parsing Started ***
[Fri Apr 01 08:23:47 2016] >>       File Path: register.bmp
[Fri Apr 01 08:23:47 2016] >>       File Path: up_arrow.gif
[Fri Apr 01 08:23:47 2016] >>       File Path: hand01.cur
[Fri Apr 01 08:23:47 2016] >>       File Path: edit.jpg
...
[Fri Apr 01 08:23:54 2016] >>       File Path: phd_app.pbt
...
[Fri Apr 01 08:23:57 2016] >>       File Path: nvo_phdhow_to_tv.sru
[Fri Apr 01 08:23:57 2016] >> *** XMl Parse complete ***

[Fri Apr 01 08:23:57 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr update gf_readini.srf
[Fri Apr 01 08:23:57 2016] >> * Directory: c:\phdoc_source\currentversion\phdoc_core\chs\patch1

[Fri Apr 01 08:23:58 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr --show-updates --verbose status --depth files --xml .
[Fri Apr 01 08:23:58 2016] >> * Directory: c:\phdoc_source\currentversion\phdoc_core\chs\patch1\
[Fri Apr 01 08:23:58 2016] >> *** XML Parsing Started ***
[Fri Apr 01 08:23:58 2016] >>       File Path: patch1.pbg
[Fri Apr 01 08:23:58 2016] >>       File Path: d_test1.srd
[Fri Apr 01 08:23:58 2016] >> *** XMl Parse complete ***

[Fri Apr 01 08:23:58 2016] >> Directory: 'c:\phdoc_source\currentversion\phdoc_core\chs\patch1\'
[Fri Apr 01 08:23:58 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr update gf_checkversion.srf
[Fri Apr 01 08:23:59 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr --show-updates --verbose status --depth files --xml .
[Fri Apr 01 08:23:59 2016] >> * Directory: C:\PHDoc_Source\CurrentVersion\PHDoc_Core\chs\local_app\
[Fri Apr 01 08:24:01 2016] >> *** XML Parsing Started ***
[Fri Apr 01 08:24:01 2016] >>       File Path: BLUEPNT1.BMP
[Fri Apr 01 08:24:01 2016] >>       File Path: 5250.bmp
[Fri Apr 01 08:24:01 2016] >>       File Path: warning.gif
...
[Fri Apr 01 08:24:10 2016] >>       File Path: m_sheet_chart_preview.srm
[Fri Apr 01 08:24:10 2016] >> *** XMl Parse complete ***

[Fri Apr 01 08:24:10 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr --show-updates --verbose status --depth files --xml .
[Fri Apr 01 08:24:10 2016] >> * Directory: C:\PHDoc_Source\CurrentVersion\PHDoc_Core\scheduling\scheduling\
[Fri Apr 01 08:24:11 2016] >> *** XML Parsing Started ***
[Fri Apr 01 08:24:11 2016] >>       File Path: nvo_sqlserver_connection_sched.sru
[Fri Apr 01 08:24:11 2016] >>       File Path: pfcapsrv.pbr
[Fri Apr 01 08:24:11 2016] >>       File Path: PC2DB.BMP
...
[Fri Apr 01 08:24:12 2016] >>       File Path: scheduling_app.ini
[Fri Apr 01 08:24:12 2016] >> *** XMl Parse complete ***

[Fri Apr 01 08:24:12 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr --show-updates --verbose status --depth files --xml .
[Fri Apr 01 08:24:12 2016] >> * Directory: C:\PHDoc_Source\CurrentVersion\PHDoc_Core\sql center\
[Fri Apr 01 08:24:13 2016] >> *** XML Parsing Started ***
[Fri Apr 01 08:24:13 2016] >>       File Path: sql_center.pbt
[Fri Apr 01 08:24:13 2016] >>       File Path: sql_center.usr.opt
[Fri Apr 01 08:24:13 2016] >> *** XMl Parse complete ***

[Fri Apr 01 08:24:13 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr --show-updates --verbose status --depth files --xml .
[Fri Apr 01 08:24:13 2016] >> * Directory: C:\PHDoc_Source\CurrentVersion\PHDoc_Core\services\dequeuer\
[Fri Apr 01 08:24:13 2016] >>       File Path: n_tr.sru
[Fri Apr 01 08:24:14 2016] >>       File Path: d_queue.srd
[Fri Apr 01 08:24:14 2016] >>       File Path: phdoclogosmallblack.bmp
...
[Fri Apr 01 08:24:15 2016] >>       File Path: Sybase.PowerBuilder.WebService.WSDL.dll
[Fri Apr 01 08:24:15 2016] >> *** XMl Parse complete ***

[Fri Apr 01 08:24:15 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr --show-updates --verbose status --depth files --xml .
[Fri Apr 01 08:24:15 2016] >> * Directory: C:\PHDoc_Source\CurrentVersion\PHDoc_Core\security\
[Fri Apr 01 08:24:17 2016] >>       File Path: comments.png
[Fri Apr 01 08:24:17 2016] >>       File Path: book.jpg
[Fri Apr 01 08:24:17 2016] >>       File Path: phd_menu_blp.bmp
...
[Fri Apr 01 08:24:27 2016] >>       File Path: upload.png
[Fri Apr 01 08:24:27 2016] >> *** XMl Parse complete ***

[Fri Apr 01 08:24:27 2016] >> *   Command: svn.exe --non-interactive --trust-server-cert --no-auth-cache --username myUsr --show-updates --verbose status --depth files --xml .
[Fri Apr 01 08:24:27 2016] >> * Directory: C:\PHDoc_Source\CurrentVersion\PHDoc_Core\dailies\dailies\
[Fri Apr 01 08:24:29 2016] >> *** XML Parsing Started ***
[Fri Apr 01 08:24:29 2016] >>       File Path: Copy of e-mail369.gif
[Fri Apr 01 08:24:29 2016] >>       File Path: Calendar_16x16.bmp
[Fri Apr 01 08:24:29 2016] >>       File Path: oasis.bmp
...
[Fri Apr 01 08:24:37 2016] >>       File Path: phdoclogosmallblack_noline.bmp
[Fri Apr 01 08:24:37 2016] >> *** XMl Parse complete ***

A total of 2038 files were checked instead of 10. Almost ALL of those files are not Part of PowerBuilder and are image files that live next to the PBT files. All of our PCs are extremely slow at disk I/O. They have antivirus that scans everything along with whole disk encryption so the performance issue is probably related to disk I/O and NOT svn commands. Yes writing to the log file does inflate the time shown but with the logging disabled it takes about twice as long with caching enabled in this particular example.

Sure we could solve the issue with an SSD or removing all images from source control and develop another process to keep image files updated on all PCs but I think it can be solved in your plugin with minimal lines of code.

I will send you the log files.

[jussij]

Code: Select all

A total of 2038 files were checked instead of 10.

I don't understand what you mean by this

Nothing is is being checked out and no files are changing on the disk.

What happens is the status of 2038 files are requested from the server in one hit and then those details are then loaded into the cache.

Now from what you said above that request for those 2038 status values only took about 1 second to complete where as an individual request took 0.5 second.

That is the whole point of this cache request as to get 2038 status values one at a time would take around 2038 * 0.5 seconds to complete.

Now in your case, as you have pointed out before, most of those 2038 file don't below in the PB project so that scenario will not happen.

However, it really does not matter as the total time spent getting those 2038 status was only 1 second as apposed to 0.5 seconds.

So if those 2038 status values came back in 1 second, the parsing of the XML is only going to be taking one or two milliseconds or less.

So that entire request still should only have taken about 1 second to complete.

So where is the rest of the delay coming from

Now the cache is directory based so if PB requests 8 file status values from 8 files in 8 different directories then that would be an 8 second delay.

And even in that scenario if those request had been done individually then that itself still be a 4 second delay.

Code: Select all

Almost ALL of those files are not Part of PowerBuilder and are image files that live next to the PBT files.

But they are part of the Subversion working copy of that folder.

There is no way Agent SVN can use the cache for some files and not use the cache for others.

Short of hard coding file extension into the code how would it make that decision

Code: Select all

All of our PCs are extremely slow at disk I/O.

But where is the disk I/O

All that caching is done in memory.

Code: Select all

Yes writing to the log file does inflate the time shown but with the logging disabled it takes about twice as long with caching enabled in this particular example.

OK, with the logging enabled, yes there is disk I/O and it causes a much noticeable slow down in performance. I see this slow down as well.

Code: Select all

Sure we could solve the issue with an SSD or removing all images from source control and develop another process to keep image files updated on all PCs

But from the timing figures you have provided I can't see how those image files can be causing more than 1 second of delay.

If you are seeing delays into the 10+ seconds where are those other 9+ seconds of delay coming from

Code: Select all

but I think it can be solved in your plugin with minimal lines of code.

As I mentioned before I am not going to start changing code, before I fully understand the problem.

Now what I think might be needed is a special debug mode that only does timings and no debugging because that will then help identify what time is being spent where.

Code: Select all

I will send you the log files.

Thanks.

Cheers Jussi

[jwolbeck]

But where is the disk I/O ?

I was assuming the cache was written to disk which could have explained the slowness. Being in memory then that was not the issue, thanks for clarifying.

So where is the rest of the delay coming from ?

When you get the status of the 2038 files do you need to do more than parse the XML or are you simply building a cache and waiting for PowerBuilders individual requests to compare to the cache? If you are only doing the latter then you are right that a few thousand extra items in your cache probably has minimal impact. I still think it can be prevented but it may not be the obvious cause of the slowdown like I thought it was.

Short of hard coding file extension into the code how would it make that decision ?

Since I do not understand the MS-SCCI API, the PB SCC extensions written or your plugin logic nor do I have the ability to debug those functions calls the only thing I can see is hard coding. There is only 1 of maybe 10 situations where assuming the request for a PBT is going to be followed up by requests to other objects in the same folder as the PBT and that is expanding the PBL that the PBT lives in. Might be an opportunity to save on processor/writing to RAM time if nothing else.

After disabling the PowerBuilder workspace "Status Refresh Rate" it does appear that most of the issues we were initially having were a result of that. Having figured that out I am not confident about where the issue with that is. We do know it was not a problem with Starteam but there might have been other factors there.

It would be nice to use the "Status Refresh Rate" setting but disabling that appears to solve most of the issues and I do not have time to do more debugging with that.

[jussij]

When you get the status of the 2038 files do you need to do more than parse the XML

Nothing but parse the XML and hold the values in memory.

or are you simply building a cache and waiting for PowerBuilders individual requests to compare to the cache?

The cache hold the status of all the items in the one directory.

As an example consider a simple C++ project with a structure as follows:

Code: Select all

    MyProject Folder
       + MyProject.sln
       + readme.txt
       + Source Folder
           + Source File1.cpp
           + Source File1.hpp
           + Source File2.cpp
           + Source File2.hpp

If the IDE ask for the status of the MyProject.sln file the status of all items in that folder are cached.

If the the IDE asks for the status of Source File1.cpp a second node is created in the cache, this time for all the items in that folder.

So now there will be two nodes in the cache.

Now if the IDE asks for the status of Source File1.hpp, Source File2.cpp or Source File1.hpp the response is almost instant as those values are already in the second node of the cache.

Code: Select all

If you are only doing the latter then you are right that a few thousand extra items in your cache probably has minimal impact.

That is exactly what is does and that is why never understand the reason for the delay.

Now of course when the debug output option is on the cache does cause a delay, because it has to dumps the entire contents of the cache to disk.

Code: Select all

After disabling the PowerBuilder workspace "Status Refresh Rate" it does appear that most of the issues we were initially having were a result of that.

What is that feature

This is the first time I have heard of it but it also sounds like I might have to document this as something to turn off when using PowerBuilder with Agent SVN.

I can't recall seeing a similar feature in Visual Studio. It only has the manual full refresh option.

Code: Select all

We do know it was not a problem with Starteam but there might have been other factors there.

The reason will be due to differences between Starteam and Subversion, and in particular how both systems manage status.

It is a well know fact the Subversion status command is terribly slow and even slower when run through the HTTPS:// protocol.

A quick search the web will find many instances of users complaining of how slowly that status command runs.

[jussij]

From the results of the latest log file I can see PowerBuilder is taking 14.712 seconds to open a project.

In the process it requesting the file status for some 225 files that span 9 distinct folder locations.

Of that 14.712 seconds total time these are the portions of time spent in Agent SVN and time spent in Subversion:

Code: Select all

    Subversion: 12.792 sec
     Agent SVN:  1.920 sec

Now I am surprised how much time Agent SVN is taking

Agent SVN will be spending most of that time parsing XML and I suspect the XML parser it is using is not the fastest

That may need to be fixed.

But the vast majority of time is being spent in Subversion meaning the problem is at the Subversion end.

It could be some configuration issue, or network issue

But one other thing worth checking is to see if this is in fact a Subversion client issue.

More details on this can be found here: viewtopic.php?f=11&t=7167

Cheers Jussi

[jwolbeck]

What is that feature ?

Appears to cause a refresh of open PBLs and all Target files when that interval is reached and it cannot be "disabled" but can be set as high as 600 minutes. It only seems to carry out the refresh when you do "something" in PB like open PBL, checkin/out objects or even saving.

We do use the HTTP protocol through collabnet and frankly the amount of time communicating with SVN is acceptable for us. Last week there must have been other reasons why everything was so slow. Since other developers are still using the 2.55 version and noticed it is much faster that brings me to the conclusion that something else was causing the slowness (above just changing that setting). Tortoise SVN client results in about the same amount of time.

As far as your parsing in memory, our IT has a large amount of processes always running in the background and AV also scans memory that could cause things to take longer than they should.

Also not sure if you planned on keeping that timing option but it does cause a VS crash when opening solution and in PB doing show differences also crashes (I know you were just interested in getting the timings on open but just thought I should mention it).

I appreciate you taking the time for this.