Please use the Apache issue tracking system for new NetBeans issues (https://issues.apache.org/jira/projects/NETBEANS0/issues) !!
Bug 168389 - 15-63s in WinNTFileSystem.getBooleanAttributes
15-63s in WinNTFileSystem.getBooleanAttributes
Status: VERIFIED FIXED
Product: platform
Classification: Unclassified
Component: Filesystems
6.x
PC Windows XP
: P2 (vote)
: 6.x
Assigned To: Jiri Skrivanek
issues@platform
http://statistics.netbeans.org/except...
EXCEPTIONS_REPORT perf-profileme
: PERFORMANCE
: 192657 193770 (view as bug list)
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2009-07-10 11:20 UTC by dynamite
Modified: 2012-06-04 11:13 UTC (History)
14 users (show)

See Also:
Issue Type: DEFECT
:


Attachments
nps snapshot (5.85 KB, bin/nps)
2009-07-10 11:20 UTC, dynamite
Details
nps snapshot (7.39 KB, bin/nps)
2009-07-10 11:59 UTC, dynamite
Details
nps snapshot (9.35 KB, bin/nps)
2009-07-13 12:59 UTC, dynamite
Details
nps snapshot (24.29 KB, bin/nps)
2009-07-20 08:49 UTC, stefan79
Details
The Thread-dump for the latest Slowness detection (79.58 KB, application/octet-stream)
2009-07-20 08:54 UTC, stefan79
Details
Can we lower the presure on WinNT filesystem by caching the results? Btw. the final patch woudl need to clear the cache on fileRename (1.48 KB, patch)
2009-08-03 17:19 UTC, Jaroslav Tulach
Details | Diff
Today I installed NB6.8m1. The IDE made a rebuild of the index. Here´s the Snapshot of this rebuild. Maybe this helps at the discussion. (60.13 KB, application/octet-stream)
2009-08-04 12:15 UTC, stefan79
Details

Note You need to log in before you can comment on or make changes to this bug.
Description dynamite 2009-07-10 11:20:44 UTC
Build: NetBeans IDE Dev (Build 090709)
VM: Java HotSpot(TM) Client VM, 14.0-b16, Java(TM) SE Runtime Environment, 1.6.0_14-b08
OS: Windows XP, 5.1, x86

User Comments:
dynamite: I have the latest checkout of NB into which I have inserted a debug call into org.openide.filesystems.FileUtil.normalizeFileOnWindows() that outputs a message into the IDE log when java.io.File.getCanonicalFile() takes more than 3 seconds (as is the case here).  The actual path ends up in the log and this points to a directory in the NB cache .netbeans\dev\var\cache\index\s2\java\14.

I have seen this a few times now, which prompted me to put the logging in.  I have also seen similar delays in LocalFileSystem.lastModified()


Maximal alredy reported slowness was 15437 ms, average is 15437
Comment 1 dynamite 2009-07-10 11:20:58 UTC
Created attachment 84585 [details]
nps snapshot
Comment 2 dynamite 2009-07-10 11:59:48 UTC
Build: NetBeans IDE Dev (Build 090709)
VM: Java HotSpot(TM) Client VM, 14.0-b16, Java(TM) SE Runtime Environment, 1.6.0_14-b08
OS: Windows XP, 5.1, x86

User Comments: 
This is related to http://statistics.netbeans.org/analytics/exception.do?id=225822.

This time the file which takes a long time is C:\DOCUME~1\daniels\LOCALS~1\Temp\vcs-1247222892286 (which exists and is currently empty).  As an aside, in the 30 minutes that the IDE has been up, org.openide.filesystems.FileUtil.normalizeFileOnWindows() has been called 76362 times which is about 42 times a second.
Maximal alredy reported slowness was 64077 ms, average is 39757
Comment 3 dynamite 2009-07-10 11:59:52 UTC
Created attachment 84591 [details]
nps snapshot
Comment 4 Jiri Skrivanek 2009-07-10 20:27:56 UTC
From profiler snapshots I see the time is spent in WinNTFileSystem.getBooleanAttributes. I am afraid we can't do more if
two such calls take 127840 ms. It might be caused by overloading of your hard drive or operating system. Are you able to
describe any reproducible scenario with daily build?
Comment 5 Exceptions Reporter 2009-07-11 19:48:04 UTC
This issue already has 5 duplicates 
see http://statistics.netbeans.org/exceptions/detail.do?id=153566
Comment 6 dynamite 2009-07-13 12:59:20 UTC
Build: NetBeans IDE Dev (Build 090712)
VM: Java HotSpot(TM) Client VM, 14.0-b16, Java(TM) SE Runtime Environment, 1.6.0_14-b08
OS: Windows XP, 5.1, x86

User Comments: 

Maximal alredy reported slowness was 64077 ms, average is 28347
Comment 7 dynamite 2009-07-13 12:59:23 UTC
Created attachment 84653 [details]
nps snapshot
Comment 8 Exceptions Reporter 2009-07-13 12:59:29 UTC
This issue already has 6 duplicates 
see http://statistics.netbeans.org/exceptions/detail.do?id=153566
Comment 9 Jiri Skrivanek 2009-07-14 08:35:45 UTC
Feel free to reopen, if you provide requested information. I can reproduce such delays.
Comment 10 dynamite 2009-07-14 12:36:12 UTC
Sorry for the delay.  I originally found this with an unmodified DEV version of NB.   My colleagues also see this with
NB 6.5.  In each case the only significant load would seem to come from the NetBeans IDE.  In my experimentation is have
removed networked drives and disabled the no-access scan of the virus scanner.

There is no reliable set of steps that reproduces the problem, although I do encounter it a few times each day.  The
most common place where the delay occurs are for files/directories in java.io.tmpdir.  This is typically full with
NetBeans-related files that are largely no longer used (listed below with *** representing a time-stamp).  I wonder how
good WXP is at dealing with large directories (my guess is not very well).  My expectation is that if NetBeans was to
tidy-up after itself then this directory would stay small and may allow the issue to be side-stepped.

There are many directories (can be thousands) named vcs-*** which are empty (I have a patch for this which I will test
tomorrow).  They are created by an inner-class in DiffSidebar.java.  This class could safely delete these directories
when it has finished with them rather than leaving it to system shutdown.  Leaving these directories for delete-on-exit
may also slow down the closing of the IDE and I guess may account for users perceiving a slowing of the IDE over up-time.

groovy-generated-***-java-source directories are left with sub-directories, but without any java source.

There are many binary files named output***, many of which seem to be safe to be removed.  I'm guessing that they relate
to the tabs in the Output window and aren't being deleted when the tabs are closed or perhaps also when the content gets
overwritten.  These files can get quite big as well as being numerous.

I should also note that I'm suing Java 1.6.0_14; Java HotSpot(TM) Client VM 14.0-b16 on Windows XP version 5.1 running
on x86; Cp1252; en_GB
Comment 11 Jiri Skrivanek 2009-07-14 12:59:05 UTC
> The most common place where the delay occurs are for files/directories in java.io.tmpdir.

What do you mean by this sentence? Does the delay occur when you open a file from temp folder? Or when?


Comment 12 dynamite 2009-07-14 13:29:52 UTC
I am not doing anything directly with the temp folder.  I am however frequently running database queries.  Looking at a
generated Profile in front of my it seems I am locking in SQLHistoryPersistenceManager.create().  It seems reasonable
that the "SQL Command X" editor tabs put their returned data into the output*** files (rather than the Output window
tabs, which would explain why they are binary).

I have however also seem lock-ups whilst typing into the editor.  I'll pay more attention to the generated profile the
next time that happens.
Comment 13 Jiri Skrivanek 2009-07-15 11:25:50 UTC
BTW, development builds have turned assertions on. If you use FCS builds or turn it off in netbeans.conf (just remove
-J-ea), you can "improve" performance.
Comment 14 stefan79 2009-07-20 08:49:13 UTC
Build: NetBeans IDE Dev (Build 200907170201)
VM: Java HotSpot(TM) Client VM, 14.0-b16, Java(TM) SE Runtime Environment, 1.6.0_14-b08
OS: Windows XP, 5.1, x86

User Comments: 
I stepped into (Control+Mouceklick) a java-source-file (~11000 Rows).
Maximal alredy reported slowness was 64077 ms, average is 24771
Comment 15 stefan79 2009-07-20 08:49:18 UTC
Created attachment 84918 [details]
nps snapshot
Comment 16 Exceptions Reporter 2009-07-20 08:49:23 UTC
This issue already has 7 duplicates 
see http://statistics.netbeans.org/exceptions/detail.do?id=153566
Comment 17 Exceptions Reporter 2009-07-20 08:53:18 UTC
This issue already has 8 duplicates 
see http://statistics.netbeans.org/exceptions/detail.do?id=153566
Comment 18 stefan79 2009-07-20 08:54:07 UTC
Created attachment 84919 [details]
The Thread-dump for the latest Slowness detection
Comment 19 Exceptions Reporter 2009-07-20 10:23:31 UTC
This issue already has 10 duplicates 
see http://statistics.netbeans.org/exceptions/detail.do?id=153566
Comment 20 Exceptions Reporter 2009-07-20 10:24:18 UTC
This issue already has 10 duplicates 
see http://statistics.netbeans.org/exceptions/detail.do?id=153566
Comment 21 Exceptions Reporter 2009-07-21 07:20:26 UTC
This issue already has 11 duplicates 
see http://statistics.netbeans.org/exceptions/detail.do?id=153566
Comment 22 Exceptions Reporter 2009-07-21 12:32:18 UTC
This issue already has 14 duplicates 
see http://statistics.netbeans.org/exceptions/detail.do?id=153566
Comment 23 _ tboudreau 2009-07-25 09:09:51 UTC
WinNTFileSystem.getBooleanAttributes is a known bottleneck on Windows;  much worse if you're using a remote filesystem
or zip drive.  Unfortunately, File.isDirectory(), File.isFile() and File.toURI() all trigger invocations of it.

See issue 65135 - probably that should be reopened and this closed as a duplicate, or a dependency set on that one from
this one.  I know work has been done to reduce I/O during startup, but there are some other possible optimizations (URL
caching for APIs that require URLs to files), etc. which could be done successfully and impact runtime performance.
Comment 24 Petr Jiricka 2009-07-27 10:08:49 UTC
Lots of new information -> I think this issue is no longer INCOMPLETE.
Comment 25 Jiri Skrivanek 2009-07-27 11:23:10 UTC
There is a lot of duplicate reports. Each of them ends in WinNTFileSystem.getBooleanAttributes but they have different
origins. As Tim summarized it is Windows or JDK problem we can hardly workaround in filesystems. If you feel such calls
should be moved out of AWT thread, please, sort duplicates and assign them to appropriate module.
Comment 26 Jaroslav Tulach 2009-08-03 15:43:45 UTC
Pavel, this seems important and you are the owner of issue 65135. Can you lower the time from those 30s to less than 
10ms, please?
Comment 27 Jaroslav Tulach 2009-08-03 17:19:46 UTC
Created attachment 85714 [details]
Can we lower the presure on WinNT filesystem by caching the results? Btw. the final patch woudl need to clear the cache on fileRename
Comment 28 dynamite 2009-08-03 17:56:47 UTC
I think that my experience is in part down to the fact that I am currently creating some directories with a large number
of files and NTFS doesn't handle this well.  Perhaps NB could check for when File access is taking a long time and then
warn the user that this is the case?
Comment 29 Jiri Skrivanek 2009-08-04 08:49:11 UTC
I don't think we need additional cache. FileUtil.toFile() is already optimized and the call below skips time consuming
URLMapper processing for files.

(File) fo.getAttribute("java.io.File")
Comment 30 Jaroslav Tulach 2009-08-04 09:34:03 UTC
My cache was there to prevent FileUtil.normalizeFile(...) which is the most expensive call on Windows. If we can 
guarantee that masterfs returns normalized file from (File) fo.getAttribute("java.io.File") and that it caches the 
normalized variant, then we do not need my cache. However I am not sure if this is compatible with the original 
intention. I thought that fo.getAttribute("java.io.File").getPath().equals(fo.getPath()) for masterfs.

Anyway I just want to find out if my cache can lower the disk I/O. If so, we can seek for better implementation.
Comment 31 Jiri Skrivanek 2009-08-04 10:36:32 UTC
I suppose fo.getAttribute("java.io.File") returns normalized file. But I don't think it is too much expensive (just 15%
from toFile execution on my computer). Anyway it doesn't solve this issue. I didn't see FileUtil.normalizeFile() calls
in attached snapshots.
Comment 32 stefan79 2009-08-04 12:15:15 UTC
Created attachment 85763 [details]
Today I installed NB6.8m1. The IDE made a rebuild of the index. Here´s the Snapshot of this rebuild. Maybe this helps at the discussion.
Comment 33 Pavel Flaska 2009-08-04 16:51:07 UTC
I can say this is not definitely NetBeans issue. From the information provided, it hangs in native call. When you look around the Internet, the same problem is 
reported in different products (even the competitive products are not an exception). Problem can occur in different calls. We saw this problem several times.
Usage of cache does not guarantee that problem will disappear, it could reduce the number of hangs, but I doubt about such a solution.

