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.
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.
Quy, could you please look into this? Thanks!
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.
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.
> 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?
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.
> 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.
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.
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!
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)
> 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.
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).
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.
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 ?
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!
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.
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.
The jsfloader is checking every JSP and Java files.
why .java file ? doesn't it need to be a .jsp ? or at lease the directory to have a .jsp file.
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.
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!
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.
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?
Write a mock FileSystem that would delay (or count) queries for nonexistent file, then you can easily follow the scenarios...
> 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!
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)
Created attachment 70015 [details] second restart stack dump
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.
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.
Nigel, can you verify now?
yes, this is very much improved in the latest builds. Thank you very much :-)