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 221213 - 31s - Children.findChild() calling many times into DataObject.find
Summary: 31s - Children.findChild() calling many times into DataObject.find
Status: RESOLVED FIXED
Alias: None
Product: platform
Classification: Unclassified
Component: Data Systems (show other bugs)
Version: 7.2
Hardware: All All
: P2 normal (vote)
Assignee: Jaroslav Tulach
URL:
Keywords: PERFORMANCE
Depends on:
Blocks:
 
Reported: 2012-10-31 23:35 UTC by darrenoh
Modified: 2012-12-21 02:34 UTC (History)
13 users (show)

See Also:
Issue Type: DEFECT
Exception Reporter: 194368


Attachments
nps snapshot (56.93 KB, application/nps)
2012-10-31 23:35 UTC, darrenoh
Details
nps snapshot (41.47 KB, application/nps)
2012-11-12 10:19 UTC, aquaglia
Details
nps snapshot (63.36 KB, application/nps)
2012-11-13 05:32 UTC, sidthesloth
Details

Note You need to log in before you can comment on or make changes to this bug.
Description darrenoh 2012-10-31 23:35:42 UTC
Build: NetBeans IDE 7.2 (Build 201207171143)
VM: Java HotSpot(TM) 64-Bit Server VM, 20.12-b01-434, Java(TM) SE Runtime Environment, 1.6.0_37-b06-434-10M3909
OS: Mac OS X

User Comments:
darrenoh: Running Xdebug on project hosted on network drive.



Maximum slowness yet reported was 31055 ms, average is 17357
Comment 1 darrenoh 2012-10-31 23:35:44 UTC
Created attachment 126894 [details]
nps snapshot
Comment 2 Tomas Hurka 2012-11-01 16:55:48 UTC
I am looking at http://statistics.netbeans.org/exceptions/exception.do?id=624211.

TreeModelChildren.applyChildren() is blocked by org.netbeans.modules.project.ui.ProjectTab$ProjectTreeView.expandNodes() in org.netbeans.modules.project.ui.ProjectTab thread. Project is on the slow FS and total 8s is spent in org.netbeans.modules.masterfs.filebasedfs.fileobjects.BaseFileObj.dumpFileInfo() in different places. See messages.log log for dumpFileInfo() output.
Comment 3 Jaroslav Tulach 2012-11-05 11:40:13 UTC
viewmodel comes from debugger.
Comment 4 aquaglia 2012-11-12 10:19:41 UTC
Created attachment 127600 [details]
nps snapshot

Running JUnit tests
Comment 5 Martin Entlicher 2012-11-12 14:02:41 UTC
Children.Keys.setKeys() is blocked on Mutex. I do not think I can do anything with this in viewmodel.
Other snapshots show this problem without presence of viewmodel.
Comment 6 sidthesloth 2012-11-13 05:32:33 UTC
Created attachment 127675 [details]
nps snapshot
Comment 7 Jaroslav Tulach 2012-11-13 06:39:47 UTC
I have seen some slowness report for treeview initial expansion as well. Usually they were caused by some HTML navigator stuff doing too much work under Children.MUTEX.writeAccess in some other thread. I've reassigned them to HTML navigator.

But I am not sure your case is the same. Aren't you just refreshing the nodes? Maybe that case could be handled more efficiently.

Btw. there was an idea that even the initial expansion in TreeView should not block EDT at all. Just schedule the computation to different thread and meanwhile display a busy mouse cursor. It is sort of the case right now anyway - getNodes() is called from EDT and getNodes(true) from other thread - instead of getNodes() one could start with an empty set of nodes...
Comment 8 Martin Entlicher 2012-11-13 10:39:26 UTC
Jardo, this is not about computation of nodes at all. Did you actually looked into the snapshots?

There is just *one* snapshot, where viewmodel is involved:
http://statistics.netbeans.org/exceptions/exception.do?id=624211

In the others, project.ui.support is involved and *no* viewmodel:
http://statistics.netbeans.org/exceptions/exception.do?id=624196
http://statistics.netbeans.org/exceptions/exception.do?id=624378
http://statistics.netbeans.org/exceptions/exception.do?id=626185
http://statistics.netbeans.org/exceptions/exception.do?id=627052
http://statistics.netbeans.org/exceptions/exception.do?id=628021
http://statistics.netbeans.org/exceptions/exception.do?id=628381

All these snapshots have something in common: Children.Keys.setKeys() sleeps on Mutex. I did not find, which thread holds the Mutex, someone who knows the code should be able to find this out.
If Children.Keys.setKeys() is really expected to block, it should be noted in the Javadoc IMHO, so that people know that they should not call it in AWT.
Comment 9 Jaroslav Tulach 2012-11-14 08:11:06 UTC
I can certainly look at all the reports, but not all of them are equal. Only few of them exceed 30s. I am trying to focus on those.

For example
http://statistics.netbeans.org/exceptions/exception.do?id=624196
is blocked by org.netbeans.modules.html.editor.gsf.HtmlStructureItem.getNestedItems(), but that is just 3.5s. Let's ignore that.

Then there is 9s in 
http://statistics.netbeans.org/exceptions/exception.do?id=628381
which goes again to HTML waiting for parsing under the lock:
org.netbeans.modules.html.navigator.HtmlElementNode$ElementChildren.createNodes()

So, yes, the HTML is likely the flaw, but there have already been other bugs reported against HTML and I hope the guys are working on fixing them.  The duplication algorithm analyses only EDT and these cases is of no use.

The reason why this was made P2 bug is the unique 31s in following report
http://statistics.netbeans.org/exceptions/exception.do?id=624211

As far as I can tell the Children.MUTEX read access is hold by 
org.netbeans.modules.project.ui.ProjectTab$ProjectTreeView.expandNodes()	
calling to 
org.openide.nodes.Children.findChild()	
and which then calls many times to
org.openide.loaders.DataObject.find()	

Thus at the end yes, the bug belongs to nodes.
Comment 10 Jaroslav Tulach 2012-12-19 10:21:03 UTC
Addressed by more efficient FolderChildren.findNode: ergonomics#fd98ffb7c475
Comment 11 bht 2012-12-20 02:30:21 UTC
Re-opening because the exception reporter pointed to it with the latest build.
id #641493 and the one before it. It has been classified as a duplicate of report #194368.

NetBeans GUI froze and my system just came to a complete halt for about 10 minutes.
Comment 12 Jaroslav Tulach 2012-12-20 05:15:57 UTC
(In reply to comment #11)
> Re-opening because the exception reporter pointed to it with the latest build.

My fix has been made today, so it is in. Anyway...

> id #641493 and the one before it. It has been classified as a duplicate of
> report #194368.

The reporter has problems detecting duplicates in this case and as such I manually created:
http://statistics.netbeans.org/analytics/detail.do?id=196785
and asked the system to create a bug for it in bugzilla. The problem comes from Maven, but it also shows extremely show I/O on your Windows machine.

> NetBeans GUI froze and my system just came to a complete halt for about 10
> minutes.

Ten minutes is attacks the longest snapshot record. I am surprised you managed to wait.

Your case is now tracked as bug 224065. Closing this one as fixed again.
Comment 13 Quality Engineering 2012-12-21 02:34:22 UTC
Integrated into 'main-golden', will be available in build *201212210001* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress)
Changeset: http://hg.netbeans.org/main-golden/rev/fd98ffb7c475
User: Jaroslav Tulach <jtulach@netbeans.org>
Log: #221213: More efficient FolderChildren.findNode - tries to avoid instantiating irrelevant DataObjects