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 177547 - 12s in TreeView.expandNode while debugging
Summary: 12s in TreeView.expandNode while debugging
Status: RESOLVED FIXED
Alias: None
Product: platform
Classification: Unclassified
Component: Explorer (show other bugs)
Version: 6.x
Hardware: All All
: P3 normal (vote)
Assignee: Jaroslav Tulach
URL:
Keywords: PERFORMANCE
Depends on:
Blocks:
 
Reported: 2009-11-24 15:20 UTC by Exceptions Reporter
Modified: 2010-05-10 09:12 UTC (History)
2 users (show)

See Also:
Issue Type: DEFECT
Exception Reporter: 158219


Attachments
nps snapshot (256.00 KB, application/nps)
2009-11-24 15:21 UTC, Exceptions Reporter
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Exceptions Reporter 2009-11-24 15:20:59 UTC
Build: NetBeans IDE 6.8 Beta (Build 200910212001)
VM: Java HotSpot(TM) Client VM, 14.2-b01, Java(TM) SE Runtime Environment, 1.6.0_16-b01
OS: Windows XP, 5.1, x86

User Comments:
GUEST: Switced to the IDE after using other apps for a bout 2-3 hours.

jis: Added directory with NetBeans hg repository to Favorites view.

GUEST: debugging the grails application.

misterm: Expanding node on Favorites view

GUEST: Expanding NetBeans HG repository directory in Favorites


Maximum slowness yet reported was 19245 ms, average is 8489
Comment 1 Exceptions Reporter 2009-11-24 15:21:05 UTC
Created attachment 91633 [details]
nps snapshot
Comment 2 Vojtech Sigler 2009-11-25 05:33:23 UTC
Anyone, who ran into this issue, could you attach some reliable steps to reproduce? I have not managed to reproduce it using the descriptions above.
Comment 3 Martin Entlicher 2009-11-25 09:36:54 UTC
It looks there are mixed several different issues. E.g. the problem in snapshot-273622.nps has definitely nothing to do with debugger - it shows a problem in CvsVisibilityQuery. But the Time(CPU) is nonsense - 871 513 seconds (10 days!)

The snapshot about debugger (snapshot-177547.nps) shows that 9.6 seconds was spent at Object.wait(200) called 35 (or more) times.
This has happened because a lot of children were expanded at once.

IMHO the root of this bug is in javax.swing.JTree.setExpandedState(). This does not scale - an unknown number of children (more than 35 in this case) is expanded in a single run in AWT. Regardless of how fast Children.addNotify() is, you can add so many invocations that as a whole it takes too long.

Since we can not fix Swing, I'll make a workaround in TreeModelChildren...
Comment 4 Martin Entlicher 2009-11-26 08:27:06 UTC
Problem in TreeModelChildren is fixed in changeset:   154506:5dc319339b8b
http://hg.netbeans.org/main/rev/5dc319339b8b

The rest is:
- snapshot-273622.nps is probably corrupted, but CvsVisibilityQuery should not access disk in AWT.

- snapshot-273911.nps: loadgenerator

- snapshot-285017.nps: org.openide.nodes.EntrySupport$Lazy

- snapshot-291283.nps: org.openide.loaders.FolderChildren

- snapshot-294543.nps: org.openide.nodes.EntrySupport$Lazy

Moving to openide/nodes for fix in EntrySupport$Lazy.
Comment 5 t_h 2009-11-26 08:37:52 UTC
snapshot-285017.nps & snapshot-294543.nps - AWT is blocked in org.openide.nodes.EntrySupport$Lazy, but it does not mean it can be fixed there. It is waiting for org.openide.loaders.FolderChildren.addNotify(). FolderChildren should be asynchronous (Children.create(ChildFactory <T> factory, boolean asynchronous)).
Comment 6 Quality Engineering 2009-11-27 06:08:35 UTC
Integrated into 'main-golden', will be available in build *200911271400* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress)
Changeset: http://hg.netbeans.org/main/rev/5dc319339b8b
User: mentlicher@netbeans.org
Log: #177547 - Wait a shorter time when children are refreshed fast.
Comment 7 Jaroslav Tulach 2010-04-29 06:48:06 UTC
Let's use this issue to track
http://statistics.netbeans.org/exceptions/exception.do?id=285017
Comment 8 Jaroslav Tulach 2010-05-04 13:00:29 UTC
I looked at the problem and tried various ways to fix it, but the best one seems to be to speed up VisiblityQuery. As discussed today, use false positives - load the cache on background, meanwhile claim that your files are visible. If you want we can even find a way for you to be initialized in some "versioning initialization window" for next version.
Comment 9 Ondrej Vrabec 2010-05-06 08:51:03 UTC
Snapshots concerning the visibility query were made duplicates of bug #176533. Remaining snapshots (mostly debugger's fault) are said to be fixed in http://hg.netbeans.org/main/rev/5dc319339b8b.

However http://statistics.netbeans.org/exceptions/exception.do?id=369699 seems to be happening while debugging even with the fix.
Reassigning to debugger to evaluate the snapshot and eventually mark this as fixed.
Comment 10 Martin Entlicher 2010-05-06 12:57:43 UTC
Object.wait() takes 1 - 200 ms per call. It looks like JTree.fireTreeExpanded() can initiate several treeExpanded() calls if there is a lot of TreeExpansionListeners, or more probably, there are many calls to TreeView.expandNode() which adds runnables into a queue through VisualizerNode.runSafe(). All runnables are then executed together in AWT at VisualizerNode.QP.run(). If one getChildren() call takes 200ms (which is O.K. IMHO), and if 60 runnables are put into the queue, we get 12 seconds processing time. Therefore IMHO VisualizerNode should not run many runnables in a single dispatchEvent() call in AWT, because that does not scale.
Moving to Nodes to evaluate...
Comment 11 Jaroslav Tulach 2010-05-06 23:57:09 UTC
OK, so looking at:
http://statistics.netbeans.org/exceptions/exception.do?id=369699

1. there is too many Default Request Processors, I hope you have already merged them into one with throughput 1.

2. changing Visualizer.runSafe is unlikely. It needs to process the requests one by one and if it starts processing them in AWT, it needs to process all of them immediately. It cannot use invokeLater.

3. As a consequence of #2, the only way to not block the AWT thread is to prepare the work sooner then the tree.expandPath is called.

4. Looking at the stacktrace it actually seems that TreeNode.expandNode is called outside of AWT thread. So I could prepare the subnodes there.
Comment 12 Jaroslav Tulach 2010-05-07 00:16:23 UTC
core-main#08910ad8ec63
Comment 13 Quality Engineering 2010-05-10 09:12:55 UTC
Integrated into 'main-golden', will be available in build *201005100200* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress)
Changeset: http://hg.netbeans.org/main/rev/
User: 
Log: