This Bugzilla instance is a read-only archive of historic NetBeans bug reports. To report a bug in NetBeans please follow the project's instructions for reporting issues.

Bug 38108 - Performance problems in VcsGlobalCommandsAction.getMenuPresenter() - DOM trees created to initialize menu
Summary: Performance problems in VcsGlobalCommandsAction.getMenuPresenter() - DOM tree...
Status: VERIFIED FIXED
Alias: None
Product: obsolete
Classification: Unclassified
Component: vcsgeneric (show other bugs)
Version: 3.x
Hardware: All All
: P2 blocker (vote)
Assignee: Martin Entlicher
URL:
Keywords: PERFORMANCE
: 38192 44883 (view as bug list)
Depends on:
Blocks:
 
Reported: 2003-12-15 13:24 UTC by _ tboudreau
Modified: 2005-07-25 09:34 UTC (History)
2 users (show)

See Also:
Issue Type: DEFECT
Exception Reporter:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description _ tboudreau 2003-12-15 13:24:30 UTC
Doing some profiling of NetBeans in OptimizeIt
shows that 1777ms of startup is spent loading
toolbars.

668 ms of that is in
VcsGlobalCommandsAction.getMenuPresenter.

From that the two hot spots are 
org.netbeans.modules.vcs.advanced.globalcommands.GlobalCommandsProvider.getInstance()
 - takes 300 ms
and
its constructor, which takes the rest of the time.

So it seems like we could save almost a second of
startup just by hiding this toolbar...
Comment 1 Martin Entlicher 2004-01-28 11:03:57 UTC
The same problem is actually described in issue #38192:

During processing of menu warmup task VCS support creates DOM
documents. This is not a bug from user's point of view but wastes
resources. DOM
related classes have to be loaded and initialized and it is likely
that custom SAXParser can do better work than building of full DOM tree.
Ideally we can get rid of all usages of DOM.

We would need to evaluate how hard it would be to use SAX instead.
Comment 2 Martin Entlicher 2004-01-28 11:04:52 UTC
*** Issue 38192 has been marked as a duplicate of this issue. ***
Comment 3 Martin Entlicher 2004-06-15 16:16:53 UTC
*** Issue 44883 has been marked as a duplicate of this issue. ***
Comment 4 _ rkubacki 2004-06-15 17:05:49 UTC
If you really want to mark other bugs as duplicate please adjust
priority and target milestone accordingly
Comment 5 Martin Entlicher 2004-06-15 17:28:15 UTC
Does it really have to be fixed for promo D? The fix will likely be
complex. This is why I left the original P3 priority.
Comment 6 _ tboudreau 2004-06-15 20:36:33 UTC
Well, if you do play with it, please get rid of the usages of JInlineMenu - in fact, it was the 
VCS module's use of nested JInlineMenus (along with truly evil things PasteAction does) 
that have so far blocked all attempts at fixing our [messy] implementation of menus 
(enabling the screen menu bar to work on mac os - though I'm still going to try to find a 
hack that works).
Comment 7 _ rkubacki 2004-06-16 08:08:25 UTC
The priorities are not based on a fix complexity. That's the rule.

The difference between Versioning on other menus is really painfull
and should be fixed. We may treat it as a regression from previous
releases where we spent effort to make menu reasonably fast. Note that
2 seconds to open something what is expected to be shown within 100ms
is an extreme.
Comment 8 Martin Entlicher 2004-06-17 09:51:46 UTC
O.K., scheduling for promo-D for now. I'll try to do something with it.

To the usage of JInlineMenus, I use them quite heavily in VCS actions,
because the set of actions can vary. The menu items need to be
generated dynamically, because the content can change.
To get rid of JInlineMenu, we would have to at least get rid of
SystemAction first, so that I can generate the actions for individual
VCS commands dynamically.
Comment 9 Martin Entlicher 2004-06-21 18:10:23 UTC
The most critical part is the constructor of GlobalExecutionContext.
It needs to be evaluated whether it's necessary to copy the shared
commands from the profile.
In any case to fix this, variables and commands reading would have to
be done by sax so that we can skip the contextual commands.
Comment 10 Martin Entlicher 2004-06-24 15:19:46 UTC
SAX parser as such seems to be significantly faster then DOM,
especially due to partial parsing that we can do. However there is
still a large overhead caused by other parts.

