Zeus Hangs for 15 seconds when its window is selected

[jussij]

Well that was short lived, from yesterday to today the window focus switch time has jumped from 3.5 seconds to 35 seconds on the same Workspace.

There is one small bug in the way Zeus handles the tag database files for a workspace, a bug that I ran into myself

It relates to how the projects in the Workspace are named.

The problem is caused by the fact that Zeus creates an individual tag database for every project in every workspace.

However the bug relates to the fact that Zeus does not distinguish between two different projects with the same name in two different workspaces.

If you create that scenario then each time you switch workspace Zeus will be forced to rebuild the tag database for the project with the duplicate name.

To get around this issue, you have to make sure you don't have two different projects in two workspaces with the same name.

Cheers Jussi

[jussij]

As to the log file, I can see from the log file this is where the workspace is first loaded:

Code: Select all

[Thu Oct 26 14:43:22 2017] RUNTIME   "zfwwrk01.cpp" (4298)    >> WorkspaceMgr::load started.
[Thu Oct 26 14:43:22 2017] RUNTIME   "xpWorkspaceEx.cpp" (4460)    >> Workspace::open started.
[Thu Oct 26 14:44:10 2017] RUNTIME   "xpWorkspaceEx.cpp" (4537)    >> TagWorkspace::make completed.
[Thu Oct 26 14:44:35 2017] RUNTIME   "zfwtag01.cpp" (2835)    >> TagWorkspace::load started.
[Thu Oct 26 14:44:35 2017] RUNTIME   "zfwtag01.cpp" (2885)    >> TagWorkspace::load completed.
[Thu Oct 26 14:44:35 2017] RUNTIME   "xpWorkspaceEx.cpp" (4902)    >> Workspace::load started.
[Thu Oct 26 14:45:19 2017] RUNTIME   "xpWorkspaceEx.cpp" (4907)    >> Workspace::load complete.
[Thu Oct 26 14:45:19 2017] RUNTIME   "zfwwrk01.cpp" (4330)    >> WorkspaceMgr::trigger.
[Thu Oct 26 14:45:19 2017] RUNTIME   "zfwwrk01.cpp" (4336)    >> WorkspaceMgr::load complete.

And as you can see that whole step is taking quite some time:

Code: Select all

[Thu Oct 26 14:43:22 2017] RUNTIME   "zfwwrk01.cpp" (4298)    >> WorkspaceMgr::load started.
[Thu Oct 26 14:45:19 2017] RUNTIME   "zfwwrk01.cpp" (4336)    >> WorkspaceMgr::load complete.

Some time is spent here:

Code: Select all

[Thu Oct 26 14:43:22 2017] RUNTIME   "xpWorkspaceEx.cpp" (4460)    >> Workspace::open started.
[Thu Oct 26 14:44:10 2017] RUNTIME   "xpWorkspaceEx.cpp" (4537)    >> TagWorkspace::make completed.

And some more time is spent here:

Code: Select all

[Thu Oct 26 14:44:35 2017] RUNTIME   "xpWorkspaceEx.cpp" (4902)    >> Workspace::load started.
[Thu Oct 26 14:45:19 2017] RUNTIME   "xpWorkspaceEx.cpp" (4907)    >> Workspace::load complete.

By comparison this is how long Zeus takes to load the Zeus workspace:

Code: Select all

[Fri Oct 27 10:07:13 2017] RUNTIME   "zfwwrk01.cpp" (4298)    >> WorkspaceMgr::load started.
[Fri Oct 27 10:07:13 2017] RUNTIME   "xpWorkspaceEx.cpp" (4460)    >> Workspace::open started.
[Fri Oct 27 10:07:13 2017] RUNTIME   "xpWorkspaceEx.cpp" (4537)    >> TagWorkspace::make completed.
[Fri Oct 27 10:07:13 2017] RUNTIME   "zfwtag01.cpp" (2835)    >> TagWorkspace::load started.
[Fri Oct 27 10:07:13 2017] RUNTIME   "zfwtag01.cpp" (2885)    >> TagWorkspace::load completed.
[Fri Oct 27 10:07:13 2017] RUNTIME   "xpWorkspaceEx.cpp" (4902)    >> Workspace::load started.
[Fri Oct 27 10:07:13 2017] RUNTIME   "xpWorkspaceEx.cpp" (4907)    >> Workspace::load complete.
[Fri Oct 27 10:07:13 2017] RUNTIME   "zfwwrk01.cpp" (4330)    >> WorkspaceMgr::trigger.

My load completes in less than a second yet your load takes nearly a minute

So my first question is how big is your Workspace

To find out could you do this:

1. Open the workspace.

2. Macros, Search, Workspace for Text and zearch for something like 'zzzz'

3. Take not of how long this first search takes (the second search will be quicker).

4. Then open the file found (changing the <Your User ID goes here> value) here and seeing how many lines it contains:

Code: Select all

C:\Users\<Your User ID goes here>\AppData\Roaming\Xidicone\Zeus\zBackup\response_file.txt

By comparison doing this with one of the Zeus workspaces I get a search time of about 5 seconds with the workspace containing about 1000 files.

Also if I do a focus change by switching away from and back to Zeus I get these two lines added to the log file:

Code: Select all

[Fri Oct 27 10:10:49 2017] RUNTIME   "xpWorkspaceEx.cpp" (4902)    >> Workspace::load started.
[Fri Oct 27 10:10:49 2017] RUNTIME   "xpWorkspaceEx.cpp" (4907)    >> Workspace::load complete.

