Bug 65135 - Excessive calls to File.isDirectory() cause performance problems
Excessive calls to File.isDirectory() cause performance problems
Status: REOPENED
Product: platform
Classification: Unclassified
Component: -- Other --
5.x
All All
: P3 (vote)
: 6.x
Assigned To: Pavel Flaska
issues@platform
: PERFORMANCE
Depends on: 65700 65714 66361 169852 171330
Blocks:
  Show dependency treegraph
 
Reported: 2005-09-26 16:30 UTC by _ tboudreau
Modified: 2009-09-08 19:49 UTC (History)
8 users (show)

See Also:
Issue Type: DEFECT
:


Attachments
Patch to eliminate most frequent calls to isDirectory() (7.06 KB, application/x-gzip)
2005-09-26 16:32 UTC, _ tboudreau
Details
jvmti agent (32.98 KB, text/plain)
2005-10-07 14:54 UTC, _ rkubacki
Details
premain class for JVMTI aganet (2.69 KB, text/plain)
2005-10-07 14:55 UTC, _ rkubacki
Details
File.isDirectory() invocations (13.78 KB, text/plain)
2008-02-19 15:58 UTC, Pavel Flaska
Details
Samples of important call-stacks (31.02 KB, text/plain)
2008-02-19 16:36 UTC, Pavel Flaska
Details
Startup log (1.10 MB, application/x-bzip)
2009-08-04 21:50 UTC, _ tboudreau
Details
Logging w/ stack traces of expensive I/O calls after expanding one project (107.44 KB, application/x-bzip)
2009-08-04 22:16 UTC, _ tboudreau
Details
Code used for logging (51.10 KB, application/octet-stream)
2009-08-04 22:19 UTC, _ tboudreau
Details
Log of I/O triggered by simply pressing Enter in the editor, w/ stack traces (17.83 KB, application/x-bzip)
2009-08-04 22:37 UTC, _ tboudreau
Details
Log for adding JFrame to main() (95.54 KB, application/x-bzip)
2009-08-04 22:53 UTC, _ tboudreau
Details
Log file for new project and adding code, filtered for only I/O in event thread (140.63 KB, application/x-bzip)
2009-08-04 23:06 UTC, _ tboudreau
Details

Note You need to log in before you can comment on or make changes to this bug.
Description _ tboudreau 2005-09-26 16:30:49 UTC
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
Comment 1 _ tboudreau 2005-09-26 16:32:03 UTC
Created attachment 25189 [details]
Patch to eliminate most frequent calls to isDirectory()
Comment 2 Jan Chalupa 2005-09-27 08:56:59 UTC
This needs to be analzyed. Perf guys, please take a look at it. Feel free to
re-assign if appropriate.
Comment 3 _ rkubacki 2005-09-29 12:49:38 UTC
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.
Comment 4 _ tboudreau 2005-09-30 01:15:15 UTC
> 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.
Comment 5 _ rkubacki 2005-09-30 10:49:55 UTC
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.
Comment 6 _ tboudreau 2005-10-01 01:16:51 UTC
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?
Comment 7 _ rkubacki 2005-10-07 14:54:26 UTC
Created attachment 25671 [details]
jvmti agent
Comment 8 _ rkubacki 2005-10-07 14:55:00 UTC
Created attachment 25672 [details]
premain class for JVMTI aganet
Comment 9 _ rkubacki 2005-10-07 14:58:01 UTC
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.
Comment 10 _ rkubacki 2005-11-16 13:00:09 UTC
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.
Comment 11 Jesse Glick 2007-07-06 21:36:13 UTC
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.
Comment 12 Jaroslav Tulach 2008-02-11 09:48:47 UTC
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.
Comment 13 Pavel Flaska 2008-02-11 10:19:23 UTC
Yes. I'll modify my agent.
Comment 14 Pavel Flaska 2008-02-16 14:05:44 UTC
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
Comment 15 Pavel Flaska 2008-02-19 15:58:25 UTC
Created attachment 56868 [details]
File.isDirectory() invocations
Comment 16 Pavel Flaska 2008-02-19 16:03:24 UTC
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!
Comment 17 Pavel Flaska 2008-02-19 16:36:56 UTC
Created attachment 56873 [details]
Samples of important call-stacks
Comment 18 Pavel Flaska 2008-02-19 16:37:48 UTC
.
Comment 19 Petr Nejedly 2008-02-19 17:31:42 UTC
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!
Comment 20 _ tboudreau 2008-02-19 18:37:30 UTC
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?
Comment 21 Pavel Flaska 2008-02-20 08:54:27 UTC
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.
Comment 22 _ tboudreau 2008-02-20 23:14:33 UTC
Well, probably the true test of this would be if you can work with a reasonably sized project on a USB drive without hangs...
Comment 23 Pavel Flaska 2008-02-22 08:27:24 UTC
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.
Comment 24 _ tboudreau 2009-07-25 09:17:51 UTC
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.
Comment 25 _ tboudreau 2009-08-04 21:17:19 UTC
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.
Comment 26 _ tboudreau 2009-08-04 21:50:13 UTC
Created attachment 85785 [details]
Startup log
Comment 27 _ tboudreau 2009-08-04 22:15:10 UTC
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
Comment 28 _ tboudreau 2009-08-04 22:16:31 UTC
Created attachment 85786 [details]
Logging w/ stack traces of expensive I/O calls after expanding one project
Comment 29 _ tboudreau 2009-08-04 22:19:14 UTC
Created attachment 85787 [details]
Code used for logging
Comment 30 _ tboudreau 2009-08-04 22:21:42 UTC
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).
Comment 31 _ tboudreau 2009-08-04 22:36:45 UTC
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
Comment 32 _ tboudreau 2009-08-04 22:37:23 UTC
Created attachment 85788 [details]
Log of I/O triggered by simply pressing Enter in the editor, w/ stack traces
Comment 33 _ tboudreau 2009-08-04 22:52:28 UTC
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
Comment 34 _ tboudreau 2009-08-04 22:53:12 UTC
Created attachment 85789 [details]
Log for adding JFrame to main()
Comment 35 _ tboudreau 2009-08-04 23:05:39 UTC
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
Comment 36 _ tboudreau 2009-08-04 23:06:27 UTC
Created attachment 85790 [details]
Log file for new project and adding code, filtered for only I/O in event thread
Comment 37 _ tboudreau 2009-09-08 19:49:30 UTC
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.


By use of this website, you agree to the NetBeans Policies and Terms of Use. © 2012, Oracle Corporation and/or its affiliates. Sponsored by Oracle logo