My measurements show following times in the current impl. (DOM):
loadConfig(cvs.xml) - 738 milliseconds
loadConfig(empty.xml) - 79 milliseconds
loadConfig(pvcs.xml) - 129 milliseconds
whole VcsGlobalCommandsAction.getGlobalCommands() took 1196 ms.

With the partial SAX parser I got following times:
loadConfig(cvs.xml) - 197 milliseconds
loadConfig(empty.xml) - 1 millisecond
loadConfig(pvcs.xml) - 21 milliseconds
whole VcsGlobalCommandsAction.getGlobalCommands() took 496 ms.

The extra time that is not devoted to loading of XML profiles is
roughly the same (250ms in the first case, 277ms in the second case).
Comment 11 Martin Entlicher 2004-06-24 15:36:28 UTC
SAX parser is in:

/cvs/vcscore/src/org/netbeans/modules/vcscore/cmdline/UserCommandSupport.java,v
 <--  UserCommandSupport.java
new revision: 1.38; previous revision: 1.37

/cvs/vcsgeneric/src/org/netbeans/modules/vcs/advanced/Profile.java,v 
<--  Profile.java
new revision: 1.3; previous revision: 1.2

/cvs/vcsgeneric/src/org/netbeans/modules/vcs/advanced/ProfilesFactory.java,v
 <--  ProfilesFactory.java
new revision: 1.7; previous revision: 1.6

RCS file:
/cvs/vcsgeneric/src/org/netbeans/modules/vcs/advanced/ProfileContentHandler.java,v
 <--  ProfileContentHandler.java
initial revision: 1.1

/cvs/vcsgeneric/src/org/netbeans/modules/vcs/advanced/commands/UserCommandIO.java,v
 <--  UserCommandIO.java
new revision: 1.18; previous revision: 1.17

/cvs/vcsgeneric/src/org/netbeans/modules/vcs/advanced/globalcommands/GlobalCommandsProvider.java,v
 <--  GlobalCommandsProvider.java
new revision: 1.5; previous revision: 1.4

/cvs/vcsgeneric/src/org/netbeans/modules/vcs/advanced/globalcommands/GlobalExecutionContext.java,v
 <--  GlobalExecutionContext.java
new revision: 1.5; previous revision: 1.4

/cvs/vcsgeneric/src/org/netbeans/modules/vcs/advanced/variables/VariableIO.java,v
 <--  VariableIO.java
new revision: 1.21; previous revision: 1.20
Comment 12 Martin Entlicher 2004-06-24 16:23:44 UTC
The lookup of all instances of VcsCommandsProvider takes 233 ms. This
time is consumed by ProfilesFactory.initProfileLabels(). Only the
loading the list of configurations takes 151 milliseconds. This needs
some optimization...
Comment 13 Martin Entlicher 2004-06-24 17:21:09 UTC
isTemporaryConfig() method moved from CommandLineVcsFileSystem to
VariableIO. This prevents unnecessary loading of
CommandLineVcsFileSystem class.
This reduce the time of loading the list of configurations from 151
milliseconds to 38 milliseconds.

/cvs/vcsgeneric/src/org/netbeans/modules/vcs/advanced/variables/VariableIO.java,v
 <--  VariableIO.java
new revision: 1.22; previous revision: 1.21

/cvs/vcsgeneric/src/org/netbeans/modules/vcs/advanced/CommandLineVcsFileSystem.java,v
 <--  CommandLineVcsFileSystem.java
new revision: 1.148; previous revision: 1.147
Comment 14 Martin Entlicher 2004-06-24 19:59:30 UTC
A further performance improvement made in loading of localized profiles:

/cvs/vcsgeneric/src/org/netbeans/modules/vcs/advanced/variables/VariableIO.java,v
 <--  VariableIO.java
new revision: 1.23; previous revision: 1.22
Comment 15 Martin Entlicher 2004-06-24 21:05:28 UTC
Further performance improvements done:

/cvs/vcsgeneric/src/org/netbeans/modules/vcs/advanced/commands/UserCommandIO.java,v
 <--  UserCommandIO.java
new revision: 1.19; previous revision: 1.18

/cvs/vcsgeneric/src/org/netbeans/modules/vcs/advanced/config/mf-layer.xml,v
 <--  mf-layer.xml
new revision: 1.24; previous revision: 1.23

