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.

Bug 267990 - "assert assertNormalized()" in FileUtil.toFile() is the cause of general slowness of NetBeans
Summary: "assert assertNormalized()" in FileUtil.toFile() is the cause of general slow...
Status: NEW
Alias: None
Product: ide
Classification: Unclassified
Component: Performance (show other bugs)
Version: Dev
Hardware: PC Windows 7
: P2 normal (vote)
Assignee: Tomas Hurka
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2016-09-13 08:39 UTC by NukemBy
Modified: 2016-09-13 10:53 UTC (History)
0 users

See Also:
Issue Type: DEFECT
Exception Reporter:


Attachments
fs-access-in-netbeans.png (48.45 KB, image/png)
2016-09-13 08:39 UTC, NukemBy
Details
selfprofiler-with-fs-access.nps (65.42 KB, application/octet-stream)
2016-09-13 08:40 UTC, NukemBy
Details

Note You need to log in before you can comment on or make changes to this bug.
Description NukemBy 2016-09-13 08:39:37 UTC
Created attachment 162020 [details]
fs-access-in-netbeans.png

While debugging reasons of excessive slowness mentioned in this bug ("Running single simple unit test in debug takes 6+ seconds" https://netbeans.org/bugzilla/show_bug.cgi?id=267969) I came up to issues which cause general slowness to NetBeans everywhere in operations related to file system.

Let's take a look onto FileUtil.toFile() - body of the method looks like following:

    - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - 
    public static File toFile(FileObject fo) {
        File retVal = (File) fo.getAttribute("java.io.File"); // NOI18N;        

        if (retVal == null) {
            ... <truncated as not relevant> ...
        }
        assert assertNormalized(retVal, BaseUtilities.isMac()); // #240180
        return retVal;
    }
    - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - 

So - each and every call to FileUtils.toFile() causes call to assertNormalized(), which consequently invokes WinNTFileSystem.canonicalize() and that operation is awfully expensive. Taking into account that FileUtils.toFile() is invoked pleeeeeeeenty of times from various NB's APIs - it is actually bottleneck for entire NB. It seems that safeguarding against potential re-occurrence of problem mentioned in #240180 (https://netbeans.org/bugzilla/show_bug.cgi?id=240180) caused major performance problem by itself.

...

Digging deeper into file operations - I've found another similar case:

    - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - 
    private static File normalizeFileOnWindows(final File file) {
        File retVal = null;
        ...
        try {
            retVal = file.getCanonicalFile(); ...
        } catch (IOException e) {
            ...
        }
        // #135547 - on Windows Vista map "Documents and Settings\<username>\My Documents" to "Users\<username>\Documents"
        if((BaseUtilities.getOperatingSystem() & BaseUtilities.OS_WINVISTA) != 0) {
            if(retVal == null) {
                retVal = file.getAbsoluteFile();
            }
            String absolutePath = retVal.getAbsolutePath();
            if(absolutePath.contains(":\\Documents and Settings")) {  //NOI18N
                absolutePath = absolutePath.replaceFirst("Documents and Settings", "Users");  //NOI18N
                absolutePath = absolutePath.replaceFirst("My Documents", "Documents");  //NOI18N
                absolutePath = absolutePath.replaceFirst("My Pictures", "Pictures");  //NOI18N
                absolutePath = absolutePath.replaceFirst("My Music", "Music");  //NOI18N
                retVal = new File(absolutePath);
            }
        }

        return (retVal != null) ? retVal : file.getAbsoluteFile();
    }
    - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - 

here, to fix #135547, absolute path is extracted once again from retVal. 
And the problem here is call to "retVal.getAbsolutePath()" instead of "retVal.getPath()"

   Let's take a look into implementation of java.io.File ...

        public String getPath() {
            return path;
        }

        public String getAbsolutePath() {
            return fs.resolve(this);
        }

   ... I can see here that invocation of getAbsolutePath() will invoke "fs.resolve()", which internally goes to native file API (WinNTFileSystem.canonicalize|getBooleanAttributes()), and it means that expensive native FS operations will be invoked once again, but ...
   - if (retVal != null), then it will already contain absolute and resolved canonical path (from file.getCanonicalFile())
   - if (retVal == null), then it will be initialized as "retVal = file.getAbsoluteFile();"

   in both execution paths retVal will already contain 'absolute path' without need to re-compute 'absolute path' once again.


...

on top of that, NB's self profiler started while NB scans something at background shows that (WinNTFileSystem.canonicalize|getBooleanAttributes()) take roughly 15-20% of total time (I would say that normal percentage in comparison to parsing of sources should be less than 1%). 

I'm not familiar with NB's architecture to give some recommendations regarding code, but I would strongly recommend someone from NB team to allocate time to self profile NB and check if results of calls to native FS (like check for isFolder()) can be cached in more places than currently is implemented. 

Attaching a screenshot and one session of self-profiler (what anyone actually can get on its own at initial opening of huge project in NB). Note: screenshot and self-profiling is made AFTER "assert assertNormalized()" is commented out from "FileUtils.toFile()" - it means that excessive FS access comes from other places too.
Comment 1 NukemBy 2016-09-13 08:40:01 UTC
Created attachment 162022 [details]
selfprofiler-with-fs-access.nps
Comment 2 Tomas Hurka 2016-09-13 08:44:30 UTC
Note that "assert assertNormalized()" is invoked only in Dev. builds. Normal builds run with assertion disabled.
Comment 3 NukemBy 2016-09-13 10:53:48 UTC
I'm using dev builds all the time last 2-3 years - because it takes rather long time for new features to appear in Release version (with delay of up to one year), plus I have some own customizations which are even more harder to get into public release. Anyway ... I feel I need to check overall performance with assertions disabled - it may happen that even more heavy expressions are verified in assertions.