Bug 269205 - 72-77% of time is spent in FilesystemInterceptorImpl.refreshRecursively
72-77% of time is spent in FilesystemInterceptorImpl.refreshRecursively
Status: VERIFIED FIXED
Product: cnd
Classification: Unclassified
Component: Remote VCS
8.1
PC Linux
: P2 (vote)
: 8.2
Assigned To: Vladimir Kvashin
issues@cnd
82patch1-verified
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2016-12-01 20:09 UTC by Vladimir Kvashin
Modified: 2016-12-11 02:35 UTC (History)
0 users

See Also:
Issue Type: DEFECT
:


Attachments
A patch with statistics - I haven't yet decided whether to push it; I think i should use profiler instead (6.45 KB, patch)
2016-12-01 20:11 UTC, Vladimir Kvashin
Details | Diff
A grepped IDE log with statistics (8.36 KB, text/plain)
2016-12-01 20:13 UTC, Vladimir Kvashin
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Vladimir Kvashin 2016-12-01 20:09:00 UTC
When remote file system reads directory that has not been cached yet, 72-77% of time is spent in FilesystemInterceptorImpl.refreshRecursively.

The scenario was as follows: I had a remote host that has been already set up, but file system cache was empty. The host was really slow (~400ms ping). I pressed "connect" button and waited until it gets green. As soon as it got green I pressed "open remote project" button and waited until file chooser is filled with the content of NetNeansProjects directory. Then I stopped measurements and quitted IDE.

When I switched remote VCS off via -J-Dremote.vcs.suport=false, it took 4-5 seconds (from pressing "open remote project" till the moment when file chooser was filled). With VCS on, it took 56-58 seconds.

Well, I haven't yet found all this 10x slowness. But I found about half of it. I used statistic measurements in code.

The stack is as follows:

	at org.netbeans.modules.remote.impl.fs.RemoteFileSystemTransport.stat(RemoteFileSystemTransport.java:181)
	at org.netbeans.modules.remote.impl.fileoperations.spi.FileOperationsProvider$FileOperations.isDirectory(FileOperationsProvider.java:175)
	at org.netbeans.modules.remotefs.versioning.spi.FileProxyProviderImpl$FileOperationsImpl.isDirectory(FileProxyProviderImpl.java:124)
	at org.netbeans.modules.versioning.core.api.VCSFileProxy.isDirectory(VCSFileProxy.java:280)
	at org.netbeans.modules.versioning.core.DelegatingVCS.hasMetadata(DelegatingVCS.java:360)
	at org.netbeans.modules.versioning.core.DelegatingVCS.getTopmostManagedAncestor(DelegatingVCS.java:178)
	at org.netbeans.modules.versioning.core.VersioningManager.getOwner(VersioningManager.java:452)
	at org.netbeans.modules.versioning.core.VersioningManager.getOwner(VersioningManager.java:348)
	at org.netbeans.modules.versioning.core.filesystems.VCSFilesystemInterceptor.getRefreshInterceptor(VCSFilesystemInterceptor.java:494)
	at org.netbeans.modules.versioning.core.filesystems.VCSFilesystemInterceptor.listFiles(VCSFilesystemInterceptor.java:391)
	at org.netbeans.modules.remotefs.versioning.spi.FilesystemInterceptorProviderImpl$FilesystemInterceptorImpl.refreshRecursively(FilesystemInterceptorProviderImpl.java:264)
	at org.netbeans.modules.remote.impl.fs.RemoteDirectory.updateChildren(RemoteDirectory.java:1362)
	at org.netbeans.modules.remote.impl.fs.RemoteDirectory.getDirectoryStorageImpl(RemoteDirectory.java:1150)
	at org.netbeans.modules.remote.impl.fs.RemoteDirectory.getDirectoryStorage(RemoteDirectory.java:532)
	at org.netbeans.modules.remote.impl.fs.RemoteDirectory.getFileObject(RemoteDirectory.java:410)
	at org.netbeans.modules.remote.impl.fs.RemoteFileObject.getFileObject(RemoteFileObject.java:421)
	at org.netbeans.modules.remote.impl.fs.RemoteDirectory.getFileObject(RemoteDirectory.java:402)
	at org.netbeans.modules.remote.impl.fs.RemoteFileSystem.findResourceImpl(RemoteFileSystem.java:565)

One of the problems is that at org.netbeans.modules.versioning.core.VersioningManager.getOwner(VersioningManager.java:452)
VersioningSystem[] vs = getVersioningSystems()
the array contains 8 instances of VersioningSystem, including local ones.
DelegatingVCS.hasMetadata calls VersioningSystem.getMetadataFolderNames() and then operates with these folders via VCSFileProxy.

The log (with flags -J-Dnativeexecution.support.logger.level=0 -J-Dremote.support.logger.level=0) shows that each folder is asked 8 times for stat/lstat. That's exactly for that reason.

What is probably the worst here is that these 8 lstat calls are asked *before* remote file system returns children to the caller.
Comment 1 Vladimir Kvashin 2016-12-01 20:11:16 UTC
Created attachment 163118 [details]
A patch with statistics - I haven't yet decided whether to push it; I think i should use profiler instead
Comment 2 Vladimir Kvashin 2016-12-01 20:13:47 UTC
Created attachment 163119 [details]
A grepped IDE log with statistics
Comment 3 Alexander Simon 2016-12-01 20:21:26 UTC
It is a remote file system problem.
I've told about separation remote file system from remote file artifices.
Comment 4 Vladimir Kvashin 2016-12-07 11:04:36 UTC
fixed in 63b7c38a886c, bcaf05cdfc7b on enum/release82
Comment 5 Vladimir Kvashin 2016-12-07 11:09:51 UTC
(In reply to Vladimir Kvashin from comment #4)
> fixed in 63b7c38a886c, bcaf05cdfc7b on enum/release82
Sorry, right change set is bcaf05cdfc7b
(although it also contains fix for issue 268361)
Comment 6 Quality Engineering 2016-12-08 02:36:39 UTC
Integrated into 'main-silver', will be available in build *201612080001* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress)

Changeset: http://hg.netbeans.org/main-silver/rev/2b227b168889
User: Vladimir Kvashin <vkvashin@netbeans.org>
Log: fixing #269205 - 72-77% of time is spent in FilesystemInterceptorImpl.refreshRecursively
(transplanted from 63b7c38a886c3b030385178c25e1c6de4b6090f8)
Comment 7 Quality Engineering 2016-12-11 02:35:35 UTC
Integrated into 'main-silver', will be available in build *201612110001* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress)

Changeset: http://hg.netbeans.org/main-silver/rev/f880e5e70140
User: Vladimir Kvashin <vkvashin@netbeans.org>
Log: addfix for #269205 - 72-77% of time is spent in FilesystemInterceptorImpl.refreshRecursively - use SPI instead of hard-coded extensions
(transplanted from 6e92ef9fb836bb7867961f21dba4e6105eb0ac93)


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