/cvs/vcsgeneric/src/org/netbeans/modules/vcs/advanced/ProfilesFactory.java,v
 <--  ProfilesFactory.java
new revision: 1.8; previous revision: 1.7

/cvs/vcscore/src/org/netbeans/modules/vcscore/cmdline/UserCommand.java,v
 <--  UserCommand.java
new revision: 1.17; previous revision: 1.16

/cvs/vcscore/src/org/netbeans/modules/vcscore/cmdline/UserCommandSupport.java,v
 <--  UserCommandSupport.java
new revision: 1.39; previous revision: 1.38

The time of VcsGlobalCommandsAction.getGlobalCommands() was reduced to
386 milliseconds.
Comment 16 _ rkubacki 2004-07-14 15:38:41 UTC
Sorry but I do not see any significant improvement. I measured with
build 200407141800 on my PIII/800MHz/512MB, RH, JDK1.5.0b55. 

Maybe it would be better leave this closed and reopen #44883 but anyway. 

1st invocations of Versioning menu takes 2283/2238/896/875ms in a
couple of sessions that I ran. Times longer than 2s happens when I
have a Java file opened in editor and try to open some other top level
menus. If I open context menu in editor before 1st opening of
Versioning it is better but still far from the expected value (100ms).
Comment 17 _ rkubacki 2004-07-16 17:30:43 UTC
VcsGlobalCommandsAction$MergedMenu.addNotify is still slow when
showing Versioning menu for the 1st time. 

Most of time is now in SAX processing where it calls handlers that
initializes profiles. During this time 4 bundles are read
(-J-Dorg.openide.util.NbBundle.DEBUG=true):
920
vcsgeneric/profiles/cvsprofiles/src/org/netbeans/modules/vcs/profiles/cvsprofiles/config/Bundle.properties
370
vcsgeneric/profiles/pvcs/src/org/netbeans/modules/vcs/profiles/pvcs/config/Bundle.properties
213
vcsgeneric/profiles/vss/src/org/netbeans/modules/vcs/profiles/vss/config/Bundle.properties
42
vcsgeneric/src/org/netbeans/modules/vcs/profiles/config/Bundle.properties

The numbers are line counts and especialy the CVS one is not quite
small. Currently we can't read them partialy.

Another issue is classloading though it should not be critical.
-verbose:class prints less than 100 classes.
Comment 18 Martin Entlicher 2004-07-22 15:40:17 UTC
Resource bundle for CVS profile commands is splited into two parts -
one, which contains messages that are loaded by global commands
provider (variables and global commands)
and the original with removed message for variables and global commands.
According to measurements this makes Versioning menu faster by about
30 ms (on Centrino 2GHz, Linux OS).

/cvs/vcsgeneric/l10n.list,v  <--  l10n.list
new revision: 1.10; previous revision: 1.9

/cvs/vcsgeneric/profiles/cvsprofiles/src/org/netbeans/modules/vcs/profiles/cvsprofiles/config/Bundle.properties,v
 <--  Bundle.properties
new revision: 1.51; previous revision: 1.50

RCS file:
/cvs/vcsgeneric/profiles/cvsprofiles/src/org/netbeans/modules/vcs/profiles/cvsprofiles/config/BundleGlobal.properties,v
done
/cvs/vcsgeneric/profiles/cvsprofiles/src/org/netbeans/modules/vcs/profiles/cvsprofiles/config/BundleGlobal.properties,v
 <--  BundleGlobal.properties
initial revision: 1.1

/cvs/vcsgeneric/profiles/cvsprofiles/src/org/netbeans/modules/vcs/profiles/cvsprofiles/config/cvs.xml,v
 <--  cvs.xml
new revision: 1.78; previous revision: 1.77
Comment 19 Martin Entlicher 2004-07-22 15:47:44 UTC
To do more improvements, we can also split variables.
CVS module defines a lot of variables, that are necessary for
contextual commands. But only a few of them are used for global commands.

To do that, we would have to modify the I/O of profiles, and also
change the variables GUI editor.

However, the first problem in the Versioning menu construction is
lookup for VcsCommandsProvider.class. According to my measurements the
time to find an instance of that class is about 150 - 220 ms on
Centrino 2GHz.
I have to find a way how to reduce that time...
Comment 20 Jiri Kovalsky 2004-07-22 15:58:05 UTC
In such a case how can we meet the limit of 200 ms ? Besides I have
also serious concerns about changing UI of variable editor because of
performance reasons. BTW, it shouldn't be possible now, should it ?
Comment 21 Martin Entlicher 2004-07-23 14:34:35 UTC
Another partial fix in reading of headers from XML profiles:

/cvs/vcsgeneric/src/org/netbeans/modules/vcs/advanced/variables/VariableIO.java,v
 <--  VariableIO.java
new revision: 1.24; previous revision: 1.23

/cvs/vcsgeneric/src/org/netbeans/modules/vcs/advanced/ProfilesFactory.java,v
 <--  ProfilesFactory.java
new revision: 1.9; previous revision: 1.8

Further observations:
- I've found, that I do some work in the constructor of the object
that is looked up :-( That work takes now (after the above fix)
~120ms. The whole lookup takes now ~135ms, therefore the lookup as
such takes ~15ms.

- There is still a lot of time spent in reading from
Bundle.properties. It's 80 ms in 43 invocations of
VcsUtilities.getBundleString(). The problem is, that even on Linux
there is 35 ms spent in reading ResourceBundle for vss.xml and 16 ms
for empty.xml. This should not be necessary.
Comment 22 Martin Entlicher 2004-07-26 15:51:08 UTC
The display names of profiles are loaded lazily from resource bundles.
This improves the performance a little:

/cvs/vcsgeneric/src/org/netbeans/modules/vcs/advanced/ProfilesFactory.java,v
 <--  ProfilesFactory.java
new revision: 1.10; previous revision: 1.9
Comment 23 Martin Entlicher 2004-07-28 11:12:57 UTC
After the fix of issue #46193, the menu takes ~255 ms to display on
Centrino 2GHz, Linux OS.
Comment 24 Martin Entlicher 2004-07-28 12:11:20 UTC
GlobalCommandsProvider service is registed in META-INF/services
instead of module XML layer. This seems to have a small performance
improvement:

RCS file:
/cvs/vcsgeneric/src/META-INF/services/org.netbeans.spi.vcs.VcsCommandsProvider,v
done
Checking in
src/META-INF/services/org.netbeans.spi.vcs.VcsCommandsProvider;
/cvs/vcsgeneric/src/META-INF/services/org.netbeans.spi.vcs.VcsCommandsProvider,v
 <--  org.netbeans.spi.vcs.VcsCommandsProvider
initial revision: 1.1
done
Processing log script arguments...
More commits to come...
Checking in src/org/netbeans/modules/vcs/advanced/config/mf-layer.xml;
/cvs/vcsgeneric/src/org/netbeans/modules/vcs/advanced/config/mf-layer.xml,v
 <--  mf-layer.xml
new revision: 1.25; previous revision: 1.24
done
Processing log script arguments...
More commits to come...
Checking in
src/org/netbeans/modules/vcs/advanced/globalcommands/GlobalCommandsProvider.java;
/cvs/vcsgeneric/src/org/netbeans/modules/vcs/advanced/globalcommands/GlobalCommandsProvider.java,v
 <--  GlobalCommandsProvider.java
new revision: 1.6; previous revision: 1.5
done

The time necessary to invoke the menu is now between 200 - 250 ms.
Comment 25 Antonin Nebuzelsky 2004-07-29 13:49:22 UTC
I've made a measurement on my slow machine (Dell Precision 220, PIII
800MHz, 512MB RAM, W2K), which is a referential configuration for our
performance measurements. I've measured trunk build 200407281800,
first invocation of the VCS main menu item after start of the IDE,
repeated three times with each of the cases below.

1.4.2_04, empty IDE: 422ms, 437ms, 484ms
1.4.2_04, prj open, vcsfs mounted: 250ms, 219ms, 235ms

1.5.0-b58, empty IDE: 641ms, 719ms, 703ms
1.5.0-b58, prj open, vcsfs mounted: 360ms, 359ms, 344ms
Comment 26 Richard Gregor 2004-08-31 16:15:37 UTC
There is a new strategy used in constructing versioning menu. Items
from profiles comes from layer instead of profile.xml. Additional
popup with merged global and context commands is initialized lazy.
Could you  please measure it again, please?


Checking in
vcscore/src/org/netbeans/modules/vcscore/actions/VcsAllCommandsAction.java;
/cvs/vcscore/src/org/netbeans/modules/vcscore/actions/VcsAllCommandsAction.java,v
 <--  VcsAllCommandsAction.java
