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 146618 - 38s wasted while expanding 51 files
Summary: 38s wasted while expanding 51 files
Status: RESOLVED FIXED
Alias: None
Product: obsolete
Classification: Unclassified
Component: visualweb (show other bugs)
Version: 6.x
Hardware: All All
: P2 blocker (vote)
Assignee: _ potingwu
URL:
Keywords: PERFORMANCE
Depends on:
Blocks: 144131 145851
  Show dependency tree
 
Reported: 2008-09-09 10:24 UTC by Jaroslav Tulach
Modified: 2008-09-24 12:17 UTC (History)
5 users (show)

See Also:
Issue Type: DEFECT
Exception Reporter:


Attachments
second restart stack dump (15.32 KB, text/plain)
2008-09-17 10:15 UTC, nleck
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Jaroslav Tulach 2008-09-09 10:24:30 UTC
While investigating issue 144131, adding numerous logging lines, running profiler in various possible and impossible 
configurations, Nigel managed to capture profiling snapshot:

http://www.netbeans.org/nonav/issues/showattachment.cgi/69382/nb_mk2.nps

It shows that in spite of JsfJavaDataLoader.findPrimaryFile is being called ~160x, it manages to generate ~1200 
queries for various non-existent files. As Petr Nejedlý explains, this is very costly:

> In a more general view, it seems that the biggest problem in this setup is that NFS is particularly slow when
> looking for nonexistent files (a thing that both versioning and jsf loader use widely). This is understandable - 
> if the (OS) user look for an explicitly named file that is not in local NFS cache, the server needs to be 
> consulted (every time). Query for >1500 nonexistent files -> >1500 network round trips, which can be at least 
> few milliseconds each.
> We should revisit the is-there-such-a-file pattern, as I fear it is used much more in the IDE.

We need to avoid it and get the number of touches bellow 200, in this particular case.
Comment 1 _ potingwu 2008-09-09 16:50:11 UTC
Quy, could you please look into this? Thanks!
Comment 2 Quy Nguyen 2008-09-10 01:44:13 UTC
Underlying issue is probably the same as Issue 145851.  As mentioned in the other issue, the implementation would need
to be changed significantly to prevent the file access.
Comment 3 Jaroslav Tulach 2008-09-10 08:24:02 UTC
I am afraid you will have to optimize the search or disable the faulty code completely. 38s slowdown is way to much to 
justify presence of such "feature" in the IDE.

Looking at the code I am curious to know why isJsfProjectFile(FileObject fo) does not use FileOwnerQuery (or similar) 
and only changes the project itself, why it continues up to the root of filesystem. Also consider adding some kind of 
caching, and make sure for each folder you do your "rich" file search just once.
Comment 4 _ potingwu 2008-09-10 17:13:45 UTC
> I am afraid you will have to optimize the search or disable the faulty code completely. 38s slowdown is way to much to
> justify presence of such "feature" in the IDE.

Yes, we are thinking about this, see Issue#145851.

> Looking at the code I am curious to know why isJsfProjectFile(FileObject fo) does not use FileOwnerQuery (or similar) 

It does use FileOwnerQuery before! But when the project creating is not yet finished, this method will return fatal
error!! I.e., when creating a Visual Web project, before the creating is finished, invoke this API on file objects under
this not-yet-created project will fail.

> and only changes the project itself, why it continues up to the root of filesystem. Also consider adding some kind of
> caching, and make sure for each folder you do your "rich" file search just once.

It does use cache in the codes. It will only do I/O once per one single project. It caches the project folder in String
instead of FileObject to even improve the performance. Then if the target file path starts with this cached string, it
just returns.

    public static Boolean isUnderJsfProjectDir(FileObject file) {
        String path = file.getPath();
        for (Map.Entry<String,Boolean> root : JsfProjectDir.entrySet()) {
            if (path.startsWith(root.getKey())) {
                return root.getValue();
            }
        }

        return null;
    }

> In a more general view, it seems that the biggest problem in this setup is that NFS is particularly slow when
> looking for nonexistent files (a thing that both versioning and jsf loader use widely).

If we use File.exists() instead, will that improve the performance?
Comment 5 Jaroslav Tulach 2008-09-10 17:53:47 UTC
Jesse is probably the best to talk about the project related behaviour.

Re. File.exists() is unlikely to make difference, as the problem is slow I/O on NFS, not the number of I/Os.

