[MAGNOLIA-6514] High usage of file descriptors caused by resource monitoring. Created: 26/Jan/16 Updated: 22/Mar/16 Resolved: 15/Mar/16 |
|
| Status: | Closed |
| Project: | Magnolia |
| Component/s: | resource-loader |
| Affects Version/s: | 5.4.4 |
| Fix Version/s: | 5.4.5 |
| Type: | Bug | Priority: | Critical |
| Reporter: | Rico Jansen | Assignee: | Ilgun Ilgun |
| Resolution: | Obsolete | Votes: | 1 |
| Labels: | support | ||
| Remaining Estimate: | 0d | ||
| Time Spent: | 5h | ||
| Original Estimate: | Not Specified | ||
| Environment: |
Java 8, OSX, Tomcat 7, Derby |
||
| Attachments: |
|
||||||||||||||||||||
| Issue Links: |
|
||||||||||||||||||||
| Template: |
|
||||||||||||||||||||
| Acceptance criteria: |
Empty
|
||||||||||||||||||||
| Task DoD: |
[ ]*
Doc/release notes changes? Comment present?
[ ]*
Downstream builds green?
[ ]*
Solution information and context easily available?
[ ]*
Tests
[ ]*
FixVersion filled and not yet released
[ ] 
Architecture Decision Record (ADR)
|
||||||||||||||||||||
| Bug DoR: |
[ ]*
Steps to reproduce, expected, and actual results filled
[ ]*
Affected version filled
|
||||||||||||||||||||
| Date of First Response: | |||||||||||||||||||||
| Sprint: | Basel 35 | ||||||||||||||||||||
| Story Points: | 2 | ||||||||||||||||||||
| Description |
|
I tested our Magnolia 5.4.2 to Magnolia 5.4.4 upgrade, and found something unexpected. In 5.4.4 you have the option to let Magnolia watch resources (which is the default): magnolia.resources.classpath.observation.pattern=.*\\.(ftl|yaml)$ However this results in a high use of filedescriptors, around 4500 filedescriptors, which is quite a lot. I tested the setting which watches 'nothing': magnolia.resources.classpath.observation.pattern=.*\\.(nonel)$ Which gave a use of around 2000 filedescriptors. If I want to watch css and js as well (which also live in the resources) like: magnolia.resources.classpath.observation.pattern=.*\\.(yaml|ftl|css|js)$ Magnolia no longer runs properly and uses close to 10000 filedescriptors which is the default limit on an OSX system. I can up the limit of course, but the numbers seem quite excessive. |
| Comments |
| Comment by Richard Gange [ 26/Jan/16 ] |
|
It should be noted that the reporter is using Derby. See |
| Comment by Richard Gange [ 26/Jan/16 ] |
|
To workaround this issue see: https://documentation.magnolia-cms.com/display/DOCS/Known+issues#Knownissues-Toomanyopenfiles |
| Comment by Ilgun Ilgun [ 15/Mar/16 ] |
|
Tried with magnolia-community-webapp(including travel-demo) + more than 1000 resources observation as follows;
Therefore, I am closing this ticket as obsolete since we already fixed the issue with 5.4.5 release. |
| Comment by Rico Jansen [ 18/Mar/16 ] |
|
The problem has not been solved, only postponed. When I start magnolia it indeed hovers around 2000 open files. However when I edit a resource and update it from IntelliJ the filedescriptor usage jumps to over 8000 and I can no longer work in Magnolia due to Too Many Open Files errors. |
| Comment by Ilgun Ilgun [ 18/Mar/16 ] |
|
Hello Rico, Can you please try do something like lsof | awk '{print $1}' | uniq -c | sort -rn | head
so that we can see what is actually using that much descriptors ? Cheers, |
| Comment by Rico Jansen [ 18/Mar/16 ] |
|
After startup:
disaster:.magnolia rico$ lsof | awk '{print $1}' | uniq -c | sort -rn | head
2374 java
717 idea
418 firefox
366 suggestd
330 Microsoft
306 Dock
272 Mail
260 soffice
243 Slack
237 Google
First attempt after updating an js file:
disaster:.magnolia rico$ lsof | awk '{print $1}' | uniq -c | sort -rn | head
lsof: can't open pipes: Too many open files in system
Second attempt after quiting an app to free some fds:
disaster:.magnolia rico$ lsof | awk '{print $1}' | uniq -c | sort -rn | head
8685 java
716 idea
366 suggestd
330 Microsoft
306 Dock
272 java
265 Mail
260 soffice
243 Slack
238 Google
|
| Comment by Rico Jansen [ 18/Mar/16 ] |
|
I made a dump specific to the java proces with lsof -p 58387 I have attached that, and made a simple extract. disaster:tmp rico$ cat /tmp/fd-dump.txt | awk '{ print $9 }' | sort | uniq -c | sort -rn | head -20 1816 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-site-vpronl-3.7-SNAPSHOT.jar 983 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/ckeditor-wrapper-for-vaadin-7.8.8.jar 904 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-standard-templating-kit-2.9.3.jar 488 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/mgwt-1.1.2.jar 424 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-templating-kit-3.7-SNAPSHOT.jar 266 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-site-cultura-3.7-SNAPSHOT.jar 188 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-site-3voor12-3.7-SNAPSHOT.jar 153 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-pip-templating-kit-3.7-SNAPSHOT.jar 151 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-site-zappechtgebeurd-3.7-SNAPSHOT.jar 129 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-site-wetenschap-3.7-SNAPSHOT.jar 128 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/commons-validator-1.4.0.jar 110 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-site-geschiedenis-3.7-SNAPSHOT.jar 105 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-site-woord-3.7-SNAPSHOT.jar 87 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-media-3.7-SNAPSHOT.jar 81 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-form-2.3.4.jar 76 /Library/Java/JavaVirtualMachines/jdk1.8.0_66.jdk/Contents/Home/jre/lib/ext/jfxrt.jar 66 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/scala-compiler-2.10.0.jar 53 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-site-tegenlicht-3.7-SNAPSHOT.jar 43 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-ui-vaadin-common-widgets-5.4.5.jar 43 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-public-user-registration-2.5.2.jar |
| Comment by Rico Jansen [ 18/Mar/16 ] |
|
Log file from the time I changed a resource. |
| Comment by Ilgun Ilgun [ 18/Mar/16 ] |
|
Dear Rico, I have tried it out one more time, Cheers |
| Comment by Rico Jansen [ 18/Mar/16 ] |
|
I can try that but the limit is currently 10000 (default on an OSX system). disaster:~ rico$ cat /tmp/x | awk '{ print $9 }' | sort | uniq -c | sort -rn | head -20 1823 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-site-vpronl-3.7-SNAPSHOT.jar 975 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/ckeditor-wrapper-for-vaadin-7.8.8.jar 891 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-standard-templating-kit-2.9.3.jar 497 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/mgwt-1.1.2.jar 426 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-templating-kit-3.7-SNAPSHOT.jar 265 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-site-cultura-3.7-SNAPSHOT.jar 190 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-site-3voor12-3.7-SNAPSHOT.jar 156 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-pip-templating-kit-3.7-SNAPSHOT.jar 149 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-site-zappechtgebeurd-3.7-SNAPSHOT.jar 131 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/commons-validator-1.4.0.jar 127 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-site-wetenschap-3.7-SNAPSHOT.jar 110 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-site-woord-3.7-SNAPSHOT.jar 106 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-site-geschiedenis-3.7-SNAPSHOT.jar 81 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-media-3.7-SNAPSHOT.jar 78 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-form-2.3.4.jar 75 /Library/Java/JavaVirtualMachines/jdk1.8.0_66.jdk/Contents/Home/jre/lib/ext/jfxrt.jar 69 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/scala-compiler-2.10.0.jar 53 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-site-tegenlicht-3.7-SNAPSHOT.jar 46 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-public-user-registration-2.5.2.jar 42 /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-ui-vaadin-common-widgets-5.4.5.jar disaster:~ rico$ jar tvf /Users/rico/projects/magnolia/trunk/magnolia-site/target/magnolia-3.7-SNAPSHOT/WEB-INF/lib/magnolia-module-vpro-site-vpronl-3.7-SNAPSHOT.jar | wc -l 1022 |
| Comment by Rico Jansen [ 18/Mar/16 ] |
|
I have been looking at the code with the debugger and found the point at which it all goes pearshaped:
final Set<String> modifiedResources = Maps.filterEntries(newEntries, new Predicate<Map.Entry<String, ClasspathEntry>>() {
@Override
public boolean apply(Map.Entry<String, ClasspathEntry> entry) {
final String path = entry.getKey();
final ClasspathEntry cpEntry = entry.getValue();
return monitoredResourcePattern.matcher(path).matches() && cpEntry.getLastModified() > previousReload;
}
}).keySet();
After this I am out of file descriptors. Also the first number is quite large for a replaced jar file with only 1022 files in it. |
| Comment by Aleksandr Pchelintcev [ 21/Mar/16 ] |
|
rico.jansen re: number of new entries - that is normal, since we reload refresh all the classpath entries from all the jars upon every refresh iteration. From algorithm point of view and file-descriptor-amount-wise that is not much different from 5.4.3 version since we still do not access the contents of most of the files. However, I made an attempt to reduce the amount of open file descriptors upon classpath refresh iteration even further. I attached a modified version of magnolia-resource-loader to the issue (also here's a corresponding pull-request: https://git.magnolia-cms.com/projects/PLATFORM/repos/main/pull-requests/140/overview), feel free to give it a shot (I personally didn't manage to crash my instance in any case). |