new revision: 1.11; previous revision: 1.10
done
Processing log script arguments...
More commits to come...
Checking in
vcsgeneric/profiles/cvsprofiles/src/org/netbeans/modules/vcs/profiles/cvsprofiles/Bundle.properties;
/cvs/vcsgeneric/profiles/cvsprofiles/src/org/netbeans/modules/vcs/profiles/cvsprofiles/Bundle.properties,v
 <--  Bundle.properties
new revision: 1.4; previous revision: 1.3
done
Checking in
vcsgeneric/profiles/cvsprofiles/src/org/netbeans/modules/vcs/profiles/cvsprofiles/mf-layer.xml;
/cvs/vcsgeneric/profiles/cvsprofiles/src/org/netbeans/modules/vcs/profiles/cvsprofiles/mf-layer.xml,v
 <--  mf-layer.xml
new revision: 1.3; previous revision: 1.2
done
Processing log script arguments...
More commits to come...
Checking in
vcsgeneric/profiles/pvcs/src/org/netbeans/modules/vcs/profiles/pvcs/Bundle.properties;
/cvs/vcsgeneric/profiles/pvcs/src/org/netbeans/modules/vcs/profiles/pvcs/Bundle.properties,v
 <--  Bundle.properties
new revision: 1.5; previous revision: 1.4
done
Checking in
vcsgeneric/profiles/pvcs/src/org/netbeans/modules/vcs/profiles/pvcs/mf-layer.xml;
/cvs/vcsgeneric/profiles/pvcs/src/org/netbeans/modules/vcs/profiles/pvcs/mf-layer.xml,v
 <--  mf-layer.xml
new revision: 1.2; previous revision: 1.1
done
Processing log script arguments...
More commits to come...
Checking in
vcsgeneric/profiles/vss/src/org/netbeans/modules/vcs/profiles/vss/Bundle.properties;
/cvs/vcsgeneric/profiles/vss/src/org/netbeans/modules/vcs/profiles/vss/Bundle.properties,v
 <--  Bundle.properties
new revision: 1.4; previous revision: 1.3
done
Checking in
vcsgeneric/profiles/vss/src/org/netbeans/modules/vcs/profiles/vss/mf-layer.xml;
/cvs/vcsgeneric/profiles/vss/src/org/netbeans/modules/vcs/profiles/vss/mf-layer.xml,v
 <--  mf-layer.xml
new revision: 1.2; previous revision: 1.1
done
Comment 27 Richard Gregor 2004-08-31 18:30:49 UTC
removed obsolete icon attribute.

Checking in mf-layer.xml;
/cvs/vcsgeneric/profiles/vss/src/org/netbeans/modules/vcs/profiles/vss/mf-layer.xml,v
 <--  mf-layer.xml
new revision: 1.3; previous revision: 1.2
done
Comment 28 Richard Gregor 2004-08-31 18:54:37 UTC
Removed url value from layers beacause of layer consistency - we don't
need them.

Checking in
profiles/cvsprofiles/src/org/netbeans/modules/vcs/profiles/cvsprofiles/mf-layer.xml;
/cvs/vcsgeneric/profiles/cvsprofiles/src/org/netbeans/modules/vcs/profiles/cvsprofiles/mf-layer.xml,v
 <--  mf-layer.xml
new revision: 1.4; previous revision: 1.3
done
Processing log script arguments...
More commits to come...
Checking in
profiles/pvcs/src/org/netbeans/modules/vcs/profiles/pvcs/mf-layer.xml;
/cvs/vcsgeneric/profiles/pvcs/src/org/netbeans/modules/vcs/profiles/pvcs/mf-layer.xml,v
 <--  mf-layer.xml
new revision: 1.3; previous revision: 1.2
done
Comment 29 Antonin Nebuzelsky 2004-09-02 14:03:47 UTC
Looks OK now. The main menu Versioning pulldown is displayed within 100ms.

I measured the following times:
without a VCS FS: 47ms, 16ms 16ms
with a VCS FS: 62ms, 15ms, 15ms
Comment 30 Richard Gregor 2004-09-02 15:00:47 UTC
Thank you! Fixed.
Comment 31 Peter Pis 2005-07-25 09:34:24 UTC
Verified.