Re. caching and "1 I/O per project": Do you have any reasonable explanation why isJsfProjectFile is called 51 times 
and it results in 1206 calls into getFileObject!? Can you add some logging into your code, so we can ask Nigel to turn 
it on? Then we can get some idea of what files are being touched, why, whether there are some cache misses, etc.
Comment 6 _ potingwu 2008-09-10 18:08:18 UTC
> why isJsfProjectFile is called 51 times and it results in 1206 calls into getFileObject!?

It is possible. When searching $proj_dir/src/com/sun/foo/Bar.java, it checks whether the following 3 files exist,
  1. "nbproject/project.xml" or
  2. "nb-configuration.xml" or
  3. "nbproject/project.properties",
in directories,
  1. "$proj_dir/src/com/sun/foo" and
  2. "$proj_dir/src/com/sun" and
  3. "$proj_dir/src/com" and
  4. "$proj_dir/src" and
  5. "$proj_dir"

For the above example, one call of isJsfProjectFile invokes 15 getFileObject.

Searching file in deeper package will need more calls. But as I described for the cache, only one searching for one
single project.
Comment 7 Jesse Glick 2008-09-10 18:54:55 UTC
I'm not working actively on the project system. I can only say that it is a clear layering violation for an
implementation of DataLoader.findPrimaryFile to invoke project system methods and you should expect problems if you try
to do so. Probably you should not be using a special DataLoader to begin with.
Comment 8 _ potingwu 2008-09-10 21:48:11 UTC
I have improved the cache and scheme by further reducing the calls of getFileObject. Please try again under your
environment.
    changeset 1a4ab3986db8 in main
    details: http://hg.netbeans.org/main?cmd=changeset;node=1a4ab3986db8
and
    changeset c4b8253ff7b9 in main
    details: http://hg.netbeans.org/main?cmd=changeset;node=c4b8253ff7b9

Before my fix, I tried to expand all Java source, e.g., of the web/core module. I see isJsfProjectFile has been called
95 times, only the first one invokes 21 times of getFileObject. Then the rest 94 calls just return because of the cache
found.

After my fix, for the above sample that already not causing big problem, the total getFileObject calls reduced to 14
times. From the scheme and cache I have changed, under much worse condition you should see more improvement.

