{"action":"opened","issue":{"url":"https://api.github.com/repos/eclipse/che/issues/2567","repository_url":"https://api.github.com/repos/eclipse/che","labels_url":"https://api.github.com/repos/eclipse/che/issues/2567/labels{/name}","comments_url":"https://api.github.com/repos/eclipse/che/issues/2567/comments","events_url":"https://api.github.com/repos/eclipse/che/issues/2567/events","html_url":"https://github.com/eclipse/che/issues/2567","id":178824988,"number":2567,"title":"Performance issue for Che In Che with slow I/O /projects disk","user":{"login":"benoitf","id":436777,"avatar_url":"https://avatars.githubusercontent.com/u/436777?v=3","gravatar_id":"","url":"https://api.github.com/users/benoitf","html_url":"https://github.com/benoitf","followers_url":"https://api.github.com/users/benoitf/followers","following_url":"https://api.github.com/users/benoitf/following{/other_user}","gists_url":"https://api.github.com/users/benoitf/gists{/gist_id}","starred_url":"https://api.github.com/users/benoitf/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/benoitf/subscriptions","organizations_url":"https://api.github.com/users/benoitf/orgs","repos_url":"https://api.github.com/users/benoitf/repos","events_url":"https://api.github.com/users/benoitf/events{/privacy}","received_events_url":"https://api.github.com/users/benoitf/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":0,"created_at":"2016-09-23T09:15:01Z","updated_at":"2016-09-23T09:15:01Z","closed_at":null,"body":"Use Case : mount local folder into Eclipse Che workspace (for example che source code)\r\n\r\nOperation is done on macOs . So the mount is operated with docker osxfs which result in having slow I/O operations on this disk. Then any operation that may take 5 seconds with SSD host filesystem may take many seconds/minutes for the same operation using osxfs.\r\n\r\nI have then analyzed why it takes almost 10+ minutes to boot Eclipse Che + Workspace being ready (and by having all docker images cached, local M2 folder mounted)\r\n\r\n\r\nI’ve seen that some heavy I/O operations is taking time and I’ve analyzed some of them which are listed below. Note that it should also improve time on Linux and reduce heavy I/O operations\r\n\r\n**Reproduction Steps:**\r\n\r\nUsing macOs or Windows\r\n```\r\n$ git clone https://github.com/eclipse/che\r\n$ cd che\r\n$ che dir up\r\n```\r\n\r\n**Expected behavior:**\r\n\r\nBoot as fast as possible\r\n\r\n**Observed behavior:**\r\n\r\nWorkspace takes several minutes before being ready with project imported.\r\n\r\n\r\n## issue 1 : Chown of directory (1minute lost)\r\n\r\nhttps://github.com/eclipse/che/blob/af2f1098d7fafbac8faf463c5672d23d68ec2c80/wsmaster/che-core-api-agent/src/main/resources/agents/scripts/org.eclipse.che.ws-agent.script.sh#L26\r\n`${SUDO} sh -c \"chown -R $(id -u -n) /projects\"`\r\n\r\n(my che folder is using 1.1GB)\r\n`$ docker run -v $HOME/che:/projects/che -v $HOME/.m2:/home/user/.m2 -ti florentbenoit/che-in-che /bin/bash\r\n`\r\nSo in my test, we can see that user “user” already own the files\r\n\r\n```\r\nuser@ac6a5bec360f:/projects$ ls -la\r\ntotal 8\r\ndrwxr-xr-x  3 root root 4096 Sep 22 07:27 .\r\ndrwxr-xr-x 60 root root 4096 Sep 22 07:27 ..\r\ndrwxr-xr-x 38 user root 1292 Sep 21 14:16 che\r\n\r\n```\r\n```\r\nuser@ac6a5bec360f:/projects$ id -u -n\r\nuser\r\n\r\n```\r\n```\r\nuser@ac6a5bec360f:/projects$ ls -la che/\r\ntotal 236\r\ndrwxr-xr-x 38 user root  1292 Sep 21 14:16 .\r\ndrwxr-xr-x  3 root root  4096 Sep 22 07:27 ..\r\ndrwxr--r--  7 user user   238 Sep 21 14:26 .che\r\ndrwxr-xr-x  3 user user   102 Sep 21 10:10 .codenvy\r\n-rw-r--r--  1 user root   146 Jun 17 09:01 .dockerignore\r\ndrwxr-xr-x 17 user root   578 Sep 22 07:17 .git\r\n-rw-r--r--  1 user user    34 Sep 19 13:42 .gitattributes\r\n\r\n```\r\nAnd here the time that chown operation takes\r\n\r\n```\r\n$ date;sh -c \"chown -R $(id -u -n) /projects\";date\r\nThu Sep 22 07:30:44 UTC 2016\r\nThu Sep 22 07:31:45 UTC 2016\r\n\r\n```\r\n1mn to change something that is not needed on this case\r\n\r\n⇒  Proposed change : Check before using chown ?\r\n\r\n## issue 2 : FileTreeWatcher (2mn lost)\r\n\r\nWhen agent is booted, ProjectManager will call startup on File Tree Watcher\r\nhttps://github.com/eclipse/che/blob/5d267fe305dce3d151baf0c866393fbf733216f2/wsagent/che-core-api-project/src/main/java/org/eclipse/che/api/project/server/ProjectManager.java#L132\r\n\r\nWhich call walkTreeAndSetupWatches\r\nhttps://github.com/eclipse/che/blob/5d267fe305dce3d151baf0c866393fbf733216f2/wsagent/che-core-api-project/src/main/java/org/eclipse/che/api/vfs/impl/file/FileTreeWatcher.java#L168-L179\r\n\r\n\r\nTime of Workspace Agent to boot with these watches : 2 minutes\r\n```\r\nINFO: che(dir): \"[STDOUT] 2016-09-21 14:26:31,048[main]             [INFO ] [o.a.c.http11.Http11NioProtocol 470]  - Starting ProtocolHandler [\\\"http-nio-4401\\\"]\" \r\nINFO: che(dir): \"[STDOUT] 2016-09-21 14:26:31,055[main]             [INFO ] [o.a.catalina.startup.Catalina 642]   - Server startup in 126118 ms\" \r\n\r\n```\r\n\r\nTime of Workspace Agent to boot without these watches : 10 seconds\r\n`INFO: che(dir): \"[STDOUT] 2016-09-21 17:01:48,055[main]             [INFO ] [o.a.catalina.startup.Catalina 642]   - Server startup in 9882 ms\" \r\n`\r\n\r\n(I've removed call to add filewatchers on this test)\r\n\r\n⇒  Proposed change : Optimize, configure, disable these watchers to consume less time when I/O is slow ?\r\nWhat do we loose without them ?\r\n\r\n\r\n## issue 3 : Project Types\r\n\r\nBooting workspace will call ProjectRegistry initProjects\r\n```\r\norg.eclipse.che.api.project.server.type.ProjectTypeDef.resolveSources(ProjectTypeDef.java:181)\r\norg.eclipse.che.api.project.server.ProjectTypes.addTransient(ProjectTypes.java:125)\r\norg.eclipse.che.api.project.server.RegisteredProject.<init>(RegisteredProject.java:95)\r\norg.eclipse.che.api.project.server.ProjectRegistry.putProject(ProjectRegistry.java:208) org.eclipse.che.api.project.server.ProjectRegistry.initUnconfiguredFolders(ProjectRegistry.java:383)\r\norg.eclipse.che.api.project.server.ProjectRegistry.initProjects(ProjectRegistry.java:103)\r\n\r\n```\r\nThen, updating project type will loop as well in the same layers\r\n```\r\norg.eclipse.che.api.project.server.type.ProjectTypeDef.resolveSources(ProjectTypeDef.java:181)\r\norg.eclipse.che.api.project.server.ProjectTypes.addTransient(ProjectTypes.java:125)\r\norg.eclipse.che.api.project.server.RegisteredProject.<init>(RegisteredProject.java:95)\r\norg.eclipse.che.api.project.server.ProjectRegistry.putProject(ProjectRegistry.java:208)\r\norg.eclipse.che.api.project.server.ProjectManager.updateProject(ProjectManager.java:313)\r\norg.eclipse.che.api.project.server.ProjectService.updateProject(ProjectService.java:222)\r\n\r\n```\r\n\r\nProjectTypes addTransient method is iterating on all Provider Factory and create new instances each time\r\nhttps://github.com/eclipse/che/blob/c93bf4d0c2bda003ba6efd92f3fc3d9f9d492cf1/wsagent/che-core-api-project/src/main/java/org/eclipse/che/api/project/server/type/ProjectTypeDef.java#L181\r\n(so even if factories are handing some caches it won’t help)\r\n\r\n⇒ ProjectType does not seem to be optimized\r\n\r\n## issue 4 : GitValueProviderFactory (several minutes lost)\r\n\r\nWhen project type is checked on a folder, it will ask Git Project Type to provide values\r\nhttps://github.com/eclipse/che/blob/c93bf4d0c2bda003ba6efd92f3fc3d9f9d492cf1/wsagent/che-core-api-git/src/main/java/org/eclipse/che/api/git/GitValueProviderFactory.java#L58-L70\r\n\r\nThen we see that asking for current branch is resulting into\r\n`return Collections.singletonList(gitConnection.status(StatusFormat.LONG).getBranchName());`\r\n\r\n\r\nSo it calls `git status` to get current branch\r\n\r\nBut git status is iterating on all files\r\n```\r\n\tat sun.nio.fs.UnixFileAttributeViews$Posix.readAttributes(UnixFileAttributeViews.java:216)\r\n\tat sun.nio.fs.UnixFileAttributeViews$Posix.readAttributes(UnixFileAttributeViews.java:131)\r\n\tat org.eclipse.jgit.util.FileUtils.getFileAttributesPosix(FileUtils.java:689)\r\n\tat org.eclipse.jgit.util.FS_POSIX.getAttributes(FS_POSIX.java:258)\r\n\tat org.eclipse.jgit.treewalk.FileTreeIterator$FileEntry.<init>(FileTreeIterator.java:365)\r\n\tat org.eclipse.jgit.treewalk.FileTreeIterator.entries(FileTreeIterator.java:242)\r\n\tat org.eclipse.jgit.treewalk.FileTreeIterator.<init>(FileTreeIterator.java:227)\r\n\tat org.eclipse.jgit.treewalk.FileTreeIterator.createSubtreeIterator(FileTreeIterator.java:233)\r\n\tat org.eclipse.jgit.treewalk.AbstractTreeIterator.createSubtreeIterator(AbstractTreeIterator.java:572)\r\n\tat org.eclipse.jgit.treewalk.TreeWalk.enterSubtree(TreeWalk.java:1196)\r\n\tat org.eclipse.jgit.treewalk.TreeWalk.next(TreeWalk.java:814)\r\n\tat org.eclipse.jgit.lib.IndexDiff.diff(IndexDiff.java:437)\r\n\tat org.eclipse.jgit.lib.IndexDiff.diff(IndexDiff.java:377)\r\n\tat org.eclipse.jgit.api.StatusCommand.call(StatusCommand.java:148)\r\n\tat org.eclipse.che.git.impl.jgit.JGitStatusImpl.<init>(JGitStatusImpl.java:64)\r\n\r\n\r\n```\r\nSo to get current branch name it took 30seconds\r\n\r\nAs we call this several times, it may take 5minutes for 10 calls\r\n\r\n⇒ Proposed Change : Use getBranchName() of JGitConnection instead of using “status” command to get it\r\n\r\nResult is almost immediate\r\n\r\n## issue 5 Maven Project Type resolver\r\n\r\nWe iterate on all folders and go in the Project Types loop iterating again on all factories.\r\n→ slow process\r\n\r\nValueProviderFactories are not cached, knowing we iterate on all folders to get new projects and if value provider are not optimized, it takes a long long time\r\n\r\nAlso, why do we need to check against git project type for sub folders for example ? \r\n\r\n## Experiments\r\n\r\nNote : by hardcoding removal of all the listed operations or rewriting GitProvider, Eclipse Che + Workspace booted + Che updated project comes to < 3 minutes\r\n\r\n\r\n\r\n\r\n**Che version:**    5.0.0-M3\r\n**OS and version:** macOs or Windows\r\n**Docker version:** 1.12.1\r\n**Che install:**   docker\r\n\r\n**Additional information:**\r\n\r\n* Problem started happening recently, didn't happen in an older version of Che: [No]\r\n* Problem can be reliably reproduced, doesn't happen randomly: [Yes]\r\n"}}
{"actor":{"display_login":"benoitf"}}