You can see this if you have the log file open in another instance of Zeus that is not being traced.

As you can see those two lines take less than a second for me.

However, I suspect you will be seeing this time delay:

Code: Select all

[Thu Oct 26 14:44:35 2017] RUNTIME   "xpWorkspaceEx.cpp" (4902)    >> Workspace::load started.
[Thu Oct 26 14:45:19 2017] RUNTIME   "xpWorkspaceEx.cpp" (4907)    >> Workspace::load complete.

Finally, could you repeat the test with the new Zeus version found here: http://www.zeusedit.com/z300/z-beta.zip

This version has some increased levels of logging to help try and identify the cause of this slowdown.

Cheers Jussi

[jmasles]

I only create one project per workspace and I don't think any of the projects have exactly the same name. In addition I've disabled automatic tag database generation for the workspace I'm testing against, although the workspace tagger is enabled. Interesting note, this morning I'm back to a 3 second time when I switch from an explorer window back to Zeus. The only variable here is the network link, so I did a quick check on network throughput and transferred a 213 MB file in around 6 seconds using windows copy from my mounted samba share in Colorado to my desktop here in silicon valley. So it's not a transfer rate issue but it could easily be a per request latency problem.

Following your suggestions the search of a files in the workspace took 9.7 seconds and here's the output:

xfgrep -f -n -i -r zzxyz C:\Users\jmasles\AppData\Roaming\Xidicone\Zeus\zBackup\response_file.txt

Search completed with a total of '580' files processed.

So a modest number of files in the workspace.

I recreated the test with the new executable and once again the initial data is from the startup of Zeus and the last 2 lines are from switching focus back to Zues from an explorer window. While everything is running better today, the window switch time is still around 3.5 seconds. I will try the experiment again later this afternoon to see if I can get a log set when the switch time is 30 seconds.

thx,
John.

[jussij]

The only variable here is the network link, so I did a quick check on network throughput and transferred a 213 MB file in around 6 seconds using windows copy from my mounted samba share in Colorado to my desktop here in silicon valley.

I suspect this is something to do with Zeus not liking this particular network

Many years ago I remember getting reports of Zeus running slow over one particular third party network system and also one on Samba networks.

I don't think I every really go to the bottom of this issue, even after setting up a test Samba network, which worked fine for me.

This always confused me as Zeus uses nothing but stock standard Win32 and C library calls for all it's file handling.

I put this down to the fact that Zeus does a lot of checking of the file status and on some networks, for reason that I don't fully understand, this can be slow.

From the trace I can see the three second switching time:

Code: Select all

[Fri Oct 27 11:09:12 2017] RUNTIME   "xpWorkspaceEx.cpp" (4912)    >> Workspace::load started.
[Fri Oct 27 11:09:15 2017] RUNTIME   "xpWorkspaceEx.cpp" (4917)    >> Workspace::load complete.

This part of the load was also slow:

Code: Select all

[Fri Oct 27 11:08:32 2017] RUNTIME   "xpWorkspaceEx.cpp" (3866)    >> Workspace::load started.
[Fri Oct 27 11:08:36 2017] RUNTIME   "xpWorkspaceEx.cpp" (3907)    >> Workspace::sort(1)

Mapping the trace output to the code, I can see this also looks like the network issue mentioned above.

The code that is running is doing nothing more than hitting the file system for file status information.

The switch focus slow down is caused by Zeus rebuilding the workspace tree.

To build the tree it does a status check for each of the files, checking if the file status has changed or the file has been deleted.

So it is those 500 status checks that are causing this slow down.

To confirm this theory can you run this simple test.

1. Start Zeus with the workspace open.

2. From the toolbar click on the Navigator Toggle button (9th button from the left) to hide the navigator panel.

3. Move the focus away and then back to Zeus and you should now see the response will be instant.

With the navigator not showing the tree is not loaded and none of these file status requests takes place.

I will do some investigation into this.

Cheers Jussi

PS: Could you repeat the test with the new Zeus version found here: http://www.zeusedit.com/z300/z-beta.zip

This version implements a different version of the file access function.

Could you check to see if that make any difference

[jmasles]

The test with the navigator panel hidden performed as you expected, focus switches were instantaneous. I loaded up the newest beta release you sent and used the -s and -t options (not sure if that was necessary ). Behavior was as before with about a 3.9 second focus switch with the navigator panel displayed. I appreciate your efforts to date and recognize that the circumstances of this issue may well be beyond your control.

thx,
John.

[jussij]

Hi John,

Thanks for the feedback.

This issue is a little hard to fix since it does somehow seem to be related to the network setup that you are using

What I will do is take a closer look at the code from that earlier 3.97w version.

The reason that version might not have show the problem is because the focus activation feature that is now causing the slowdown may have been added some time after that earlier version.

Cheers Jussi

[jussij]

The latest Zeus beta will not fix this issue, but it will hopefully reduce the delay by about half.

The latest version can be found here: http://www.zeusedit.com/z300/z-beta.zip

Cheers Jussi

[jmasles]

I did a quick back to back test with the lastest beta vs the previous one you sent out. Previous ones times were around 4.15 seconds and the latest one was about 3.30 seconds, so a noticeable improvement.

thx,
John.

[jussij]

Hi John,

I have tracked down the code for that much older 3.97w release.

From that code I can see there is no update of the workspace on the Zeus get focus event and hence the reason you don't see the delay for that version of Zeus.

As such I think the only solution will be to add some sort of option to allow for this behaviour to be enabled/disabled.

Cheers Jussi