BTW, what is your testing target (what do you try to expand)? I can't simulate an environment that will need 1200
getFileObject calls! (though 160 isJsfProjectFile calls is understandable) Please help me create the environment so that
we can improve the issue clearly. Thanks!
Comment 9 nleck 2008-09-10 22:01:56 UTC
In our environment there are many ~5000 Java source files, NO jsp pages at all. These files are all stored on a NFS
mount ( yes, I know but it's corporate policy) 
Comment 10 _ potingwu 2008-09-10 22:48:56 UTC
> many ~5000 Java source files

Are they under NetBeans project tree? I suspect they are not and caused the cache not help. The cache only stores
project folder.
Comment 11 nleck 2008-09-10 23:01:16 UTC
The project itself is on a NFS mount. 

There are ~20 developers that share 2 big Sun boxes with 8 cpus and 32 gigs of ram each but... our home directory is on
a NFS mount ( I can't get all the developers home directors of this NFS mount). 
Comment 12 _ potingwu 2008-09-10 23:09:51 UTC
I found the cause; it's for the projects that were created by '... Existing Sources' or imported Eclipse projects.

These 'existing sources' are not under any NetBeans project structure, no Ant 'nbproject' or Maven 'pom.xml'. Cache in
isJsfProjectFile uses these flags to store the visited project folder.

nleck, could you please verify my guess by checking root of these '~5000 Java source files'? I believe they are not
under either 'nbproject' or 'pom.xml' structures.
Comment 13 nleck 2008-09-10 23:13:34 UTC
not sure what you mean... Yes, this project was created from an existing source base. The sources are in
${user.home}/src/DC and the project and build xml etc are in ${user.home}projects/DC

Is this the wrong structure ? 
Comment 14 _ potingwu 2008-09-10 23:18:07 UTC
No, it's not a wrong structure!

Yes, it's what I suspected. The cache does not work for 'created by existing sources'. I'm fixing it. Thanks!
Comment 15 _ potingwu 2008-09-10 23:57:22 UTC
Yes, it's the 'project created by existing sources' issue! Here is what I experienced:

- When expanding all sources under web/core where it's a regular NetBeans project
    95 isJsfProjectFile calls -> 21 getFileObject calls

- Creating a new project with existing sources based on web/core
    92 isJsfProjectFile calls -> 2838 getFileObject calls

after my todays' fix,
- the first case becomes,     95 isJsfProjectFile calls -> 14 getFileObject calls
- the second case becomes,    92 isJsfProjectFile calls -> 1892 getFileObject calls

The numbers are exactly what I computed; 33% improving: 21 x 2/3 = 14 & 2838 x 2/3 = 1892

Yes, I agree it's still not good enough. I will fix it further.
Comment 16 nleck 2008-09-11 00:17:56 UTC
can it not check if the file ( or if any in the directory) is a .jsp file before doing anything else. We have no .jsp
files at all. 
Comment 17 _ potingwu 2008-09-11 00:20:26 UTC
The jsfloader is checking every JSP and Java files.
Comment 18 nleck 2008-09-11 00:23:09 UTC
why .java file ? doesn't it need to be a .jsp ? or at lease the directory to have a .jsp file. 
Comment 19 Quality Engineering 2008-09-11 17:35:53 UTC
Integrated into 'main-golden', will be available in build *200809111401* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress)
Changeset: http://hg.netbeans.org/main/rev/1a4ab3986db8
User: potingwu@netbeans.org
Log: Partial fix for Issue#146618, P2, 38s wasted while expanding 51 files
Since project.xml and project.properties are always located in the same directory 'nbproject' (at least for Visual Web project if there is any exception for other special project), this fix can reduce 33% of the getFileObject calls.
Comment 20 _ potingwu 2008-09-16 00:19:20 UTC
Fixed in the 6.5 trunk,
    changeset c563c77785bd in main
    details: http://hg.netbeans.org/main?cmd=changeset;node=c563c77785bd

Now for the "Creating a new project with existing sources based on web/core" is
    98 isJsfProjectFile calls -> 52 getFileObject calls

I.e., for this sample project, the getFileObject calls have been reduced from 2838 to 52. I think that should improve
much of your experience.

Please try build#3780 or later to see whether it resolve your issue or not. Thanks!
Comment 21 Quality Engineering 2008-09-16 05:58:39 UTC
Integrated into 'main-golden', will be available in build *200809160201* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress)
Changeset: http://hg.netbeans.org/main/rev/c563c77785bd
User: potingwu@netbeans.org
Log: Fix Issue#146618, P2, 38s wasted while expanding 51 files.
Add cache for visited directories.
Comment 22 Jaroslav Tulach 2008-09-16 07:38:09 UTC
The result sounds promising. Is there a way to write automated test that deals with projects like nleck has? Do you 
have some tests already? Who should I talk to write a test to prevent regressions in this magnificent improvement?
Comment 23 Petr Nejedly 2008-09-16 08:55:18 UTC
Write a mock FileSystem that would delay (or count) queries for nonexistent file, then you can easily follow the
scenarios...
Comment 24 _ potingwu 2008-09-16 16:53:18 UTC
> Please try build#3780 or later to see whether it resolve your issue or not. Thanks!

BTW, for the public daily build, please use build *200809160201* or later. Thanks!
Comment 25 nleck 2008-09-17 10:11:59 UTC
just tried the lastest nightly build. It seems to lock up with the following stack dump:-

