[
https://issues.apache.org/jira/browse/TOMEE-4293?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17805062#comment-17805062
]
Nicolas Ternisien edited comment on TOMEE-4293 at 1/10/24 10:45 AM:
--------------------------------------------------------------------
With a brand 2024 new-year motivation, I've performed some profiling via
VisualVM of the 2 scenarios I described in this ticket, with the original
application I mentioned here.
h4. ear-with-modules
With the following EAR structure:
company-ear (ear)
-> company-front (war)
-> company-domain (ejb-jar)
-> company-ws (ejb-jar)
-> company-digital-signature (ejb-jar)
This artifact structure loads in about 1min25secs, with 4-5 GB (when not
profiled by JVisualVM)
!ear-with-modules.memory-usage.jpg|width=1200!
As shown in the attached [^ear-with-modules.cpu-profiler.nps], about 20secs are
spent on AppInfoBuilder.build(), and about 20MB of OpenEJB references are
stored in memory (see [^ear-with-modules.memory-profiler.nps])
!ear-with-modules.cpu-profiler.jpg|width=1200!
------------------------
h4. ear-with-one-war-with-modules
At the opposite, with the following structure, after more than 10minutes and a
constant growing RAM consumption (+8 GB), the application startup is still
ongoing (still on OpenEJB stack). From my previous tests, with no profiling,
the app was still not started after 30minutes.
!ear-with-one-war-with-modules.memory-usage.jpg|width=1200!
EAR Structure:
(for the sake of simplicity, i kept the root EAR file, but deploying the
"company-front.war" has the same issues)
company-ear (ear)
-> company-front (war)
-> company-domain.jar (ejb-jar)
-> company-ws (ejb-jar)
-> company-digital-signature (ejb-jar)
As shown in the attached [^ear-with-one-war-with-modules.cpu-profiler.nps],
about 400secs (+) are spent on AppInfoBuilder.build(), and about 300MB of
OpenEJB references are stored in memory (see
[^ear-with-one-war-with-modules.memory-profiler.nps])
!ear-with-one-war-with-modules.cpu-profiler.jpg|width=1200!
Among others, the code bottlenecks (either in call count, or execution time)
seem to be the following:
org.apache.openejb.config.JndiEncInfoBuilder.getInterfaceBeanInfo (String) 264
503 ms (57,9 %) 266 530 ms (58,7 %) 9 840 210
org.apache.openejb.assembler.classic.EjbResolver.resolveInterface
(org.apache.openejb.assembler.classic.EjbResolver.Reference) 94 107 ms (20,6 %)
92 429 ms (20,4 %) 9 811 566
And if we compare the two profilings, this part of OpenEJB seems slower
org.apache.openejb.config.MergeWebappJndiContext.copy (java.util.Map,
java.util.Map) 16 352 ms (3,6 %) 16 248 ms (3,6 %) 10 212
I don't think the code at org.apache.openejb.config.JndiEncInfoBuilder or
org.apache.openejb.assembler.classic.EjbResolver.resolveInterface is
necessarily to be blamed (even though maybe replacing some ArrayList<String>
with TreeSet<String> or HashSet<String>) here and there could benefit to some
contains() calls), but rather that at registration time of the "collapsed EAR",
the EJB links are much more complex (or duplicated?) than with a plain standard
EAR file.
I hope these additional infos will help you spotting the issue
was (Author: lastnico):
With a brand 2024 new-year motivation, I've performed some profiling via
VisualVM of the 2 scenarios I described in this ticket, with the original
application I mentioned here.
h4. ear-with-modules
With the following EAR structure:
company-ear (ear)
-> company-front (war)
-> company-domain (ejb-jar)
-> company-ws (ejb-jar)
-> company-digital-signature (ejb-jar)
This artifact structure loads in about 1min25secs, with 4-5 GB (when not
profiled by JVisualVM)
!ear-with-modules.memory-usage.jpg|width=700!
As shown in the attached [^ear-with-modules.cpu-profiler.nps], about 20secs are
spent on AppInfoBuilder.build(), and about 20MB of OpenEJB references are
stored in memory (see [^ear-with-modules.memory-profiler.nps])
!ear-with-modules.cpu-profiler.jpg|width=700!
------------------------
h4. ear-with-one-war-with-modules
At the opposite, with the following structure, after more than 10minutes and a
constant growing RAM consumption (+8 GB), the application startup is still
ongoing (still on OpenEJB stack). From my previous tests, with no profiling,
the app was still not started after 30minutes.
!ear-with-one-war-with-modules.memory-usage.jpg|width=700!
EAR Structure:
(for the sake of simplicity, i kept the root EAR file, but deploying the
"company-front.war" has the same issues)
company-ear (ear)
-> company-front (war)
-> company-domain.jar (ejb-jar)
-> company-ws (ejb-jar)
-> company-digital-signature (ejb-jar)
As shown in the attached [^ear-with-one-war-with-modules.cpu-profiler.nps],
about 400secs (+) are spent on AppInfoBuilder.build(), and about 300MB of
OpenEJB references are stored in memory (see
[^ear-with-one-war-with-modules.memory-profiler.nps])
!ear-with-one-war-with-modules.cpu-profiler.jpg|width=700!
Among others, the code bottlenecks (either in call count, or execution time)
seem to be the following:
org.apache.openejb.config.JndiEncInfoBuilder.getInterfaceBeanInfo (String) 264
503 ms (57,9 %) 266 530 ms (58,7 %) 9 840 210
org.apache.openejb.assembler.classic.EjbResolver.resolveInterface
(org.apache.openejb.assembler.classic.EjbResolver.Reference) 94 107 ms (20,6 %)
92 429 ms (20,4 %) 9 811 566
And if we compare the two profilings, this part of OpenEJB seems slower
org.apache.openejb.config.MergeWebappJndiContext.copy (java.util.Map,
java.util.Map) 16 352 ms (3,6 %) 16 248 ms (3,6 %) 10 212
I don't think the code at org.apache.openejb.config.JndiEncInfoBuilder or
org.apache.openejb.assembler.classic.EjbResolver.resolveInterface is
necessarily to be blamed (even though maybe replacing some ArrayList<String>
with TreeSet<String> or HashSet<String>) here and there could benefit to some
contains() calls), but rather that at registration time of the "collapsed EAR",
the EJB links are much more complex (or duplicated?) than with a plain standard
EAR file.
I hope these additional infos will help you spotting the issue
> WAR-wide EJB local refs linked to each EJB at startup
> -----------------------------------------------------
>
> Key: TOMEE-4293
> URL: https://issues.apache.org/jira/browse/TOMEE-4293
> Project: TomEE
> Issue Type: Bug
> Components: TomEE Core Server
> Affects Versions: 8.0.16
> Reporter: Nicolas Ternisien
> Assignee: Jonathan Gallimore
> Priority: Major
> Attachments: collapsedear-bug-ear.catalina.out,
> collapsedear-bug-ear.ear, collapsedear-bug-project.tar.gz,
> collapsedear-bug.war, collapsedear-bug.war.catalina.out,
> ear-with-modules.cpu-profiler.jpg, ear-with-modules.cpu-profiler.nps,
> ear-with-modules.memory-profiler.nps, ear-with-modules.memory-usage.jpg,
> ear-with-one-war-with-modules.cpu-profiler.jpg,
> ear-with-one-war-with-modules.cpu-profiler.nps,
> ear-with-one-war-with-modules.memory-profiler.nps,
> ear-with-one-war-with-modules.memory-usage.jpg
>
>
> h3. High Memory Consumption / Load Time when using WAR file (as "Collapsed
> EAR") vs EAR file
> We're currently experimenting the migration of an EAR project from Oracle
> Weblogic application server to TomEE.
> While conducting this experiment, we also tried to see if we could rely on
> "Collapsed EAR" approach, ie, simplifying the deployable by providing a
> single WAR file with EJBs embedded into it, instead of multiple ejb and web
> modules inside the EAR file.
> The project is quite big with:
> * 1992 EJBs in EJB Module (+ CDI beans)
> * 1193 EJBs in Web Module (+ CDI beans for JAX RS resources)
> * (and a total of 8569 injection points via @EJB annotation - you can keep
> this info for later)
> Still, with the EAR approach, total loading time on TomEE 8.0.16 is about
> 1min, with 3.1 GB JVM memory usage, so this is quite good (way faster than
> Oracle Weblogic).
> When trying the alternative approach via a WAR file (including the EJB module
> as JAR) on TomEE 8.0.16, the startup takes huge time (30 to 40 minutes) and
> JVM memory consumption goes up to 8.7 GB.
>
> h3. How to Reproduce
> We tried to investigate this difference and we have identified the bottleneck
> (via TomEE startup debugging) at JndiEncInfoBuilder, more especially at
> JndiEncInfoBuilder.buildEjbRefs() where each EJB has the *whole* list of
> ejbLocalRef of all the EJBs of the entire application. We are not very sure
> if this is an expected behavior, but each EJB referenced is linked to the
> 8569 injection points discovered.
> We've setup a dedicated project (in attachment), with 2 different deployable
> binaries:
> * collapsedear-bug.war
> * collapsedear-bug-ear.ear
> So that we could reproduce the issue at a smaller scale and compare the two
> processes at loading time.
> Note the deployment is performed via the "tomee/apps" folder. We only
> deployed on archive at a time, to be able to properly compare the two
> startups.
> Both WAR and EAR contains an EJB module, named "collapsedear-bug-ejb", which
> itself contains the following basic EJB NumberService.java:
> {code:java}
> package org.lastnico.collapsedear.bug.ejb;
> import java.util.Random;
> import javax.annotation.PostConstruct;
> import javax.ejb.EJB;
> import javax.ejb.Singleton;
> import javax.ejb.Startup;
> import org.slf4j.Logger;
> import org.slf4j.LoggerFactory;
> @Singleton
> @Startup
> public class NumberService {
> private static Logger log = LoggerFactory.getLogger(NumberFinder.class);
> @PostConstruct
> public void start() {
> log.info("Starting {}", this.getClass());
> }
> @EJB
> private NumberFinder userFinder;
> public long save() {
> return new Random().nextLong();
> }
> }
> {code}
>
> Of course, this project is much more simple (less than 5 EJBs in total), so
> we cannot really notice any measurable hit from memory consumption or loading
> time perspective, but, still, here are the debugging output:
>
> h4. collapsedear-bug.war
> At startup, with a debugging breakpoint, watching for "NumberService" EJB
> registration
> at
> {code}
> org.apache.openejb.config.JndiEncInfoBuilder.build(final JndiConsumer
> jndiConsumer, final String ejbName, final String moduleId, final URI
> moduleUri, final JndiEncInfo moduleJndiEnc, final JndiEncInfo compJndiEnc)
> throws OpenEJBException {
> {code}
> {code:java}
> moduleId = collapsedear-bug-ejb
> jndiConsumer.ejbClass = "org.lastnico.collapsedear.bug.ejb.NumberService"
> jndiConsumer.ejbLocalRef =
> {java:comp/env/org.lastnico.collapsedear.bug.ejb.NumberService/userFinder=EjbLocalRef{name='java:comp/env/org.lastnico.collapsedear.bug.ejb.NumberService/userFinder',
> local=org.lastnico.collapsedear.bug.ejb.NumberFinder, link='null',
> mappedName='null', lookupName='null'},
> java:comp/env/org.lastnico.collapsedear.bug.war.GreetingResource/numberFinder=EjbLocalRef{name='java:comp/env/org.lastnico.collapsedear.bug.war.GreetingResource/numberFinder',
> local=org.lastnico.collapsedear.bug.ejb.NumberFinder, link='null',
> mappedName='null', lookupName='null'},
> java:comp/env/org.lastnico.collapsedear.bug.war.GreetingResource/calculatorFront=EjbLocalRef{name='java:comp/env/org.lastnico.collapsedear.bug.war.GreetingResource/calculatorFront',
> local=org.lastnico.collapsedear.bug.war.CalculatorFront, link='null',
> mappedName='null', lookupName='null'},
> java:comp/env/org.lastnico.collapsedear.bug.war.CalculatorFront/numberFinder=EjbLocalRef{name='java:comp/env/org.lastnico.collapsedear.bug.war.CalculatorFront/numberFinder',
> local=org.lastnico.collapsedear.bug.ejb.NumberFinder, link='null',
> mappedName='null', lookupName='null'}}{code}
>
> You can see that ejbLocalRef contains 8 different injection points, while
> NumberService has only a single injection point (NumberFinder). Most of them
> actually relates to *other* EJBs in the application. If we skip and go to the
> next EJB JNDI registration, the exact same complete list of ejbLocalRef is
> provided.
> h4. collapsedear-bug-ear.ear
> At the opposite, when debugging the startup of the equivalent EAR file
> Here are the debugging info extracted:
> {code}
> moduleId = collapsedear-bug-ejb
> jndiConsumer.ejbClass = "org.lastnico.collapsedear.bug.ejb.NumberService"
> jndiConsumer.ejbLocalRef =
> {java:comp/env/org.lastnico.collapsedear.bug.ejb.NumberService/userFinder=EjbLocalRef{name='java:comp/env/org.lastnico.collapsedear.bug.ejb.NumberService/userFinder',
> local=org.lastnico.collapsedear.bug.ejb.NumberFinder, link='null',
> mappedName='null', lookupName='null'}}
> {code}
> This time, as expected, the NumberService EJB only has 1 single EJB local
> ref, matching its single injection point.
> h4. Suspicion
> I suspect the reason for this is that MergeWebappJndiContext indistinctely
> copies all possible EJB local refs, and hence each EJB receives the whole
> list of injection points (from all registered EJBs in the application).
> In the scenario of our application described earlier, we end up with (1992 +
> 1193) * 8569 declared EJB local refs, which slows down the whole startup and
> wastes huge quantity of memory.
> You can find in attachments both the WAR and EAR file, as well as the log
> output of both deployable artifacts, and the source code of the respective
> Maven project. Please note this was tested against TomEE 8.0.16 because this
> is our current target, but I assume this issue could also be reproduced on
> TomEE 9.1.2.
> Thanks!
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
