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.
Synopsis: A user recently complained about very bad performance when working with a project on an encrypted disk. I duplicated the problem somewhat by creating a project on a USB drive. In particular, the call file.isDirectory() involves IO, and, at least on Windows, can be a serious bottleneck. Patching java.io.File to log calls to this method showed two things: 1. It is indeed slower 2. It is called *all* the time in NetBeans This could definitely account for some of the performance problems that user was experiencing - just typing a character in the editor causes this method to be called multiple times against the currently open file for each character typed; many operations cause it to be called against all jars on the bootclasspath. To get a real sense of the effect on performance of calls to this method being slow, try inserting a sleep() into a patched version of java.io.File and use NetBeans with that. I will attach an experimental patch to seriously reduce calls to this method - in particular to eliminate them from the critical path of typing in the editor. The patch does some things that may be questionable in practice, like assuming files ending in ".class"/".jar"/".java"/etc. are never directories, manually constructing URLs/URIs, etc. It does work on Windows and Macintosh - I have been running successfully with it for a few days. Subjectively, the effect seems profound: The "stuttering" feeling of typing in the editor is gone - the delay between clicking a line and the caret/highlight appearing there is below the threshold of perception; the same for typing characters in the ediitor. It *feels* faster in a way that's hard to put a finger on - many things (switching editor tabs, typing, menus) seem smoother. An unscientific stopwatch timing of startup time on my mac, with loaded J2SE projects and disk cache primed showed startup time to be significantly improved (30 seconds w/o patch, 21 seconds with), but that seems too large a difference to be believed - probably it has more to do with my disk cache. It sounds too good to be true, so I suspect I must be seeing what I want to see here. Or who knows, maybe it really is a "silver bullet". It would be interesting to see real scientific measurement of the performance differences running with the attached patch and not. --- Some numbers: NUMBER OF CALLS TO isDirectory() BY FILE - STARTUP WITH A 1-FILE J2SE PROJECT OPENED, MAKE 2 EDITS TO CONSTRUCTOR, INVOKE CC ONCE 227:C:\Program Files\Java\jdk1.6.0\jre\lib\rt.jar 134:C:\Program Files\Java\jdk1.6.0\jre\lib\ext\dnsns.jar 130:F:\JavaApplication1\src\javaapplication1\Main.java 129:C:\Program Files\Java\jdk1.6.0\src.zip 128:C:\Program Files\Java\jdk1.6.0\jre\lib\ext\sunpkcs11.jar 128:C:\Program Files\Java\jdk1.6.0\jre\lib\ext\localedata.jar 128:C:\Program Files\Java\jdk1.6.0\jre\lib\ext\sunjce_provider.jar 111:C:\Program Files\Java\jdk1.6.0\jre\lib\jsse.jar 110:C:\Program Files\Java\jdk1.6.0\jre\lib\jce.jar 110:C:\Program Files\Java\jdk1.6.0\jre\lib\charsets.jar 108:C:\space\filehack\dist\filehack.jar 92:F:\JavaApplication1\src 48:C:\Program Files\Java\jdk1.6.0\jre\lib\i18n.jar 48:C:\Program Files\Java\jdk1.6.0\jre\lib\sunrsasign.jar 39:F:\JavaApplication1\build\classes 31:F:\JavaApplication1\test 30:C:\space\filehack\build\classes 27:F:\JavaApplication1 25:C:\space\filehack\dist\javadoc 24:F:\JavaApplication1\dist\javadoc 22:C:\space\nb_other\nbbuild\netbeans\ide6\modules\org-netbeans-spi-debugger-ui. jar OPEN A FREEFORM PROJECT (JNN), OPEN ITS MAIN CLASS, INVOKE CODE COMPLETION ONCE: 440:C:\Program Files\Java\jdk1.6.0\jre\lib\rt.jar 308:C:\space\jnn 294:C:\Program Files\Java\jdk1.6.0\src.zip 242:C:\Program Files\Java\jdk1.6.0\jre\lib\ext\dnsns.jar 225:C:\Program Files\Java\jdk1.6.0\jre\lib\ext\sunpkcs11.jar 225:C:\Program Files\Java\jdk1.6.0\jre\lib\ext\localedata.jar 225:C:\Program Files\Java\jdk1.6.0\jre\lib\ext\sunjce_provider.jar 199:F:\JavaApplication1\src\javaapplication1\Main.java 192:C:\space\nb_other\nbbuild\netbeans 191:C:\space\filehack\dist\filehack.jar 186:C:\Program Files\Java\jdk1.6.0\jre\lib\jce.jar 186:C:\Program Files\Java\jdk1.6.0\jre\lib\charsets.jar 186:C:\Program Files\Java\jdk1.6.0\jre\lib\jsse.jar 157:C:\space\jnn\lib\Actions.jar
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