"AWT-EventQueue-1" prio=1 tid=0x09cf01c0 nid=0x672c in Object.wait() [0x8331e000..0x8331ee40]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x89daa750> (a org.openide.util.Mutex$QueueCell)
        at java.lang.Object.wait(Object.java:474)
        at org.openide.util.Mutex$QueueCell.sleep(Mutex.java:1602)
        - locked <0x89daa750> (a org.openide.util.Mutex$QueueCell)
        at org.openide.util.Mutex.enterImpl(Mutex.java:723)
        at org.openide.util.Mutex.enter(Mutex.java:630)
        at org.openide.util.Mutex.readEnter(Mutex.java:613)
        at org.openide.util.Mutex$Privileged.enterReadAccess(Mutex.java:1651)
        at org.openide.nodes.Children.attachTo(Children.java:206)
        at org.openide.nodes.Node.<init>(Node.java:236)
        at org.openide.nodes.FilterNode.<init>(FilterNode.java:193)
        at org.openide.nodes.FilterNode.<init>(FilterNode.java:174)
        at org.openide.loaders.DataFolder$ClonedFilter.<init>(DataFolder.java:342)
        at org.openide.loaders.DataFolder.getClonedNodeDelegate(DataFolder.java:438)
        at org.openide.loaders.FolderChildren.createNodes(FolderChildren.java:203)
        at org.openide.loaders.FolderChildren.createNodes(FolderChildren.java:66)
        at org.openide.nodes.Children$Keys$KE.nodes(Children.java:1572)
        at org.openide.nodes.EntrySupport$Lazy$EntryInfo.refreshNode(EntrySupport.java:1471)
        at org.openide.nodes.EntrySupport$Lazy$EntryInfo.getNode(EntrySupport.java:1455)
        - locked <0x89d9f538> (a java.lang.Object)
        at org.openide.nodes.EntrySupport$Lazy$LazySnapshot.get(EntrySupport.java:1674)
        at org.openide.nodes.EntrySupport$Lazy$LazySnapshot.get(EntrySupport.java:1662)
        at org.openide.explorer.view.VisualizerChildren.getChildAt(VisualizerChildren.java:116)
        at org.openide.explorer.view.VisualizerNode.getChildAt(VisualizerNode.java:319)
        at javax.swing.tree.DefaultTreeModel.getChild(DefaultTreeModel.java:156)
        at javax.swing.tree.FixedHeightLayoutCache$SearchInfo.getPath(FixedHeightLayoutCache.java:1448)
        at javax.swing.tree.FixedHeightLayoutCache.getPathForRow(FixedHeightLayoutCache.java:193)
        at javax.swing.plaf.basic.BasicTreeUI.getPathForRow(BasicTreeUI.java:527)
        at javax.swing.plaf.basic.BasicTreeUI.ensureRowsAreVisible(BasicTreeUI.java:1859)
        at javax.swing.plaf.basic.BasicTreeUI.toggleExpandState(BasicTreeUI.java:2193)
        at javax.swing.plaf.basic.BasicTreeUI.handleExpandControlClick(BasicTreeUI.java:2176)
        at javax.swing.plaf.basic.BasicTreeUI.checkForClickInExpandControl(BasicTreeUI.java:2130)
        at javax.swing.plaf.basic.BasicTreeUI$Handler.handleSelectionImpl(BasicTreeUI.java:3499)
        at javax.swing.plaf.basic.BasicTreeUI$Handler.handleSelection(BasicTreeUI.java:3484)
        at javax.swing.plaf.basic.BasicTreeUI$Handler.mousePressed(BasicTreeUI.java:3465)
        at java.awt.AWTEventMulticaster.mousePressed(AWTEventMulticaster.java:222)
        at java.awt.AWTEventMulticaster.mousePressed(AWTEventMulticaster.java:221)
        at java.awt.AWTEventMulticaster.mousePressed(AWTEventMulticaster.java:221)
        at java.awt.AWTEventMulticaster.mousePressed(AWTEventMulticaster.java:221)
        at java.awt.AWTEventMulticaster.mousePressed(AWTEventMulticaster.java:221)
        at java.awt.AWTEventMulticaster.mousePressed(AWTEventMulticaster.java:221)
        at java.awt.Component.processMouseEvent(Component.java:5514)
        at javax.swing.JComponent.processMouseEvent(JComponent.java:3135)
        at java.awt.Component.processEvent(Component.java:5282)
        at java.awt.Container.processEvent(Container.java:1966)
        at java.awt.Component.dispatchEventImpl(Component.java:3984)
        at java.awt.Container.dispatchEventImpl(Container.java:2024)
        at java.awt.Component.dispatchEvent(Component.java:3819)
        at java.awt.LightweightDispatcher.retargetMouseEvent(Container.java:4212)
        at java.awt.LightweightDispatcher.processMouseEvent(Container.java:3889)
        at java.awt.LightweightDispatcher.dispatchEvent(Container.java:3822)
        at java.awt.Container.dispatchEventImpl(Container.java:2010)
        at java.awt.Window.dispatchEventImpl(Window.java:1791)
        at java.awt.Component.dispatchEvent(Component.java:3819)
        at java.awt.EventQueue.dispatchEvent(EventQueue.java:463)
        at org.netbeans.core.TimableEventQueue.dispatchEvent(TimableEventQueue.java:104)
        at java.awt.EventDispatchThread.pumpOneEventForHierarchy(EventDispatchThread.java:242)
        at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:163)
        at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:157)
        at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:149)
        at java.awt.EventDispatchThread.run(EventDispatchThread.java:110)

Comment 26 nleck 2008-09-17 10:16:44 UTC
Created attachment 70015 [details]
second restart stack dump
Comment 27 nleck 2008-09-17 10:20:43 UTC
I think this issue should be re-opened... please check the stack dumps attached to see if this caused by this fix or a
different issue. 
Comment 28 Jaroslav Tulach 2008-09-17 15:14:35 UTC
No need to reopen this issue, we just received issue 147465. Let's leave this one for the speed problems and dedicate 
issue 147465 to the deadlock.
Comment 29 Jaroslav Tulach 2008-09-24 12:13:46 UTC
Nigel, can you verify now?
Comment 30 nleck 2008-09-24 12:17:08 UTC
yes, this is very much improved in the latest builds. 

Thank you very much :-)