[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: Text File fd-dump.txt     File magnolia-resource-loader-5.4.6-SNAPSHOT.jar     Text File magnolia.log     PNG File screenshot-1.png    
Issue Links:
Relates
relation
is related to MGNLEE-414 Stop the installation if the open-fil... Closed
supersession
is superseded by MAGNOLIA-6523 Refactor ClasspathResourceOrigin and ... Closed
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 MAGNOLIA-6421

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;

  • 5.4.4 -> between 2700 and 4500 open files.
  • 5.4.5 -> stable 2000 open files.

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.
The edit I made was in impl.js which is locate in site-vpronl jar file.

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,
I added 300+ files to the module and edited some of them (your case), at most i got 5000 open file descriptors and eventually it gets lower by time.
Maybe you should consider increasing the limit?

Cheers

Comment by Rico Jansen [ 18/Mar/16 ]

I can try that but the limit is currently 10000 (default on an OSX system).
What I do find strange that 1823 fd's are used on a jar that only has 1022 files in it, of which 700 are in the 'watch' pattern list.
That is something that feels problematic to me. I'll look some more into it to see if I can figure out why that is.

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:
In info.magnolia.resourceloader.classpath.service.impl.devmode.DevelopmentModeClasspathService
Lines 138 to 145:

        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.
I was able to see the following info in the debugger:
newEntries: size = 17203
modifiedResources: size = 395

Also the first number is quite large for a replaced jar file with only 1022 files in it.
The last number looks reasonable for the replaced jar file.

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).

Generated at Mon Feb 12 04:15:14 CET 2024 using Jira 9.4.2#940002-sha1:46d1a51de284217efdcb32434eab47a99af2938b.