Bugzilla – Full Text Bug Listing
| Summary: | 100% CPU utilization while decorating large repository | ||||||||
|---|---|---|---|---|---|---|---|---|---|
| Product: | [Technology] EGit | Reporter: | Jean-Philippe Gariepy <jpgariepy> | ||||||
| Component: | UI | Assignee: | Philipp Thun <philipp.thun> | ||||||
| Status: | RESOLVED FIXED | QA Contact: | |||||||
| Severity: | critical | ||||||||
| Priority: | P3 | CC: | caniszczyk, christian.halstrick, jamesblackburn+eclipse, matthias.sohn, robin.rosenberg, stefan.lay | ||||||
| Version: | 0.8.1 | ||||||||
| Target Milestone: | 0.10.0 | ||||||||
| Hardware: | PC | ||||||||
| OS: | Linux-GTK | ||||||||
| Whiteboard: | |||||||||
| Bug Depends on: | 331273, 333204 | ||||||||
| Bug Blocks: | |||||||||
| Attachments: |
|
||||||||
|
Description
Jean-Philippe Gariepy
Maybe this change http://egit.eclipse.org/r/#change,1927 will help to fix this issue as well. It would be nice to have access to your big repo. Is this a public repo and can you share the URL? Sadly, this is a private repo. I can't share a URL. I did some further analyses and can reproduce (very) long decoration runs when there are many files (1000+) in a single directory which is opened in Eclipse (project explorer). Furthermore the performance of the decoration process seems to be non-linear with regards to the number of files shown. Can you provide some information on the structure of your repo, Jean-Philippe? Are there many files and only few directories? Are there some very big files? When do you see the 100% CPU utilization - when opening a folder within the project explorer? The average number of files per directory is 6.9 (max: 265), so no big directories. The average directory depth of files is 10 (range: [1-18]). Some files are rather large: about 300 files are bigger than 1 Mb (total is 1Gb). I've checked the option "Re-decorate ancestors when decorating changed resources" Maximum number of levels: Inf. I'm not sure what is the condition that triggers this behaviour. I'm trying to reproduce the problem with 0.9.1 but it doesn't happen. However, there are lots of GUI operations in the Package Explorer (expand a project, refresh) that will trigger the org.eclipse.ui.internal.decorators.LightweightDecoratorDefinition.decorate() method. This translates to high CPU usage for a few seconds (2-20). Thanks for providing this addtional information, Jean-Philippe. I have continued my analyses and did some optimizations. Here is the baseline - i.e. performance results for the following scenario: 1. Open a (Git shared) folder in Eclipse (project explorer) containing n files. 2. Wait until all resources have been decorated (time = t). | n | 1000 | 2000 | 3000 | --------------------------------------------- | t | 28 seconds | 66 seconds | 117 seconds | First optimization: http://egit.eclipse.org/r/2245 | n | 1000 | 2000 | 3000 | --------------------------------------------- | t | 14 seconds | 37 seconds | 74 seconds | | | (-14) | (-29) | (-43) | Second optimization: http://egit.eclipse.org/r/2247 | n | 1000 | 2000 | 3000 | -------------------------------------------- | t | 9 seconds | 19 seconds | 32 seconds | | | (-5) | (-18) | (-42) | This a dup of Bug 333204 which also relates to 331273. This proposed fix, while improving performance a little bit (and ok for that reason), does not resolve the issue. We can improve performance about ten times once we agree on the API changes in 331273. I found another issue related to decorations: when creating a new Eclipse workspace and then importing a Git project, all resources are decorated once even though they are not visible. When closing and re-opening Eclipse, this does not happen again. Re-measured performance for patch set 2 of change 2245 (immutable DirCache instance): same results Third optimization: http://egit.eclipse.org/r/2283 | n | 1000 | 2000 | 3000 | 4000 | 5000 | -------------------------------------------------------------------- | t | 5 seconds | 8 seconds | 11 seconds | 15 seconds | 19 seconds | | | (-4) | (-11) | (-22) | | | (In reply to comment #10) > Third optimization: http://egit.eclipse.org/r/2283 > > | n | 1000 | 2000 | 3000 | 4000 | 5000 | > -------------------------------------------------------------------- > | t | 5 seconds | 8 seconds | 11 seconds | 15 seconds | 19 seconds | > | | (-4) | (-11) | (-22) | | | These numbers are still dreadful. It cannot be that is has to take this long. I've never seen these kind of delays, so maybe some layout cause more slowdown than others. Some more profiling might help, including counting the number attempt to check for dirtyness. I had some yourkit sessions with our decoration code. Although a complete tracing of all egit/jgit code increases the runtime for such use-cases by factor 10 it still gives some nices hints. First hint: we still loose a lot of time because we are computing hashes on every file. I'll attach some yourkit reports if there is the first free timeslot during todays workshop I think we are pretty close to what is possible. To get a better estimation of the current timings, I deactivated the Git decorator and measured how long it takes to simply open a folder with n files in eclipse. This shows that the decoration time (t3 = t1 - t2) is down to just 2 to 5 seconds for 1000 to 5000 resources. | n | 1000 | 2000 | 3000 | 4000 | 5000 | -------------------------------------------------------------------- | t1 | 5 seconds | 8 seconds | 11 seconds | 15 seconds | 19 seconds | | t2 | 3 seconds | 6 seconds | 8 seconds | 11 seconds | 14 seconds | --------------------------------------------------------------------- | t3 | 2 seconds | 2 seconds | 3 seconds | 4 seconds | 5 seconds | Patch for third optimization (2283) Another small enhancement: http://egit.eclipse.org/r/2290 Re-measured t1 (time until decorations become visible). Re-calculated t3 (time difference compared to deactivated Git decorator). | n | 1000 | 2000 | 3000 | 4000 | 5000 | --------------------------------------------------------------------- | t1 | 5 seconds | 8 seconds | 11 seconds | 14 seconds | 18 seconds | | | | | | (-1) | (-1) | | t2 | 3 seconds | 6 seconds | 8 seconds | 11 seconds | 14 seconds | --------------------------------------------------------------------- | t3 | 2 seconds | 2 seconds | 3 seconds | 3 seconds | 4 seconds | Here is a breakdown for t3: t3a = GitDecoratorJob.run t3b = GitLightweightDecorator.decorate | n | 1000 | 2000 | 3000 | 4000 | 5000 | ------------------------------------------------------- | t3a | 400 ms | 700 ms | 1100 ms | 1500 ms | 1900 ms | | t3b | 300 ms | 400 ms | 500 ms | 600 ms | 700 ms | Ok, the breakdown explains it. Just get it through code review also. Created attachment 187251 [details]
call tree report for non-optimized code
I attach some Yourkit performance analysis files. They explain the huge improvement. I analyzed the usecase Philipp described for a folder with 1000 files. I used yourkit to create a calltree for all egit/jgit classes with cpu-times and invocation counts for all our methods. In the reports I expanded every part of the call-tree which used at least 5% to the overall cpu-time. I compared our current EGit/JGit master branches against a merged version containg the gerrit changes 2245/2283/2290. If you look at the report for the non-optimized code you see that for decorating a folder with 1000 files which lies in a repo with 15000 files we constructed DirCacheEntries 15.000.000 times (yes, 15 million times). If for every of the 1000 files we construct a new dircache which contains entries for all of our 15.000 files in the repo then you reach 15mio instantiations. Since we now use a single dircache which is in our case already read and cached before we trigger the decoration of the 1000-files-folder we are down from 15mio constructor calls down to 0. I attached the call-tree reports as text files and also the original yourkit snapshots. Created attachment 187252 [details]
call tree report for optimized code containing changes 2245,2283,2290
Yourkit (www.yourkit.com) snapshots for - non-optimized code: http://dl.dropbox.com/u/15639867/Decorate1000_master.snapshot -optimized code: http://dl.dropbox.com/u/15639867/decorate1000_2245_2283_2290.snapshot Next change: http://egit.eclipse.org/r/2306 This change optimizes the following use cases: 1. Expand project node 2. Open folder 3. Refresh (project) With the big test repository expanding the project node or refreshing everything took about 4 seconds. With this change this time is reduced to 0,3 seconds. The initial time when opening eclipse or importing a project is not changed by this optimization. (In reply to comment #20) > Next change: http://egit.eclipse.org/r/2306 > > This change optimizes the following use cases: > 1. Expand project node > 2. Open folder > 3. Refresh (project) > > With the big test repository expanding the project node or refreshing > everything took about 4 seconds. With this change this time is reduced to 0,3 > seconds. > > The initial time when opening eclipse or importing a project is not changed by > this optimization. this improvement has been merged as c03562f2202231d55e84eb761bb1462fd69a584a EGit 0.11 includes many performance improvements. |