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.
|
Description
_ tboudreau
2005-09-26 16:30:49 UTC
Created attachment 25189 [details]
Patch to eliminate most frequent calls to isDirectory()
This needs to be analzyed. Perf guys, please take a look at it. Feel free to re-assign if appropriate. I am looking at your patch. You are suggesting an API addition (I have no problem with this). The heuristic with names is perhaps acceptable though not quite safe. Manual building of URL is more controversial: is your patch OK wrt to non 7-bit ASCII chars? Even localized version "Documents and Settings" can contain them. Do you really think new URL(String) is faster than other constructors? java/api/src/org/netbeans/spi/java/classpath/support/ClassPathSupport.java - does your patch really helps here? When this code is called. Your normalized cache is leaking (only put()s no remove()). re startup time improvement - I did not check yet. > I am looking at your patch.
> You are suggesting an API addition (I have no problem with this). The heuristic
> with names is perhaps acceptable though not quite safe. Manual building of URL
> is more controversial: is your patch OK wrt to non 7-bit ASCII chars? Even
> localized version "Documents and Settings" can contain them. Do you really think
> new URL(String) is faster than other constructors?
The only thing the patch tries to do is eliminate as many calls to File.isDirectory() as possible and still
have NetBeans run - it's quick and dirty code. None of it is pretty or necessarily correct or necessarily
what we should do in production. If it shows the avenues we should explore, it serves its purpose.
Re non 7-bit ASCII - I have no idea, it would have to be tested - as for new URL(String), same thing - I
did think about the cost of the required try/catch. The only thing I'm trying to do is show that taking I/
O out of these code paths can make a significant difference in performance. Probably we should find
the changes that make the most significant differences and concentrate on how to do those in a correct
and safe way.
I'd be curious if the URL/URI caching/manual construction stuff makes a difference in JarClassLoader.
There will be some places where it's safe to do this sort of thing and some places it won't be.
OK, we know the File.isDirectory can be a problem and have a patch showing that there are possible improvements. This patch probably needs to be refined. Re try/catch block: should have negligible impact if there are no exception. re URL constructors - almost all versions boils down to the same one that parses URL so IMO there is no big difference re JarClassLoader: how big win can we get in constructor that is called 229 during startup? I guess we could get more if we speed up creating of URL that is returned from getResource OK I will built it and submit to our testing machines. I'll be curious to see the results. One place I notice a definite difference is plain old typing in the editor: The time between typing a character and it appearing (usually imperceptible but with the occasional hiccup) seems shorter - below the threshold of perception. Same for moving the caret between lines with the mouse. Maybe it is my imagination. Do we have tests for that? Also, do we run tests with jdk and/or project on an NFS mount? Created attachment 25671 [details]
jvmti agent
Created attachment 25672 [details]
premain class for JVMTI aganet
attached are sources of JVMTI agent that tracks who calls particular method (grouped by given number of stack elements). This is modified demo from JDK distribution. During start roughly half of calls goes through FileUtils.normalizeFile. We already know this I am going to file few other IZ records for possible improvements. Next step is to add reseting of counter so we can track this during typing. Lowering to P3 as we fixed some of these calls. Definitely we are going to continue. Probably most of the fixes will be done during next release. This should include improving in Java parsing (convert FO of platform CP elements to files) for example. The patch to FileUtil.java in particular looks dangerous. Perhaps we can use an LRU cache of some kind to try to reduce the number of calls to File.isDirectory rather than eliminating them. Pavel, looks like Radim also played with tracking agents. Anyway I believe your solution with java.lang.instrument is more portable. Maybe you can modify it to track also isDirectory... Anyway, as you help Radek with his MasterFS changes, you are probably the right one to take care and close this bug. Yes. I'll modify my agent. I've tried to reproduce the original scenario. Unfortunately, I didn't find the patched java.io.File to use the same measuring method, so I cannot be sure that my data use the same measuring method. I will do the measurements for the older versions to have comparable data. (and will attach my agent for further measurements.) From the initial measurements, it seems the number of isDirectory() method calls was reduced. I expect this is related to recent Filesystems changes and, maybe, java infrastructure changes. 42 : /usr/java/jdk1.6.0_04/jre/lib/rt.jar 60 : /usr/java/jdk1.6.0_04/jre/lib/ext/dnsns.jar 100: /tmp/JavaApplication1/src/javaapplication1/Main.java 32 : /usr/java/jdk1.6.0_04/src.zip 60 :/usr/java/jdk1.6.0_04/jre/lib/ext/sunpkcs11.jar 61 : /usr/java/jdk1.6.0_04/jre/lib/ext/localedata.jar Created attachment 56868 [details]
File.isDirectory() invocations
I measured the new values and dive into the problem. Seems that this issue is no longer valid, I tried the specified use-case and it seems it works correctly, see file above. On the other hand, we can still do some improvements here, but not sure about the gain. Bear in mind that testing has to be done with disabled assertions! Created attachment 56873 [details]
Samples of important call-stacks
. For the record, I particularly don't like the accesses from the JarClassLoader. We tried to avoid accessing the jars (in any way) during the startup, but the JarClassLoader ctor still needs to touch the disk, it seems, even when we're not really opening the jars at that time. And of course the IFL looks scary. I didn't even know it has so many clients, but every client access is multiplied by the number of clusters! Pavle: This problem appears only to cause serious performance on Windows (probably the implementation of file access in the JDK); if you are going to mark this as fixed, did you test it there? Yes, I run on Windows too. NetBeans are a bit slower, but I do not see huge problems. I did some raw measuring of File.isDirectory() on both, Ubuntu and XP platforms, see: http://wiki.netbeans.org/IOImprovementsDesc. Of course, we carry on all excessive I/O operations. I closed the issue because the number of original reported File.isDirectory() invocations was reduced significantly (of course, many other improvements can be done.) Feel free to reopen. At least,, suspicious calls described by nenik should be investigated. Well, probably the true test of this would be if you can work with a reasonably sized project on a USB drive without hangs... Maybe. -- Because we still do not have reliable data from I/O measuring (and still we don't know how to get them) we agreed with Jarda that we will focus on reducing I/O operations and we believe this will lead to the faster startup. c.f. issue 168389, probably some of the suggestions here are still worth looking at; while startup File I/O has been reduced, runtime performance still appears to be an issue issue 168389 looks like a duplicate of this; issue 169166 and issue 169160 both are related. It also might be worth looking at how the JDK actually implements these methods - in many cases, on Windows, there are multiple APIs to do the same thing (for example, listening for file changes - there are three Win32 APIs for it, and which you use depends on the version of windows). If the JDK is using the lowest common denominator, it might be possible for the problem to be improved at the source. This issue is far from fixed. In particular, I frequently still encounter multi-minute freezes of the AWT event thread,
and the thread dump is always in File.isDirectory(), File.isFile() or File.getCanonicalFile().
I did what I originally did - instrumenting java.io.File to record calls to isDirectory(), isFile() and
getCanonicalFile() (also a frequent bottleneck in thread dumps when NetBeans is frozen - see below).
"AWT-EventQueue-1" prio=6 tid=0x07a1c400 nid=0xa2c runnable [0x08a5e000]
java.lang.Thread.State: RUNNABLE
at java.io.WinNTFileSystem.canonicalize0(Native Method)
at java.io.Win32FileSystem.canonicalize(Win32FileSystem.java:414)
at java.io.File.getCanonicalPath(File.java:591)
at java.io.File.getCanonicalFile(File.java:616)
at org.openide.filesystems.FileUtil.normalizeFileOnWindows(FileUtil.java:1658)
at org.openide.filesystems.FileUtil.normalizeFile(FileUtil.java:1565)
at org.netbeans.modules.masterfs.filebasedfs.FileBasedURLMapper.getFileObjects(FileBasedURLM
apper.java:118)
at org.netbeans.modules.masterfs.MasterURLMapper.getFileObjects(MasterURLMapper.java:62)
at org.openide.filesystems.URLMapper.findFileObject(URLMapper.java:213)
at org.netbeans.modules.parsing.impl.indexing.RepositoryUpdater.getOwningSourceRoot(Reposito
ryUpdater.java:856)
(what this is doing running in the event queue, I have no idea)
Below is a list of the above named expensive I/O calls from NetBeans startup through 7 percent of 30 projects opened
(the added logging code is rather non-optimal), running on a real-world userdir with a number of NetBeans src module
projects open, a module suite and its modules, one web application, two j2se projects and one web application open, and
a number of files open in the editor. I will attach a log file with actual stack traces for these.
This is startup through editors initialized, project scanning completed, opening projects 7% complete:
1253 H:\work\nbsrc2
1253 H:\work\nbsrc2
562 H:\work\PatchFile\src\java\io\File.java
562 H:\work\PatchFile\src\java\io\File.java
180 C:\Documents and Settings\Administrator\My Documents\NetBeansProjects\AbbreviationsTutor
180 C:\Documents and Settings\Administrator\My Documents\NetBeansProjects\AbbreviationsTutor
177 H:\work\nbsrc2\applemenu
177 H:\work\nbsrc2\applemenu
172 C:\
172 C:\
167 H:\work\nbsrc2\nbbuild\netbeans\ide11
167 H:\work\nbsrc2\nbbuild\netbeans\ide11
154 H:\work\nbsrc2\project.ant
154 H:\work\nbsrc2\project.ant
148 H:\work\nbsrc2\mobility.project\src\org\netbeans\modules\mobility\project\ui\wizard\imports\WtkPanel.java
148 H:\work\nbsrc2\mobility.project\src\org\netbeans\modules\mobility\project\ui\wizard\imports\WtkPanel.java
148 H:\work\nbsrc2\mobility.project\src\org\netbeans\modules\mobility\project\ui\wizard\imports\WtkPanel.java
146 H:\work\nbsrc2\java.platform\src\org\netbeans\modules\java\platform\ui\PlatformsCustomizer.java
146 H:\work\nbsrc2\java.platform\src\org\netbeans\modules\java\platform\ui\PlatformsCustomizer.java
133 H:\work\PatchFile
133 H:\work\PatchFile
132 H:\work\nbsrc2\java.platform
132 H:\work\nbsrc2\java.platform
131 H:\work\nbsrc2\mobility.project
131 H:\work\nbsrc2\mobility.project
130 H:\work\PatchFile\src\java
130 H:\work\PatchFile\src\java
126 H:\work\PatchFile\src
126 H:\work\PatchFile\src
122 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\dnsns.jar
122 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\dnsns.jar
119 H:\work\nbsrc2\java.j2seplatform
119 H:\work\nbsrc2\java.j2seplatform
118 C:\Program Files\Java\jdk1.7.0
118 C:\Program Files\Java\jdk1.7.0
117 H:\work\nbsrc2\mobility.cldcplatform
117 H:\work\nbsrc2\j2me.cdc.platform
117 H:\work\nbsrc2\mobility.cldcplatform
117 H:\work\nbsrc2\j2me.cdc.platform
115 H:\work\nbsrc2\nbbuild
115 H:\work\nbsrc2\nbbuild
112 H:\work\nbsrc2\javacard.project
112 H:\work\nbsrc2\javacard.project
110 H:\work\nbsrc2\contrib\jemmysupport
110 H:\work\nbsrc2\contrib\jemmysupport
107 H:\work\nbsrc2\nbbuild\netbeans\enterprise5
107 H:\work\nbsrc2\nbbuild\netbeans\enterprise5
104 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\sunjce_provider.jar
104 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\sunjce_provider.jar
103 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\sunmscapi.jar
103 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\localedata.jar
103 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\sunmscapi.jar
103 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\localedata.jar
102 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\sunpkcs11.jar
102 H:\work\nbsrc2\jemmy
102 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\sunpkcs11.jar
102 H:\work\nbsrc2\jemmy
102 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\sunpkcs11.jar
100 C:\Documents and Settings\Administrator\My Documents\NetBeansProjects\WebApplication15
100 C:\Documents and Settings\Administrator\My Documents\NetBeansProjects\WebApplication15
I'll attach some logs for runtime behavior, turning off logging until full initializing, when working in the editor.
Given that these calls cause the editor to freeze, just moving the work out of the startup sequence doesn't really
address this issue at all - it just delays the expensive calls until they will have even more impact on runtime performance.
Created attachment 85785 [details]
Startup log
I modified my patch to be able to be turned on and off with a system property, and installed a module to add an action to set that property to true. The following is the number of expensive I/O calls after doing the following steps: - Start Netbeans on an existing userdir with a module suite application open, three J2SE projects open (one of them using an instance of JDK 5) and one web application open - Go to File > Start Logging to enable logging - Expand one non-nbsrc NetBeans module project - Change window focus to another window and do not give focus back to NetBeans until logging stops I'll attach the full log file. Note that all of this I/O was happening when NetBeans should be *idle*: 6057 C:\Program Files\Java\jdk1.5.0_06 2621 C:\Program Files\Java\jdk1.7.0 279 C:\Program Files\Java\jdk1.5.0_06\jre\lib\ext\dnsns.jar 275 C:\Program Files\Java\jdk1.5.0_06\jre\lib\ext\localedata.jar 272 C:\Program Files\Java\jdk1.5.0_06\jre\lib\ext\sunpkcs11.jar 256 C:\Program Files\Java\jdk1.5.0_06\jre\lib\ext\sunjce_provider.jar 240 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\dnsns.jar 239 C:\Program Files\Java\jdk1.5.0_06\jre\classes 236 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\localedata.jar 235 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\sunjce_provider.jar 235 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\sunmscapi.jar 235 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\sunpkcs11.jar 219 C:\Documents and Settings\Administrator\.nbbuild.properties 219 C:\Program Files\Java\jdk1.7.0\jre\classes 140 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\meta-index 136 C:\Program Files\Java\jdk1.5.0_06\jre\lib\rt.jar 132 C:\Program Files\Java\jdk1.5.0_06\jre\lib\jsse.jar 132 C:\Program Files\Java\jdk1.5.0_06\jre\lib\i18n.jar 132 C:\Program Files\Java\jdk1.5.0_06\jre\lib\sunrsasign.jar 131 C:\Program Files\Java\jdk1.5.0_06\jre\lib\jce.jar 131 C:\Program Files\Java\jdk1.5.0_06\jre\lib\charsets.jar 121 C:\Program Files\Java\jdk1.7.0\jre\lib\sunrsasign.jar 110 C:\Program Files\Java\jdk1.7.0\jre\lib\resources.jar 106 C:\Program Files\Java\jdk1.7.0\jre\lib\rt.jar 106 C:\Program Files\Java\jdk1.7.0\jre\lib\charsets.jar 106 C:\Program Files\Java\jdk1.7.0\jre\lib\jsse.jar 106 C:\Program Files\Java\jdk1.7.0\jre\lib\jce.jar 98 H:\work\TaxSheet\nbproject 89 H:\work\PatchFile\dist\PatchFile.jar Created attachment 85786 [details]
Logging w/ stack traces of expensive I/O calls after expanding one project
Created attachment 85787 [details]
Code used for logging
The attached zip file includes the projects used to generate these logs. PatchFile just contains a patched version of java.io.File w/ non-blocking logging code (logging is enabled by setting the system property "file.log" to "true") PatchFileTester adds an action to the file menu that toggles the system property. Note the logging code is very slow, due to use of CopyOnWriteArrayList and ConcurrentHashMap to avoid potential locking issues (although the periodic logging code probably does forcibly serialize some operations). A very simple case: Close all projects except one small J2SEProject with one Main class and one text file; before
shutting down, open Main. Shut down IDE.
Restart IDE. Wait 10 minutes to ensure all startup activities are finished. Position cursor at the opening { of the
main(String[]) method. Do not remove focus from IDE window, to avoid fs refresh activity. Wait again to ensure any I/O
that triggered by moving the caret is done. Now, simply press Enter.
The next attachment contains the full log of all files touched (includes files from projects that were closed before the
restart).
The following files had > 10 expensive I/O operations performed on them, simply by pressing Enter in the editor. See
next attached log for all files touched, with stack traces:
175 H:\work\ThingSorter\src\thingsorter\Main.java
74 H:\work\ThingSorter\src
60 H:\work\ThingSorter\src\thingsorter
44 H:\ud\var\cache\index\s1002\java\14
35 H:\ud\var\cache\index\s1002\java\14\checksums.properties
27 H:\ud\var\cache\index\s1002\timestamps.properties
26 C:\Program Files\Java\jdk1.7.0\jre\classes
23 H:\ud\var\cache\index\s1002\java\14\classes
22 C:\Program Files\Java\jdk1.7.0\jre\lib\sunrsasign.jar
16 H:\
15 H:\ud\var\cache\index\s1002\java
14 H:\work\ThingSorter\src\thingsorter\nbproject\project.xml
14 H:\work\ThingSorter\src\thingsorter\grails-app
14 H:\work\ThingSorter\src\thingsorter\pom.xml
12 H:\netbeans\ide11\jsstubs\allstubs.zip
11 H:\ud\var\cache\index\s1002
11 H:\work\ThingSorter\build\classes
Created attachment 85788 [details]
Log of I/O triggered by simply pressing Enter in the editor, w/ stack traces
The next log shows the expensive I/O calls triggered by the following:
- In the same Main class, invoke the start logging action, then add the lines
JFrame jf = new JFrame();
jf.setTitle("Foo");
jf.setVisible(true);
jf.setLayout (new BorderLayout());
using code completion where appropriate.
1606 H:\work\ThingSorter\src\thingsorter\Main.java
484 H:\work\ThingSorter\src
366 C:\Program Files\Java\jdk1.7.0\src.zip
267 H:\ud\var\cache\index\s1002
205 H:\ud\var\cache\index\s1002\TaskListIndexer\1\1
193 H:\ud\var\cache\index\s1002\java\14
167 H:\work\ThingSorter\src\thingsorter
160 C:\Program Files\Java\jdk1.7.0\jre\classes
144 C:\Program Files\Java\jdk1.7.0\jre\lib\sunrsasign.jar
139 H:\ud\var\cache\index\s1002\TaskListIndexer\1
128 H:\ud\var\cache\index\s1002\java
124 C:\Program Files\Java\jdk1.7.0
122 C:\Program Files\Java\jdk1.7.0\jre\lib\rt.jar
121 H:\ud\var\cache\index\s1002\org-netbeans-modules-jumpto-file-FileIndexer\1
112 C:\
111 H:\ud\var\cache\index\s22\java\14\classes
111 H:\ud\var\cache\index\s1002\org-netbeans-modules-jumpto-file-FileIndexer
110 H:\ud\var\cache\index\s1002\TaskListIndexer
80 H:\ud\var\cache\index\s22\java\14
77 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\dnsns.jar
72 C:\Program Files
71 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\sunjce_provider.jar
71 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\sunmscapi.jar
71 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\sunpkcs11.jar
71 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\localedata.jar
70 C:\Program Files\Java\jdk1.7.0\jre\lib\resources.jar
65 C:\Program Files\Java
62 H:\ud\var\cache\index\s22\java
58 C:\Program Files\Java\jdk1.7.0\jre\lib\charsets.jar
58 C:\Program Files\Java\jdk1.7.0\jre\lib\jsse.jar
58 C:\Program Files\Java\jdk1.7.0\jre\lib\jce.jar
56 H:\ud\var\cache\index\s45\java\14\classes
56 H:\ud\var\cache\index\s19\java\14\classes
56 H:\ud\var\cache\index\s21\java\14\classes
56 H:\ud\var\cache\index\s44\java\14\classes
56 H:\ud\var\cache\index\s14\java\14\classes
56 H:\ud\var\cache\index\s1000\java\14\classes
55 H:\ud\var\cache\index\s31\java\14\classes
55 H:\ud\var\cache\index\s17\java\14\classes
55 H:\ud\var\cache\index\s25\java\14\classes
55 H:\ud\var\cache\index\s28\java\14\classes
52 H:\ud\var\cache\index\s18\java\14\classes
52 H:\ud\var\cache\index\s42\java\14\classes
50 H:\ud\var\cache\index\s22
45 H:\ud\var\cache\index\s22\java\14\classes\java\awt
44 C:\Program Files\Java\jdk1.7.0\jre
43 C:\Program Files\Java\jdk1.7.0\nbproject\project.xml
42 H:\work\ThingSorter\src\thingsorter\nbproject\project.xml
42 H:\work\ThingSorter\src\thingsorter\pom.xml
42 H:\work\ThingSorter\src\thingsorter\grails-app
40 H:\ud\var\cache\index\s1002\java\14\checksums.properties
40 H:\ud\var
40 H:\ud
34 C:\Program Files\Java\jdk1.7.0\grails-app
34 C:\Program Files\Java\jdk1.7.0\pom.xml
30 H:\ud\var\cache
28 H:\
26 C:\Program Files\nbproject\project.xml
24 C:\Program Files\Java\nbproject\project.xml
24 H:\ud\config\Preferences\org\netbeans
24 H:\ud\var\cache\index\s45\java\14
24 H:\ud\config\Preferences\org\netbeans\modules
24 H:\ud\var\cache\index\s21\java\14
24 H:\ud\var\cache\index\s19\java\14
23 H:\ud\var\cache\index\s18\java\14
23 H:\ud\var\cache\index\s1000\java\14
23 H:\ud\var\cache\index\s17\java\14
23 H:\ud\var\cache\index\s42\java\14
23 H:\ud\var\cache\index\s44\java\14
23 C:\Program Files\Java\jdk1.7.0\jre\lib
23 H:\ud\var\cache\index\s25\java\14
22 H:\ud\var\cache\index\s14\java\14
22 H:\ud\var\cache\index\s1002\java\14\classes
21 C:\Program Files\Java\jdk1.5.0_06\jre\lib\ext\dnsns.jar
21 H:\ud\var\cache\index\s28\java\14
20 C:\Program Files\grails-app
20 H:\ud\var\cache\index\s31\java\14
20 C:\Program Files\pom.xml
19 C:\Program Files\Java\jdk1.5.0_06\jre\lib\ext\sunpkcs11.jar
19 H:\work\ThingSorter
19 C:\Program Files\Java\jdk1.5.0_06\jre\lib\ext\localedata.jar
19 C:\Program Files\Java\jdk1.7.0\lib\dt.jar
19 C:\Program Files\Java\jdk1.5.0_06\jre\lib\ext\sunjce_provider.jar
19 H:\netbeans\platform10\lib\boot.jar
19 H:\work\ThingSorter\build\classes
19 C:\Program Files\Java\jdk1.5.0_06\jre\classes
18 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\meta-index
18 C:\Program Files\Java\grails-app
18 C:\Program Files\Java\pom.xml
18 C:\Program Files\Java\jdk1.7.0\lib\tools.jar
17 H:\netbeans\platform10\lib\org-openide-util.jar
17 H:\netbeans\platform10\lib\org-openide-modules.jar
17 H:\work\PatchFile\dist\PatchFile.jar
14 H:\ud\var\cache\index\s22\java\14\classes\java
14 H:\ud\var\cache\index\s1000\java\14\classes\java
12 C:\Program Files\Java\jdk1.7.0\jre\pom.xml
12 C:\Program Files\Java\jdk1.5.0_06\jre\lib\rt.jar
12 C:\Program Files\Java\jdk1.7.0\jre\grails-app
12 C:\Program Files\Java\jdk1.7.0\jre\nbproject\project.xml
12 H:\ud\var\cache\index\s1000\java\14\classes\java\awt
11 H:\ud\config\Preferences\org\netbeans\modules\uihandler.properties
11 H:\ud\var\cache\index\s1002\java\14\classes\thingsorter\Main$X.sig
11 H:\work\ThingSorter\src\java
11 H:\ud\var\cache\index\s1002\java\14\classes\thingsorter\Main.sig
Created attachment 85789 [details]
Log for adding JFrame to main()
In the following case, I initiated logging, then
- Created a new project
- Using code completion and Override Methods and the Implement All Abstract Methods and Fix Imports hint where
appropriate, I created the code below.
In this case, I modified the filtering in the patched java.io.File to only log expensive I/O if it were performed in the
event thread. Simply typing this code in the editor resulted in a total of 32345 expensive blocking I/O calls performed
in the event thread. And bear in mind this is a simple J2SE project with no dependencies using the default JDK. There
were three J2SE projects open - ThingSorter (a project that simply sorts the logging output I've been pasting in below),
the project for patching java.io.File, and the project I created while logging was enabled.
public class Main {
public static void main(String[] args) {
JFrame jf = new JFrame() {
@Override
protected JRootPane createRootPane() {
return super.createRootPane();
}
@Override
public void repaint(long time, int x, int y, int width, int height) {
super.repaint(time, x, y, width, height);
}
@Override
public void setGlassPane(Component glassPane) {
super.setGlassPane(glassPane);
}
};
jf.setTitle("Hello");
jf.setLayout (new BorderLayout());
JButton jb = new JButton("Hello");
jf.add (jb, BorderLayout.CENTER);
jf.setVisible(true);
}
private static final class AL implements ActionListener {
public void actionPerformed(ActionEvent e) {
System.out.println("Hello world");
}
}
}
4206 H:\work\JavaApplication9\src\javaapplication9\Main.java
3684 H:\
1790 H:\work\JavaApplication9\src
1367 H:\netbeans\ide11\jsstubs\allstubs.zip
960 H:\ud\var\cache\index\s1010
726 H:\work\ThingSorter\src
720 H:\work\ThingSorter\test
715 H:\work\PatchFile\src
713 H:\work\PatchFile\test
697 H:\ud\var\cache\index\s1010\TaskListIndexer\1\1
666 H:\ud\var\cache\index\s1010\java\14
666 H:\work\JavaApplication9
519 H:\ud\var\cache\index\s1010\org-netbeans-modules-jumpto-file-FileIndexer\1
436 H:\ud\var\cache\index\s1010\TaskListIndexer\1
414 H:\ud\var\cache\index\s1010\java
358 C:\Program Files\Java\jdk1.7.0\jre\classes
354 H:\ud\var\cache\index\s1010\org-netbeans-modules-jumpto-file-FileIndexer
354 H:\ud\var\cache\index\s1010\TaskListIndexer
348 H:\work
319 C:\Program Files\Java\jdk1.7.0\jre\lib\sunrsasign.jar
282 H:\work\JavaApplication9\build
279 H:\work\JavaApplication9\test
251 C:\Program Files\Java\jdk1.7.0\src.zip
237 H:\work\JavaApplication9\src\javaapplication9
232 H:\work\JavaApplication9\dist
231 C:\Program Files\Java\jdk1.7.0\jre\lib\rt.jar
175 H:\ud\var\cache\index\s1010\timestamps.properties
173 H:\ud\var\cache\index\s1010\java\14\checksums.properties
149 H:\ud\var\cache\index\s22\java\14\classes
141 H:\work\JavaApplication9\nbproject\project.xml
139 C:\Program Files\Java
137 C:\Program Files\Java\jdk1.7.0
128 C:\
123 C:\Program Files
123 H:\work\JavaApplication9\nbproject
114 H:\work\JavaApplication9\build\generated-sources
113 H:\work\JavaApplication9\nbproject\private\private.properties
112 H:\ud\var\cache\index\s22\java\14
110 H:\work\JavaApplication9\nbproject\project.properties
109 H:\work\JavaApplication9\build\classes
109 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\dnsns.jar
102 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\localedata.jar
101 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\sunjce_provider.jar
101 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\sunmscapi.jar
101 C:\Program Files\Java\jdk1.7.0\jre\lib\ext\sunpkcs11.jar
100 C:\Program Files\Java\jdk1.7.0\jre\lib\resources.jar
Created attachment 85790 [details]
Log file for new project and adding code, filtered for only I/O in event thread
Some info I got from Jeff Richter, formerly of Microsoft, re Win32 file API calls. Probably the most relevant detail is that any call to File.isDirectory() will cause the OS to put the calling thread to sleep for some amount of time. - Is GetAttributesEx the optimal call to be using in modern versions of Windows? [JR] Yes. - Is there any internal synchronization that could be serializing such calls, making contention the source of the bottleneck? [JR] Absolutely. When you call GetAttributesEx, your thread calls into the kernel, the I/O request is queued to the device driver and your thread is put to sleep. The driver then handles the request (along with other queued requests) and wakes your thread up so it can return. Depending on the various outstanding I/O requests that are queued, they can't all happen at once especially if the disk head has to move. - At worst, is there any way to ensure that metadata about files which are frequently stat'd are retained in the OS filesystem cache? [JR] No as there could be hundreds of thousands of files and keeping all this data would hurt other parts of the system too much. - Any other thoughts on strategies to work around this issue? [JR] I've never heard of anything like you describe and I have been in this are for 20 years or so now. I can't really believe that GetAttributesEx is actually the problem at all. I would think that something else is happening. We're encountering this problem on fast, local drives - primarily NTFS - so I'm not talking about remote filesystems or USB drives or anything like that here. While we are working to cut down the amount of I/O performed, app- or VM-level attribute-caching is not an option because we need an accurate representation of the filesystem state. Windows has Event Tracing for Windows (ETW). This mechanism records/logs events that are happening in the system including I/O events. You can then filter these events down to see just the ones for a single process using tools like xperf.exe. I don't know if it offers as much details as you're looking for. I'd like to resurrect that ancient issues becase
a) self-profiler shows that 3sec out 11sec (or 30%) during initial load of the project goes to WinNTFileSystem.getBooleanAttributes()
b) i have a solution for that problem
Short answer ...
----------------
switch to proper java.nio API and never call any of File.isFolder(), File.getCanonicalFile(), File.getAbsoluteFile().
Long answer ...
----------------
1) It appears that native WinNTFileSystem.getBooleanAttributes() is a very resource-consuming operation. It is called once from File.isFolder() and many times from File.getCanonicalFile() and File.getAbsoluteFile() - it means that these calls should be avoided as much as possible.
Typical problemous code looks like following: `dir.listFile()` -> exclude non-files via `file.isDirectory()`.
Below is method using such implementation and which is the bottleneck for many operations:
masterfs\src\org\netbeans\modules\masterfs\filebasedfs\fileobjects\FileObjectKeeper.java
final class FileObjectKeeper implements FileChangeListener {
final synchronized FileObjectKeeper getKeeper(Collection<? super File> arr) {
if (keeper == null) {
keeper = new FileObjectKeeper(this);
List<File> ch = keeper.init(-1, null, false);
public List<File> init(long previous, FileObjectFactory factory, boolean expected) {
...
List<File> arr = new ArrayList<File>();
long ts = root.getProvidedExtensions().refreshRecursively(file, previous, arr);
try {
for (File f : arr) {
if (f.isDirectory()) {
continue;
}
It appears that java.nio provides one of the methods to list files absolutely without need for file.isDirecory(). The same functionality can be rewritten with java.nio like following:
List<Path> list = Files.find(dir, 1, (path, attrs)
-> !attrs.isDirectory()).collect(Collectors.toList());
Note: file `attrs` provided by find() can be cached for later use to avoid need to call methods like
file.isFolder(), file.length() and other later.
Look here for more details
https://docs.oracle.com/javase/8/docs/api/java/nio/file/attribute/BasicFileAttributes.html
Files.find() appears to be 10 times quicker than `dir.listFile()`->`file.isDirectory(), BUT wrong API appears to be 4 times slower.
Here are the results of JMH test (sources will be attached below). The test lists 'files-only' in Netbeans source directory with 50 iterations per 'operation' :
Benchmark Mode Cnt Score Error Units
MyBenchmark.dir_listFiles avgt 5 0.437 ? 0.064 s/op
MyBenchmark.path_find avgt 5 0.046 ? 0.001 s/op
MyBenchmark.path_walkTree avgt 5 1.702 ? 0.047 s/op
2) It appears that across sources of NetBeans there are places where usage of File.isFolder|getCanonicalFile|getAbsoluteFile() can be avoided by
- caching the 'canonical' path, isFolder flag, if its going to be used later multiple times
- not calling these methods one after another in the same method
Some examples of such cases can be found here: https://netbeans.org/bugzilla/show_bug.cgi?id=267990 ('flag' isNormalized can be made as a cacheble property of FileObject).
Created attachment 162048 [details]
JMH test mentioned at 2016-09-14 13:58:34 UTC
Below is one more code sample where unneeded call to file IO is invoked - in this case it is enough to check for binaryFile.isFile() - it will return false if file do not exist, preceding 'binaryFile.exists()' just have no sense here, but fill cause invocation of expensive "WinNTFileSystem.getBooleanAttributes[native] ()"
public class RepositoryForBinaryQueryImpl extends AbstractMavenForBinaryQueryImpl {
private List<Coordinates> getJarMetadataCoordinatesIntern(File binaryFile) {
if (binaryFile == null || !binaryFile.exists() || !binaryFile.isFile()) {
return null;
public static List<Coordinates> getJarMetadataCoordinates(File binaryFile) {
if (binaryFile == null || !binaryFile.exists() || !binaryFile.isFile()) {
return null;
Created attachment 162106 [details]
JMH test for various file access API's
I've created JMH test to check if some APIs from java.nio can be used to replace old file API in terms of performances. Results are not encouraging - below are the numbers for verifying of pre-collected lists of file paths in Netbeans install dir, Win7 x64 & Java 8 u102.
Running over --- 4399 --- paths
Benchmark Mode Cnt Score Error Units
FileAccess.file_new avgt 5 0.001 ? 0.001 s/op
FileAccess.file_exists avgt 5 0.233 ? 0.002 s/op
FileAccess.file_isFile avgt 5 0.231 ? 0.001 s/op
FileAccess.file_getAbsoluteFile avgt 5 ? 10?? s/op
FileAccess.file_getAbsolutePath avgt 5 ? 10?? s/op
FileAccess.file_getCanonicalFile avgt 5 0.572 ? 0.012 s/op
FileAccess.file_getCanonicalPath avgt 5 0.575 ? 0.004 s/op
FileAccess.path_toFile avgt 5 0.001 ? 0.001 s/op
FileAccess.paths_get avgt 5 0.008 ? 0.001 s/op
FileAccess.paths_exists avgt 5 0.383 ? 0.003 s/op
FileAccess.paths_exists_real avgt 5 0.383 ? 0.003 s/op
FileAccess.paths_toAbsolutePath avgt 5 ? 10?? s/op
FileAccess.paths_toRealPath avgt 5 1.895 ? 0.027 s/op
FileAccess.paths_toRealPath_nf avgt 5 2.027 ? 0.014 s/op
|