For the time being, I would recommend to run filesystem integrity tool (fsck?}. Check, that you mounted drives are accessible. If not, try to unmount them.

We should try to provide logging mechanism of problematic files. It could help us to understand why NTFS is blocked and emulate the problem.
Comment 34 Pavel Flaska 2009-08-05 13:09:52 UTC
I have tried to run with suggested patch and cache is used in 80% throughout initial scan.
Comment 35 Jiri Skrivanek 2009-08-05 13:27:34 UTC
And how much is it faster with the patch?
Comment 36 Jaroslav Tulach 2009-08-05 17:33:39 UTC
I think that the cache can be beneficial slow disks or network drives (which do not cache on OS level). Then I'd 
expect 80% speedup. On a local disk, when OS caches repetitive calls, the speed up is not going to be significant. The 
only hope is by querying the WinNT less often, the 15s delays will not be that often. That is not guaranteed, but 
still, for the benefit of network drives I'd like the filesystem API to lower the amount of normalizeFile calls.
Comment 37 sreimers 2009-08-05 17:46:41 UTC
Looking at my actual development hardware and consider the disk activities I see (especially if memory runs low due to a
big platform being run in debugger), I think every call to WinNTFs, which can avoid is worth the effort. 

How about trying the same scenarios with new openjdk 7 builds? I think there may have been changes that could have an
effect, but maybe I am just completely wrong here.
Comment 38 Jiri Skrivanek 2009-09-02 13:41:14 UTC
I didn't apply jtulach's patch but I skipped normalization if file in toFile() comes from masterfs. It is already
normalized.
core-main #39aa41b4804d
Comment 39 Jaroslav Tulach 2009-09-02 14:53:31 UTC
Good, thanks. Let see if that helps.
Comment 40 Quality Engineering 2009-09-03 18:11:43 UTC
Integrated into 'main-golden', will be available in build *200909030951* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress)
Changeset: http://hg.netbeans.org/main-golden/rev/39aa41b4804d
User: Jiri Skrivanek <jskrivanek@netbeans.org>
Log: #168389 - Do not normalize file in toFile() if comes from masterfs - it is already mormalized.
Comment 41 Jan Becicka 2010-12-28 14:29:21 UTC
*** Bug 193770 has been marked as a duplicate of this bug. ***
Comment 42 Petr Cyhelsky 2012-06-04 11:13:34 UTC
*** Bug 192657 has been marked as a duplicate of this bug. ***


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