paketo-buildpacks / libjvm

A library and helper applications that form the basis for building the different Paketo-style JVM-providing buildpacks
Apache License 2.0
19 stars 20 forks source link

Spring Boot app failed to start because of OOM (Metaspace OOM) #208

Open zhoufenqin opened 2 years ago

zhoufenqin commented 2 years ago

I create a spring boot app with Dynamic buildpack, the app failed to start with Terminating due to java.lang.OutOfMemoryError: Metaspace error. The OOM app sample respo: https://github.com/zhoufenqin/java-sample/tree/main/echo-app-oom

The buildpack i'm using: tanzu-java-azure:7.28.0 libjvm v1.37.0

The errorlog show:

Setting Active Processor Count to 16
Adding $JAVA_OPTS to $JAVA_TOOL_OPTIONS
Calculated JVM Memory Configuration: -XX:MaxDirectMemorySize=10M -Xmx437195K -XX:MaxMetaspaceSize=99380K -XX:ReservedCodeCacheSize=240M -Xss1M (Total Memory: 1G, Thread Count: 250, Loaded Class Count: 15132, Headroom: 0%)
Enabling Java Native Memory Tracking
Adding 127 container CA certificates to JVM truststore
Spring Cloud Bindings Enabled
Configuring AppDynamics properties
Picked up JAVA_TOOL_OPTIONS: -Djava.security.properties=/layers/paketo-buildpacks_microsoft-openjdk/java-security-properties/java-security.properties -XX:+ExitOnOutOfMemoryError -javaagent:/layers/tanzu-buildpacks_appdynamics/appdynamics-java/javaagent.jar -XX:ActiveProcessorCount=16 -XX:InitialRAMPercentage=60.0 -XX:MaxRAMPercentage=60.0 -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=1099 -Dcom.sun.management.jmxremote.local.only=true -Dcom.sun.management.jmxremote.authenticate=false
-Dcom.sun.management.jmxremote.ssl=false -Dspring.jmx.enabled=true -Dserver.tomcat.mbeanregistry.enabled=true -Dfile.encoding=UTF8 -Dspring.config.import=optional:configserver:/ -XX:MaxDirectMemorySize=10M -Xmx437195K -XX:MaxMetaspaceSize=99380K -XX:ReservedCodeCacheSize=240M -Xss1M -XX:+UnlockDiagnosticVMOptions -XX:NativeMemoryTracking=summary -XX:+PrintNMTStatistics -Dorg.springframework.cloud.bindings.boot.enable=true
......
......
2022-09-05 15:01:26.209  INFO 1 --- [           main] o.s.b.w.e.t.TomcatWebServer              : Tomca
t started on port(s): 8080 (http) with context path ''
2022-09-05 15:01:26.213  INFO 1 --- [           main] c.a.s.c.t.c.c.MasonApplication           : Start
ed MasonApplication in 19.602 seconds (JVM running for 36.459)
Terminating due to java.lang.OutOfMemoryError: Metaspace

Then I add some other dependency in pom.xml, like

<dependency>
      <groupId>org.springframework.cloud</groupId>
      <artifactId>spring-cloud-starter-netflix-eureka-client</artifactId>
    </dependency>

The app can be started, the metaspace is larger than before The correct app repo: https://github.com/zhoufenqin/java-sample/tree/main/echo-app

The log shows:

Setting Active Processor Count to 4
Adding $JAVA_OPTS to $JAVA_TOOL_OPTIONS
Calculated JVM Memory Configuration: -XX:MaxDirectMemorySize=10M -Xmx400820K -XX:MaxMetaspaceSize=1357
55K -XX:ReservedCodeCacheSize=240M -Xss1M (Total Memory: 1G, Thread Count: 250, Loaded Class Count: 21
554, Headroom: 0%)
Enabling Java Native Memory Tracking
Adding 127 container CA certificates to JVM truststore
Spring Cloud Bindings Enabled
Configuring AppDynamics properties
Picked up JAVA_TOOL_OPTIONS: -Djava.security.properties=/layers/paketo-buildpacks_microsoft-openjdk/ja
va-security-properties/java-security.properties -XX:+ExitOnOutOfMemoryError -javaagent:/layers/tanzu-b
uildpacks_appdynamics/appdynamics-java/javaagent.jar -XX:ActiveProcessorCount=4 -XX:InitialRAMPercenta
ge=60.0 -XX:MaxRAMPercentage=60.0 -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=1
099 -Dcom.sun.management.jmxremote.local.only=true -Dcom.sun.management.jmxremote.authenticate=false -
Dcom.sun.management.jmxremote.ssl=false -Dspring.jmx.enabled=true -Dserver.tomcat.mbeanregistry.enable
d=true -Dfile.encoding=UTF8 -Dspring.config.import=optional:configserver:/ -XX:MaxDirectMemorySize=10M
 -Xmx400820K -XX:MaxMetaspaceSize=135755K -XX:ReservedCodeCacheSize=240M -Xss1M -XX:+UnlockDiagnosticV
MOptions -XX:NativeMemoryTracking=summary -XX:+PrintNMTStatistics -Dorg.springframework.cloud.bindings
.boot.enable=true
......

These two app are only different in pom.xml, the correct one have eureka dependency but the oom one hasn't

How the Metaspace size calculate?

Expected Behavior

The calculate Metaspace size should large enough

Current Behavior

The app failed to start because of OOM metaspace

Possible Solution

Steps to Reproduce

1.

Motivations

pivotal-david-osullivan commented 2 years ago

Although I produced the same Memory Calculator values on startup using your sample app, I did not hit the OOM error:

Setting Active Processor Count to 4
Memory Calculation: (100% * (30531 + 12562 + 144 + 0)) * 0.35
Calculated JVM Memory Configuration: -XX:MaxDirectMemorySize=10M -Xmx437195K -XX:MaxMetaspaceSize=99380K -XX:ReservedCodeCacheSize=240M -Xss1M (Total Memory: 1G, Thread Count: 250, Loaded Class Count: 15132, Headroom: 0%)
Enabling Java Native Memory Tracking
Adding 127 container CA certificates to JVM truststore
Spring Cloud Bindings Enabled
Configuring AppDynamics properties
Picked up JAVA_TOOL_OPTIONS: -Djava.security.properties=/layers/paketo-buildpacks_microsoft-openjdk/java-security-properties/java-security.properties -XX:+ExitOnOutOfMemoryError -javaagent:/layers/tanzu-buildpacks_appdynamics/appdynamics-java/javaagent.jar -XX:ActiveProcessorCount=4 -XX:MaxDirectMemorySize=10M -Xmx437195K -XX:MaxMetaspaceSize=99380K -XX:ReservedCodeCacheSize=240M -Xss1M -XX:+UnlockDiagnosticVMOptions -XX:NativeMemoryTracking=summary -XX:+PrintNMTStatistics -Dorg.springframework.cloud.bindings.boot.enable=true
...
2022-09-08 08:08:10.471  INFO 1c852f0cfb1b --- [kground-preinit] o.h.v.i.u.Version                        : HV000001: Hibernate Validator 6.0.22.Final
2022-09-08 08:08:10.813  INFO 1c852f0cfb1b --- [           main] c.a.s.c.t.c.c.MasonApplication           : Starting MasonApplication on 1c852f0cfb1b with PID 1 (/workspace/BOOT-INF/classes started by cnb in /workspace)
2022-09-08 08:08:10.831  INFO 1c852f0cfb1b --- [           main] c.a.s.c.t.c.c.MasonApplication           : No active profile set, falling back to default profiles: default
2022-09-08 08:08:15.255  INFO 1c852f0cfb1b --- [           main] o.s.b.w.e.t.TomcatWebServer              : Tomcat initialized with port(s): 8080 (http)
2022-09-08 08:08:15.351  INFO 1c852f0cfb1b --- [           main] o.a.c.h.Http11NioProtocol                : Initializing ProtocolHandler ["http-nio-8080"]
2022-09-08 08:08:15.354  INFO 1c852f0cfb1b --- [           main] o.a.c.c.StandardService                  : Starting service [Tomcat]
2022-09-08 08:08:15.357  INFO 1c852f0cfb1b --- [           main] o.a.c.c.StandardEngine                   : Starting Servlet engine: [Apache Tomcat/9.0.41]
2022-09-08 08:08:15.532  INFO 1c852f0cfb1b --- [           main] o.a.c.c.C.[.[.[/]                        : Initializing Spring embedded WebApplicationContext
2022-09-08 08:08:15.532  INFO 1c852f0cfb1b --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 4499 ms
2022-09-08 08:08:16.434  INFO 1c852f0cfb1b --- [           main] o.s.s.c.ThreadPoolTaskExecutor           : Initializing ExecutorService 'applicationTaskExecutor'
2022-09-08 08:08:17.013  INFO 1c852f0cfb1b --- [           main] o.s.b.a.e.w.EndpointLinksResolver        : Exposing 2 endpoint(s) beneath base path '/actuator'
2022-09-08 08:08:17.091  INFO 1c852f0cfb1b --- [           main] o.a.c.h.Http11NioProtocol                : Starting ProtocolHandler ["http-nio-8080"]
2022-09-08 08:08:17.171  INFO 1c852f0cfb1b --- [           main] o.s.b.w.e.t.TomcatWebServer              : Tomcat started on port(s): 8080 (http) with context path ''
2022-

The Metaspace size is automatically calculated using a formula, by counting the number of classes loaded, i.e. the number of class files in the jar, multiplied by a fixed class size value + a fixed class overhead value. This calculation usually works well for Spring Boot apps. We recently added support for counting classes specified within javaagent: property jars to ensure a more accurate calculation, so in this case we know the AppD agent classes are included.

Unless there is another difference here, it is possible that the calculated value for Metaspace is just below the amount required. Adding the Eureka jar will increase the class count and therefore increase the calculated Metaspace size (by around 30M here) which seems to be just enough to start successfully.

One thing you can try is adjusting the class count - a runtime variable exists to set a class count adjustment factor. BPL_JVM_CLASS_ADJUSTMENT. Try setting this to a percentage value, e.g. 120% which will result in a higher Metaspace size and see if the app starts successfully.

zhoufenqin commented 2 years ago

@pivotal-david-osullivan I keep my JAVA_OPTS as same as you, but it still OOM, the only difference is -XX:ActiveProcessorCount, it's calculated by this buildpack. Does it affect memory?

Double confirm with you: Did the app keep running successfully after starting for several minutes? Because my app will start to run first then a few seconds later, the OOM occur.

The error logs:

Setting Active Processor Count to 16
Calculated JVM Memory Configuration: -XX:MaxDirectMemorySize=10M -Xmx437195K -XX:MaxMetaspaceSize=99380K -XX:ReservedCodeCacheSize=240M -Xss1M (Total Memory: 1G, Thread Count: 250, Loaded Class Count: 15132, Headroom: 0%)
Enabling Java Native Memory Tracking
Adding 127 container CA certificates to JVM truststore
Spring Cloud Bindings Enabled
Configuring AppDynamics properties
Picked up JAVA_TOOL_OPTIONS: -Djava.security.properties=/layers/paketo-buildpacks_microsoft-openjdk/java-security-properties/java-security.properties -XX:+ExitOnOutOfMemoryError -javaagent:/layers/tanzu-buildpacks_appdynamics/appdynamics-java/javaagent.jar -XX:ActiveProcessorCount=16 -XX:MaxDirectMemorySize=10M -Xmx437195K -XX:MaxMetaspaceSize=99380K -XX:ReservedCodeCacheSize=240M -Xss1M -XX:+UnlockDiagnosticVMOptions -XX:NativeMemoryTracking=summary -XX:+PrintNMTStatistics -Dorg.springframework.cloud.bindings.boot.enable=true
Java 9+ detected, booting with Java9Util enabled.
Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_APPLICATION_NAME] for application name [after-app2]
Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_TIER_NAME] for tier name [enterprise]
Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_NODE_NAME] for node name [node-0]
Full Agent Registration Info Resolver using selfService [false]
Full Agent Registration Info Resolver using selfService [false]
Full Agent Registration Info Resolver using ephemeral node setting [false]
Full Agent Registration Info Resolver using application name [after-app2]
Full Agent Registration Info Resolver using tier name [enterprise]
Full Agent Registration Info Resolver using node name [node-0]
Install Directory resolved to[/layers/tanzu-buildpacks_appdynamics/appdynamics-java]
getBootstrapResource not available on ClassLoader
Class with name [com.ibm.lang.management.internal.ExtendedOperatingSystemMXBeanImpl] is not available in classpath, so will ignore export access.
[AD Agent init] Fri Sep 09 07:21:08 UTC 2022[DEBUG]: JavaAgent - Setting AgentClassLoader as Context ClassLoader
[AD Agent init] Fri Sep 09 07:21:09 UTC 2022[DEBUG]: JavaAgent - Setting AgentClassLoader as Context ClassLoader
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: JavaAgent - Low Entropy Mode: Attempting to swap to non-blocking PRNG algorithm
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: JavaAgent - UUIDPool size is 10
Agent conf directory set to [/layers/tanzu-buildpacks_appdynamics/appdynamics-java/ver22.5.0.33845/conf]
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: JavaAgent - Agent conf directory set to [/layers/tanzu-buildpacks_appdynamics/appdynamics-java/ver22.5.0.33845/conf]
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[DEBUG]: AgentInstallManager - Full Agent Registration Info Resolver is running
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_APPLICATION_NAME] for application name [after-app2]
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_TIER_NAME] for tier name [enterprise]
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_NODE_NAME] for node name [node-0]
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using selfService [false]
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using selfService [false]
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using ephemeral node setting [false]
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using application name [after-app2]
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using tier name [enterprise]
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using node name [node-0]
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[DEBUG]: AgentInstallManager - Full Agent Registration Info Resolver finished running
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: AgentInstallManager - Agent runtime directory set to [/layers/tanzu-buildpacks_appdynamics/appdynamics-java/ver22.5.0.33845]
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: AgentInstallManager - Agent node directory set to [node-0]
Agent runtime conf directory set to /layers/tanzu-buildpacks_appdynamics/appdynamics-java/ver22.5.0.33845/conf
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: AgentInstallManager - Agent runtime conf directory set to /layers/tanzu-buildpacks_appdynamics/appdynamics-java/ver22.5.0.33845/conf
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: JavaAgent - JDK Compatibility: 1.8+
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: JavaAgent - Using Java Agent Version [Server Agent #22.5.0.33845 v22.5.0 GA compatible with 4.4.1.0 rd9770530415f19f4c5154a80772b833db8dd7cee release/22.5.0]
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: JavaAgent - Running IBM Java Agent [No]
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: JavaAgent - Java Agent Directory [/layers/tanzu-buildpacks_appdynamics/appdynamics-java/ver22.5.0.33845]
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: JavaAgent - Java Agent AppAgent directory [/layers/tanzu-buildpacks_appdynamics/appdynamics-java/ver22.5.0.33845]
Agent logging directory set to [/layers/tanzu-buildpacks_appdynamics/appdynamics-java/ver22.5.0.33845/logs]
[AD Agent init] Fri Sep 09 07:21:10 UTC 2022[INFO]: JavaAgent - Agent logging directory set to [/layers/tanzu-buildpacks_appdynamics/appdynamics-java/ver22.5.0.33845/logs]
getBootstrapResource not available on ClassLoader
Registered app server agent with Node ID[7205109] Component ID[3529688] Application ID [1663605]
Started AppDynamics Java Agent Successfully.

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::       (v2.2.13.RELEASE)

2022-09-09 07:21:29.304  INFO 1 --- [           main] c.a.s.c.t.c.c.MasonApplication           : Starting MasonApplication on after-app3-default-10-75b79f58d8-dmwd6 with PID 1 (/workspace/BOOT-INF/classes started by cnb in /workspace)
2022-09-09 07:21:29.409  INFO 1 --- [           main] c.a.s.c.t.c.c.MasonApplication           : No active profile set, falling back to default profiles: default
2022-09-09 07:21:39.604  INFO 1 --- [           main] o.s.b.w.e.t.TomcatWebServer              : Tomcat initialized with port(s): 8080 (http)
2022-09-09 07:21:39.817  INFO 1 --- [           main] o.a.c.c.StandardService                  : Starting service [Tomcat]
2022-09-09 07:21:39.818  INFO 1 --- [           main] o.a.c.c.StandardEngine                   : Starting Servlet engine: [Apache Tomcat/9.0.41]
2022-09-09 07:21:40.113  INFO 1 --- [           main] o.a.c.c.C.[.[.[/]                        : Initializing Spring embedded WebApplicationContext
2022-09-09 07:21:40.114  INFO 1 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 10205 ms
2022-09-09 07:21:42.517  INFO 1 --- [           main] o.s.s.c.ThreadPoolTaskExecutor           : Initializing ExecutorService 'applicationTaskExecutor'
2022-09-09 07:21:44.413  INFO 1 --- [           main] o.s.b.a.e.w.EndpointLinksResolver        : Exposing 2 endpoint(s) beneath base path '/actuator'
2022-09-09 07:21:44.812  INFO 1 --- [           main] o.s.b.w.e.t.TomcatWebServer              : Tomcat started on port(s): 8080 (http) with context path ''
2022-09-09 07:21:44.816  INFO 1 --- [           main] c.a.s.c.t.c.c.MasonApplication           : Started MasonApplication in 19.512 seconds (JVM running for 37.834)
Terminating due to java.lang.OutOfMemoryError: Metaspace
pivotal-david-osullivan commented 2 years ago

The ActiveProcessorCount is the value returned by a library call to retrieve the number of logical CPUs usable by the current process. See more detail here. I notice your working app log has this value set to '4'.

Following your comment I left the app running for several hours but it never hits an OOM. The application seems to start much more quickly for me: Started MasonApplication in 9.61 seconds (JVM running for 21.608) compared to Started MasonApplication in 19.512 seconds (JVM running for 37.834)

Have you tried setting the variable to allow for an increase in Metaspace?

zhoufenqin commented 1 year ago

Although I produced the same Memory Calculator values on startup using your sample app, I did not hit the OOM error:

Setting Active Processor Count to 4
Memory Calculation: (100% * (30531 + 12562 + 144 + 0)) * 0.35
Calculated JVM Memory Configuration: -XX:MaxDirectMemorySize=10M -Xmx437195K -XX:MaxMetaspaceSize=99380K -XX:ReservedCodeCacheSize=240M -Xss1M (Total Memory: 1G, Thread Count: 250, Loaded Class Count: 15132, Headroom: 0%)
Enabling Java Native Memory Tracking
Adding 127 container CA certificates to JVM truststore
Spring Cloud Bindings Enabled
Configuring AppDynamics properties
Picked up JAVA_TOOL_OPTIONS: -Djava.security.properties=/layers/paketo-buildpacks_microsoft-openjdk/java-security-properties/java-security.properties -XX:+ExitOnOutOfMemoryError -javaagent:/layers/tanzu-buildpacks_appdynamics/appdynamics-java/javaagent.jar -XX:ActiveProcessorCount=4 -XX:MaxDirectMemorySize=10M -Xmx437195K -XX:MaxMetaspaceSize=99380K -XX:ReservedCodeCacheSize=240M -Xss1M -XX:+UnlockDiagnosticVMOptions -XX:NativeMemoryTracking=summary -XX:+PrintNMTStatistics -Dorg.springframework.cloud.bindings.boot.enable=true
...
2022-09-08 08:08:10.471  INFO 1c852f0cfb1b --- [kground-preinit] o.h.v.i.u.Version                        : HV000001: Hibernate Validator 6.0.22.Final
2022-09-08 08:08:10.813  INFO 1c852f0cfb1b --- [           main] c.a.s.c.t.c.c.MasonApplication           : Starting MasonApplication on 1c852f0cfb1b with PID 1 (/workspace/BOOT-INF/classes started by cnb in /workspace)
2022-09-08 08:08:10.831  INFO 1c852f0cfb1b --- [           main] c.a.s.c.t.c.c.MasonApplication           : No active profile set, falling back to default profiles: default
2022-09-08 08:08:15.255  INFO 1c852f0cfb1b --- [           main] o.s.b.w.e.t.TomcatWebServer              : Tomcat initialized with port(s): 8080 (http)
2022-09-08 08:08:15.351  INFO 1c852f0cfb1b --- [           main] o.a.c.h.Http11NioProtocol                : Initializing ProtocolHandler ["http-nio-8080"]
2022-09-08 08:08:15.354  INFO 1c852f0cfb1b --- [           main] o.a.c.c.StandardService                  : Starting service [Tomcat]
2022-09-08 08:08:15.357  INFO 1c852f0cfb1b --- [           main] o.a.c.c.StandardEngine                   : Starting Servlet engine: [Apache Tomcat/9.0.41]
2022-09-08 08:08:15.532  INFO 1c852f0cfb1b --- [           main] o.a.c.c.C.[.[.[/]                        : Initializing Spring embedded WebApplicationContext
2022-09-08 08:08:15.532  INFO 1c852f0cfb1b --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 4499 ms
2022-09-08 08:08:16.434  INFO 1c852f0cfb1b --- [           main] o.s.s.c.ThreadPoolTaskExecutor           : Initializing ExecutorService 'applicationTaskExecutor'
2022-09-08 08:08:17.013  INFO 1c852f0cfb1b --- [           main] o.s.b.a.e.w.EndpointLinksResolver        : Exposing 2 endpoint(s) beneath base path '/actuator'
2022-09-08 08:08:17.091  INFO 1c852f0cfb1b --- [           main] o.a.c.h.Http11NioProtocol                : Starting ProtocolHandler ["http-nio-8080"]
2022-09-08 08:08:17.171  INFO 1c852f0cfb1b --- [           main] o.s.b.w.e.t.TomcatWebServer              : Tomcat started on port(s): 8080 (http) with context path ''
2022-

The Metaspace size is automatically calculated using a formula, by counting the number of classes loaded, i.e. the number of class files in the jar, multiplied by a fixed class size value + a fixed class overhead value. This calculation usually works well for Spring Boot apps. We recently added support for counting classes specified within javaagent: property jars to ensure a more accurate calculation, so in this case we know the AppD agent classes are included.

Unless there is another difference here, it is possible that the calculated value for Metaspace is just below the amount required. Adding the Eureka jar will increase the class count and therefore increase the calculated Metaspace size (by around 30M here) which seems to be just enough to start successfully.

One thing you can try is adjusting the class count - a runtime variable exists to set a class count adjustment factor. BPL_JVM_CLASS_ADJUSTMENT. Try setting this to a percentage value, e.g. 120% which will result in a higher Metaspace size and see if the app starts successfully.

//=====================================================

Hi @pivotal-david-osullivan Sorry for not following this question for a long time, Now we have upgraded the java-azure buildpack version to 8.8.0 and the kpack version to 0.7.2. the issue still exists

I'm not sure how you deploy an app with dynamic, from the previous logs, it seems that the app doesn't run with AppDynamics APM(I didn't see the logs about AppDynamics) , I use pack CLI to build the app with AppDynamic and then run it locally, the metaspace OOM happened. see

> pack build dynamic --path ./echo-app-oom --volume "/mnt/d/code/github/java-sample/buildbindings/:/platform/bindings/dynamic" --builder my-builder
Warning: Using untrusted builder with volume mounts. If there is sensitive data in the volumes, this may present a security vulnerability.base-cnb-df: Pulling from azurespringapps/paketobuildpacks/run
a404e5416296: Already exists
795b19220565: Already exists
0ce12e95ee49: Pull complete
4b8c913f2038: Pull complete
fec36b8c9d3a: Pull complete
c4db82fa0ee1: Pull complete
bee0d0e29bb4: Pull complete
Digest: sha256:ae2131f66028972d190eac22a0baa1b21628db00074d4230f2600b9a43dba25d
Status: Downloaded newer image for mcr.microsoft.com/azurespringapps/paketobuildpacks/run:base-cnb-df
0.14.3: Pulling from buildpacksio/lifecycle
Digest: sha256:8f06973b07430f09e6076cf2e34b52cf4b0b4a48201d0c9457985f1726d31014
Status: Image is up to date for buildpacksio/lifecycle:0.14.3
===> ANALYZING
[analyzer] Restoring data for SBOM from previous image
===> DETECTING
[detector] 11 of 41 buildpacks participating
[detector] paketo-buildpacks/ca-certificates   3.4.0
[detector] paketo-buildpacks/microsoft-openjdk 2.6.0
[detector] paketo-buildpacks/syft              1.10.1
[detector] paketo-buildpacks/maven             6.11.0
[detector] paketo-buildpacks/executable-jar    6.5.0
[detector] paketo-buildpacks/apache-tomcat     7.8.0
[detector] paketo-buildpacks/apache-tomee      1.3.0
[detector] paketo-buildpacks/liberty           2.2.0
[detector] paketo-buildpacks/dist-zip          5.4.0
[detector] paketo-buildpacks/spring-boot       5.19.0
[detector] paketo-buildpacks/appdynamics       5.1.0
===> RESTORING
[restorer] Restoring metadata for "paketo-buildpacks/ca-certificates:helper" from app image
[restorer] Restoring metadata for "paketo-buildpacks/syft:syft" from cache
[restorer] Restoring metadata for "paketo-buildpacks/maven:application" from cache
[restorer] Restoring metadata for "paketo-buildpacks/maven:cache" from cache
[restorer] Restoring metadata for "paketo-buildpacks/maven:maven" from cache
[restorer] Restoring metadata for "paketo-buildpacks/spring-boot:spring-cloud-bindings" from app image
[restorer] Restoring metadata for "paketo-buildpacks/spring-boot:web-application-type" from app image
[restorer] Restoring metadata for "paketo-buildpacks/spring-boot:helper" from app image
[restorer] Restoring data for "paketo-buildpacks/syft:syft" from cache
[restorer] Restoring data for "paketo-buildpacks/maven:application" from cache
[restorer] Restoring data for "paketo-buildpacks/maven:cache" from cache
[restorer] Restoring data for "paketo-buildpacks/maven:maven" from cache
[restorer] Restoring data for SBOM from cache
===> BUILDING
[builder]
[builder] Paketo Buildpack for CA Certificates 3.4.0
[builder]   https://github.com/paketo-buildpacks/ca-certificates
[builder]   Launch Helper: Contributing to layer
[builder]     Creating /layers/paketo-buildpacks_ca-certificates/helper/exec.d/ca-certificates-helper
[builder]
[builder] Paketo Buildpack for Microsoft OpenJDK 2.6.0
[builder]   https://github.com/paketo-buildpacks/microsoft-openjdk
[builder]   Build Configuration:
[builder]     $BP_JVM_JLINK_ARGS           --no-man-pages --no-header-files --strip-debug --compress=1  configure custom link arguments (--output must be omitted)
[builder]     $BP_JVM_JLINK_ENABLED        false                                                        enables running jlink tool to generate custom JRE
[builder]     $BP_JVM_TYPE                 JRE                                                          the JVM type - JDK or JRE
[builder]     $BP_JVM_VERSION              11                                                           the Java version
[builder]   Launch Configuration:
[builder]     $BPL_DEBUG_ENABLED           false                                                        enables Java remote debugging support
[builder]     $BPL_DEBUG_PORT              8000                                                         configure the remote debugging port
[builder]     $BPL_DEBUG_SUSPEND           false                                                        configure whether to suspend execution until a debugger has attached
[builder]     $BPL_HEAP_DUMP_PATH                                                                       write heap dumps on error to this path
[builder]     $BPL_JAVA_NMT_ENABLED        true                                                         enables Java Native Memory Tracking (NMT)
[builder]     $BPL_JAVA_NMT_LEVEL          summary                                                      configure level of NMT, summary or detail
[builder]     $BPL_JFR_ARGS                                                                             configure custom Java Flight Recording (JFR) arguments
[builder]     $BPL_JFR_ENABLED             false                                                        enables Java Flight Recording (JFR)
[builder]     $BPL_JMX_ENABLED             false                                                        enables Java Management Extensions (JMX)
[builder]     $BPL_JMX_PORT                5000                                                         configure the JMX port
[builder]     $BPL_JVM_HEAD_ROOM           0                                                            the headroom in memory calculation[builder]     $BPL_JVM_LOADED_CLASS_COUNT  35% of classes                                               the number of loaded classes in memory calculation
[builder]     $BPL_JVM_THREAD_COUNT        250                                                          the number of threads in memory calculation
[builder]     $JAVA_TOOL_OPTIONS                                                                        the JVM launch flags
[builder]     Using buildpack default Java version 11
[builder]   No valid JRE available, providing matching JDK instead. Using a JDK at runtime has security implications.
[builder]   Microsoft OpenJDK 11.0.16: Contributing to layer
[builder]     Reusing cached download from buildpack
[builder]     Expanding to /layers/paketo-buildpacks_microsoft-openjdk/jdk
[builder]     Adding 127 container CA certificates to JVM truststore
[builder]     Writing env.build/JAVA_HOME.default
[builder]     Writing env.launch/BPI_APPLICATION_PATH.default
[builder]     Writing env.launch/BPI_JVM_CACERTS.default
[builder]     Writing env.launch/BPI_JVM_CLASS_COUNT.default
[builder]     Writing env.launch/BPI_JVM_SECURITY_PROVIDERS.default
[builder]     Writing env.launch/JAVA_HOME.default
[builder]     Writing env.launch/JAVA_TOOL_OPTIONS.append
[builder]     Writing env.launch/JAVA_TOOL_OPTIONS.delim
[builder]     Writing env.launch/MALLOC_ARENA_MAX.default
[builder]   Launch Helper: Contributing to layer
[builder]     Creating /layers/paketo-buildpacks_microsoft-openjdk/helper/exec.d/active-processor-count
[builder]     Creating /layers/paketo-buildpacks_microsoft-openjdk/helper/exec.d/java-opts
[builder]     Creating /layers/paketo-buildpacks_microsoft-openjdk/helper/exec.d/jvm-heap
[builder]     Creating /layers/paketo-buildpacks_microsoft-openjdk/helper/exec.d/link-local-dns
[builder]     Creating /layers/paketo-buildpacks_microsoft-openjdk/helper/exec.d/memory-calculator
[builder]     Creating /layers/paketo-buildpacks_microsoft-openjdk/helper/exec.d/security-providers-configurer
[builder]     Creating /layers/paketo-buildpacks_microsoft-openjdk/helper/exec.d/jmx
[builder]     Creating /layers/paketo-buildpacks_microsoft-openjdk/helper/exec.d/jfr
[builder]     Creating /layers/paketo-buildpacks_microsoft-openjdk/helper/exec.d/security-providers-classpath-9
[builder]     Creating /layers/paketo-buildpacks_microsoft-openjdk/helper/exec.d/debug-9
[builder]     Creating /layers/paketo-buildpacks_microsoft-openjdk/helper/exec.d/nmt
[builder]     Creating /layers/paketo-buildpacks_microsoft-openjdk/helper/exec.d/openssl-certificate-loader
[builder]   Java Security Properties: Contributing to layer
[builder]     Writing env.launch/JAVA_SECURITY_PROPERTIES.default
[builder]     Writing env.launch/JAVA_TOOL_OPTIONS.append
[builder]     Writing env.launch/JAVA_TOOL_OPTIONS.delim
[builder]
[builder] Paketo Syft Buildpack 1.10.1
[builder]   https://github.com/paketo-buildpacks/syft
[builder]     Reusing cached download from buildpack
[builder]     Writing env.build/SYFT_CHECK_FOR_APP_UPDATE.default
[builder]
[builder] Paketo Buildpack for Maven 6.11.0
[builder]   https://github.com/paketo-buildpacks/maven
[builder]   Build Configuration:
[builder]     $BP_EXCLUDE_FILES                                                                 colon separated list of glob patterns, matched source files are removed
[builder]     $BP_INCLUDE_FILES                                                                 colon separated list of glob patterns, matched source files are included
[builder]     $BP_MAVEN_BUILD_ARGUMENTS  -Dmaven.test.skip=true --no-transfer-progress package  the arguments to pass to Maven
[builder]     $BP_MAVEN_BUILT_ARTIFACT   target/*.[ejw]ar                                       the built application artifact explicitly.  Supersedes $BP_MAVEN_BUILT_MODULE
[builder]     $BP_MAVEN_BUILT_MODULE                                                            the module to find application artifact in[builder]     $BP_MAVEN_DAEMON_ENABLED   false                                                  use maven daemon
[builder]     $BP_MAVEN_POM_FILE         pom.xml                                                the location of the main pom.xml file, relative to the application root
[builder]     $BP_MAVEN_SETTINGS_PATH                                                           the path to a Maven settings file
[builder]     Creating cache directory /home/cnb/.m2
[builder]   Compiled Application: Contributing to layer
[builder]     Executing mvn --batch-mode -Dmaven.test.skip=true --no-transfer-progress package
[builder]       [INFO] Scanning for projects...
[builder]       [INFO]
[builder]       [INFO] -----< com.azure.spring.cloud.test-apps:echo-app-mason-with-log4j >-----
[builder]       [INFO] Building echo-app-mason-with-log4j 0.0.1-SNAPSHOT
[builder]       [INFO] --------------------------------[ jar ]---------------------------------
[builder]       [INFO]
[builder]       [INFO] --- maven-resources-plugin:3.1.0:resources (default-resources) @ echo-app-mason-with-log4j ---
[builder]       [INFO] Using 'UTF-8' encoding to copy filtered resources.
[builder]       [INFO] Copying 0 resource
[builder]       [INFO] Copying 1 resource
[builder]       [INFO]
[builder]       [INFO] --- maven-compiler-plugin:3.8.1:compile (default-compile) @ echo-app-mason-with-log4j ---
[builder]       [INFO] Changes detected - recompiling the module!
[builder]       [INFO] Compiling 2 source files to /workspace/target/classes
[builder]       [INFO]
[builder]       [INFO] --- maven-resources-plugin:3.1.0:testResources (default-testResources) @ echo-app-mason-with-log4j ---
[builder]       [INFO] Not copying test resources
[builder]       [INFO]
[builder]       [INFO] --- maven-compiler-plugin:3.8.1:testCompile (default-testCompile) @ echo-app-mason-with-log4j ---
[builder]       [INFO] Not compiling test sources
[builder]       [INFO]
[builder]       [INFO] --- maven-surefire-plugin:2.22.2:test (default-test) @ echo-app-mason-with-log4j ---
[builder]       [INFO] Tests are skipped.
[builder]       [INFO]
[builder]       [INFO] --- maven-jar-plugin:3.1.2:jar (default-jar) @ echo-app-mason-with-log4j ---
[builder]       [INFO] Building jar: /workspace/target/echo-app-mason-with-log4j-0.0.1-SNAPSHOT.jar
[builder]       [INFO]
[builder]       [INFO] --- spring-boot-maven-plugin:2.2.13.RELEASE:repackage (repackage) @ echo-app-mason-with-log4j ---
[builder]       [INFO] Replacing main artifact with repackaged archive
[builder]       [INFO] ------------------------------------------------------------------------
[builder]       [INFO] BUILD SUCCESS
[builder]       [INFO] ------------------------------------------------------------------------
[builder]       [INFO] Total time:  6.781 s
[builder]       [INFO] Finished at: 2022-11-29T07:42:15Z
[builder]       [INFO] ------------------------------------------------------------------------
[builder]
[builder]   Removing source code
[builder]   Restoring application artifact
[builder]
[builder] Paketo Buildpack for Executable JAR 6.5.0
[builder]   https://github.com/paketo-buildpacks/executable-jar
[builder]   Class Path: Contributing to layer
[builder]     Writing env/CLASSPATH.delim
[builder]     Writing env/CLASSPATH.prepend
[builder]   Process types:
[builder]     executable-jar: java org.springframework.boot.loader.JarLauncher (direct)
[builder]     task:           java org.springframework.boot.loader.JarLauncher (direct)
[builder]     web:            java org.springframework.boot.loader.JarLauncher (direct)
[builder]
[builder] Paketo Buildpack for Spring Boot 5.19.0
[builder]   https://github.com/paketo-buildpacks/spring-boot
[builder]   Build Configuration:
[builder]     $BP_SPRING_CLOUD_BINDINGS_DISABLED   false  whether to contribute Spring Boot cloud bindings support
[builder]   Launch Configuration:
[builder]     $BPL_SPRING_CLOUD_BINDINGS_DISABLED  false  whether to auto-configure Spring Boot environment properties from bindings
[builder]     $BPL_SPRING_CLOUD_BINDINGS_ENABLED   true   Deprecated - whether to auto-configure Spring Boot environment properties from bindings
[builder]   Launch Helper: Contributing to layer
[builder]     Creating /layers/paketo-buildpacks_spring-boot/helper/exec.d/spring-cloud-bindings
[builder]   Spring Cloud Bindings 1.10.0: Reusing cached layer
[builder]   Web Application Type: Reusing cached layer
[builder]   Image labels:
[builder]     org.opencontainers.image.title
[builder]     org.opencontainers.image.version
[builder]     org.springframework.boot.version
[builder]
[builder] Paketo Buildpack for AppDynamics 5.1.0
[builder]   https://github.com/paketo-buildpacks/appdynamics
[builder]   Build Configuration:
[builder]     $BP_APPD_EXT_CONF_SHA256                the SHA256 hash of the external AppDynamics configuration archive
[builder]     $BP_APPD_EXT_CONF_STRIP              0  the number of directory components to strip from the external AppDynamics configuration archive
[builder]     $BP_APPD_EXT_CONF_URI                   the download location of the external AppDynamics configuration
[builder]     $BP_APPD_EXT_CONF_VERSION               the version of the external AppDynamics configuration
[builder]   Launch Configuration:
[builder]     $APPDYNAMICS_AGENT_APPLICATION_NAME     the AppDynamics application name
[builder]     $APPDYNAMICS_AGENT_NODE_NAME            the AppDynamics node name
[builder]     $APPDYNAMICS_AGENT_TIER_NAME            the AppDynamics tier name
[builder]   AppDynamics Java Agent 22.8.0: Contributing to layer
[builder]     Reusing cached download from buildpack
[builder]     Expanding to /layers/paketo-buildpacks_appdynamics/appdynamics-java
[builder]     Copying app-agent-config.xml to /layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.8.0.34104/conf
[builder]     Copying custom-activity-correlation.xml to /layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.8.0.34104/conf
[builder]     Copying log4j2.xml to /layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.8.0.34104/conf/logging
[builder]     Writing env.launch/JAVA_TOOL_OPTIONS.append
[builder]     Writing env.launch/JAVA_TOOL_OPTIONS.delim
[builder]   Launch Helper: Contributing to layer
[builder]     Creating /layers/paketo-buildpacks_appdynamics/helper/exec.d/properties
===> EXPORTING
[exporter] Adding layer 'paketo-buildpacks/ca-certificates:helper'
[exporter] Adding layer 'paketo-buildpacks/microsoft-openjdk:helper'
[exporter] Adding layer 'paketo-buildpacks/microsoft-openjdk:java-security-properties'
[exporter] Adding layer 'paketo-buildpacks/microsoft-openjdk:jdk'
[exporter] Reusing layer 'paketo-buildpacks/executable-jar:classpath'
[exporter] Adding layer 'paketo-buildpacks/spring-boot:helper'
[exporter] Reusing layer 'paketo-buildpacks/spring-boot:spring-cloud-bindings'
[exporter] Reusing layer 'paketo-buildpacks/spring-boot:web-application-type'
[exporter] Adding layer 'paketo-buildpacks/appdynamics:appdynamics-java'
[exporter] Adding layer 'paketo-buildpacks/appdynamics:helper'
[exporter] Adding layer 'launch.sbom'
[exporter] Reusing 1/1 app layer(s)
[exporter] Adding layer 'launcher'
[exporter] Adding layer 'config'
[exporter] Reusing layer 'process-types'
[exporter] Adding label 'io.buildpacks.lifecycle.metadata'
[exporter] Adding label 'io.buildpacks.build.metadata'
[exporter] Adding label 'io.buildpacks.project.metadata'
[exporter] Adding label 'org.opencontainers.image.title'
[exporter] Adding label 'org.opencontainers.image.version'
[exporter] Adding label 'org.springframework.boot.version'
[exporter] Setting default process type 'web'
[exporter] Saving dynamic...
[exporter] *** Images (ce348edc4b92):
[exporter]       dynamic
[exporter] Adding cache layer 'paketo-buildpacks/microsoft-openjdk:jdk'
[exporter] Adding cache layer 'paketo-buildpacks/syft:syft'
[exporter] Adding cache layer 'paketo-buildpacks/maven:application'
[exporter] Reusing cache layer 'paketo-buildpacks/maven:cache'
[exporter] Reusing cache layer 'paketo-buildpacks/maven:maven'
[exporter] Adding cache layer 'cache.sbom'
Successfully built image dynamic
> docker run -it --rm -v /mnt/d/code/github/java-sample/bindings:/bindings/dynamic --env SERVICE_BINDING_ROOT=/bindings dynamic
Setting Active Processor Count to 8
Calculating JVM memory based on 14506624K available memory
For more information on this calculation, see https://paketo.io/docs/reference/java-reference/#memory-calculator
Calculated JVM Memory Configuration: -XX:MaxDirectMemorySize=10M -Xmx13895198K -XX:MaxMetaspaceSize=99425K -XX:ReservedCodeCacheSize=240M -Xss1M (Total Memory: 14506624K, Thread Count: 250, Loaded Class Count: 15140, Headroom: 0%)
Enabling Java Native Memory Tracking
Adding 127 container CA certificates to JVM truststore
Spring Cloud Bindings Enabled
Configuring AppDynamics properties
Picked up JAVA_TOOL_OPTIONS: -Djava.security.properties=/layers/paketo-buildpacks_microsoft-openjdk/java-security-properties/java-security.properties -XX:+ExitOnOutOfMemoryError -javaagent:/layers/paketo-buildpacks_appdynamics/appdynamics-java/javaagent.jar -XX:ActiveProcessorCount=8 -XX:MaxDirectMemorySize=10M -Xmx13895198K -XX:MaxMetaspaceSize=99425K -XX:ReservedCodeCacheSize=240M -Xss1M -XX:+UnlockDiagnosticVMOptions -XX:NativeMemoryTracking=summary -XX:+PrintNMTStatistics -Dorg.springframework.cloud.bindings.boot.enable=true
Java 9+ detected, booting with Java9Util enabled.
Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_APPLICATION_NAME] for application name [gateway]
Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_TIER_NAME] for tier name [standard]
Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_NODE_NAME] for node name [node-0]
Full Agent Registration Info Resolver using selfService [false]
Full Agent Registration Info Resolver using selfService [false]
Full Agent Registration Info Resolver using ephemeral node setting [false]
Full Agent Registration Info Resolver using application name [gateway]
Full Agent Registration Info Resolver using tier name [standard]
Full Agent Registration Info Resolver using node name [node-0]
Install Directory resolved to[/layers/paketo-buildpacks_appdynamics/appdynamics-java]
getBootstrapResource not available on ClassLoader
Class with name [com.ibm.lang.management.internal.ExtendedOperatingSystemMXBeanImpl] is not available in classpath, so will ignore export access.
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[DEBUG]: JavaAgent - Setting AgentClassLoader as Context ClassLoader
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: JavaAgent - Low Entropy Mode: Attempting to swap to non-blocking PRNG algorithm
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: JavaAgent - UUIDPool size is 10
Agent conf directory set to [/layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.8.0.34104/conf]
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: JavaAgent - Agent conf directory set to [/layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.8.0.34104/conf]
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[DEBUG]: AgentInstallManager - Full Agent Registration Info Resolver is running
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_APPLICATION_NAME] for application name [gateway]
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_TIER_NAME] for tier name [standard]
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_NODE_NAME] for node name [node-0]
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using selfService [false]
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using selfService [false]
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using ephemeral node setting [false]
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using application name [gateway]
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using tier name [standard][AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using node name [node-0]
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[DEBUG]: AgentInstallManager - Full Agent Registration Info Resolver finished running
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: AgentInstallManager - Agent runtime directory set to [/layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.8.0.34104]
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: AgentInstallManager - Agent node directory set to [node-0]
Agent runtime conf directory set to /layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.8.0.34104/conf
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: AgentInstallManager - Agent runtime conf directory set to /layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.8.0.34104/conf
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: JavaAgent - JDK Compatibility: 1.8+
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: JavaAgent - Using Java Agent Version [Server Agent #22.8.0.34104 v22.8.0 GA compatible with 4.4.1.0 r76b2bb8f45a498afcc5ecaf5a1a9480ed0d4998b release/22.8.0]
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: JavaAgent - Running IBM Java Agent [No]
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: JavaAgent - Java Agent Directory [/layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.8.0.34104]
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: JavaAgent - Java Agent AppAgent directory [/layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.8.0.34104]
Agent logging directory set to [/layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.8.0.34104/logs]
[AD Agent init] Tue Nov 29 07:59:23 UTC 2022[INFO]: JavaAgent - Agent logging directory set to [/layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.8.0.34104/logs]
getBootstrapResource not available on ClassLoader
Registered app server agent with Node ID[8184043] Component ID[3791123] Application ID [1222894]
Started AppDynamics Java Agent Successfully.

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::       (v2.2.13.RELEASE)

2022-11-29 07:59:33.376  INFO 255d83e35e7f --- [kground-preinit] o.h.v.i.u.Version                        : HV000001: Hibernate Validator 6.0.22.Final
2022-11-29 07:59:33.671  INFO 255d83e35e7f --- [           main] c.a.s.c.t.c.c.MasonApplication           : Starting MasonApplication on 255d83e35e7f with PID 1 (/workspace/BOOT-INF/classes started by cnb in /workspace)
2022-11-29 07:59:33.683  INFO 255d83e35e7f --- [           main] c.a.s.c.t.c.c.MasonApplication           : No active profile set, falling back to default profiles: default
2022-11-29 07:59:36.557  INFO 255d83e35e7f --- [           main] o.s.b.w.e.t.TomcatWebServer              : Tomcat initialized with port(s): 8080 (http)
2022-11-29 07:59:36.625  INFO 255d83e35e7f --- [           main] o.a.c.h.Http11NioProtocol                : Initializing ProtocolHandler ["http-nio-8080"]
2022-11-29 07:59:36.627  INFO 255d83e35e7f --- [           main] o.a.c.c.StandardService                  : Starting service [Tomcat]
2022-11-29 07:59:36.627  INFO 255d83e35e7f --- [           main] o.a.c.c.StandardEngine                   : Starting Servlet engine: [Apache Tomcat/9.0.41]
2022-11-29 07:59:36.740  INFO 255d83e35e7f --- [           main] o.a.c.c.C.[.[.[/]                        : Initializing Spring embedded WebApplicationContext
2022-11-29 07:59:36.741  INFO 255d83e35e7f --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 2911 ms
2022-11-29 07:59:37.393  INFO 255d83e35e7f --- [           main] o.s.s.c.ThreadPoolTaskExecutor           : Initializing ExecutorService 'applicationTaskExecutor'
2022-11-29 07:59:37.906  INFO 255d83e35e7f --- [           main] o.s.b.a.e.w.EndpointLinksResolver        : Exposing 2 endpoint(s) beneath base path '/actuator'
2022-11-29 07:59:37.961  INFO 255d83e35e7f --- [           main] o.a.c.h.Http11NioProtocol                : Starting ProtocolHandler ["http-nio-8080"]
2022-11-29 07:59:37.994  INFO 255d83e35e7f --- [           main] o.s.b.w.e.t.TomcatWebServer              : Tomcat started on port(s): 8080 (http) with context path ''
2022-11-29 07:59:37.999  INFO 255d83e35e7f --- [           main] c.a.s.c.t.c.c.MasonApplication           : Started MasonApplication in 5.583 seconds (JVM running for 16.013)
Terminating due to java.lang.OutOfMemoryError: Metaspace
pivotal-david-osullivan commented 1 year ago

Hi @zhoufenqin

I did build & run with AppDynamics but I cut out the logs for readability, you can see the helper log in my output above

Configuring AppDynamics properties

Here is the full output from a new build, also left running for some time:

 Setting Active Processor Count to 4
Memory Calculation: (100% * (30531 + 12564 + 147 + 0)) * 0.35
Calculating JVM memory based on 6584516K available memory
For more information on this calculation, see https://paketo.io/docs/reference/java-reference/#memory-calculator
Calculated JVM Memory Configuration: -XX:MaxDirectMemorySize=10M -Xmx5973124K -XX:MaxMetaspaceSize=99391K -XX:ReservedCodeCacheSize=240M -Xss1M (Total Memory: 6584516K, Thread Count: 250, Loaded Class Count: 15134, Headroom: 0%)
Enabling Java Native Memory Tracking
Adding 127 container CA certificates to JVM truststore
Spring Cloud Bindings Enabled
Configuring AppDynamics properties
Picked up JAVA_TOOL_OPTIONS: -Djava.security.properties=/layers/paketo-buildpacks_microsoft-openjdk/java-security-properties/java-security.properties -XX:+ExitOnOutOfMemoryError -javaagent:/layers/paketo-buildpacks_appdynamics/appdynamics-java/javaagent.jar -XX:ActiveProcessorCount=4 -XX:MaxDirectMemorySize=10M -Xmx5973124K -XX:MaxMetaspaceSize=99391K -XX:ReservedCodeCacheSize=240M -Xss1M -XX:+UnlockDiagnosticVMOptions -XX:NativeMemoryTracking=summary -XX:+PrintNMTStatistics -Dorg.springframework.cloud.bindings.boot.enable=true
Java 9+ detected, booting with Java9Util enabled.
Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_APPLICATION_NAME] for application name [spring-music]
Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_TIER_NAME] for tier name [InventoryTier]
Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_NODE_NAME] for node name [Inventory1]
Full Agent Registration Info Resolver using selfService [false]
Full Agent Registration Info Resolver using selfService [false]
Full Agent Registration Info Resolver using ephemeral node setting [false]
Full Agent Registration Info Resolver using application name [spring-music]
Full Agent Registration Info Resolver using tier name [InventoryTier]
Full Agent Registration Info Resolver using node name [Inventory1]
Install Directory resolved to[/layers/paketo-buildpacks_appdynamics/appdynamics-java]
getBootstrapResource not available on ClassLoader
Class with name [com.ibm.lang.management.internal.ExtendedOperatingSystemMXBeanImpl] is not available in classpath, so will ignore export access.
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[DEBUG]: JavaAgent - Setting AgentClassLoader as Context ClassLoader
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: JavaAgent - Low Entropy Mode: Attempting to swap to non-blocking PRNG algorithm
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: JavaAgent - UUIDPool size is 10
Agent conf directory set to [/layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.11.0.34486/conf]
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: JavaAgent - Agent conf directory set to [/layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.11.0.34486/conf]
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[DEBUG]: AgentInstallManager - Full Agent Registration Info Resolver is running
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_APPLICATION_NAME] for application name [spring-music]
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_TIER_NAME] for tier name [InventoryTier]
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_NODE_NAME] for node name [Inventory1]
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using selfService [false]
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using selfService [false]
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using ephemeral node setting [false]
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using application name [spring-music]
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using tier name [InventoryTier]
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using node name [Inventory1]
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[DEBUG]: AgentInstallManager - Full Agent Registration Info Resolver finished running
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: AgentInstallManager - Agent runtime directory set to [/layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.11.0.34486]
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: AgentInstallManager - Agent node directory set to [Inventory1]
Agent runtime conf directory set to /layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.11.0.34486/conf
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: AgentInstallManager - Agent runtime conf directory set to /layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.11.0.34486/conf
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: JavaAgent - JDK Compatibility: 1.8+
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: JavaAgent - Using Java Agent Version [Server Agent #22.11.0.34486 v22.11.0 GA compatible with 4.4.1.0 r3a8da0f7bc6e93139cf1be2647f2bcc6e7d284cc release/22.11.0]
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: JavaAgent - Running IBM Java Agent [No]
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: JavaAgent - Java Agent Directory [/layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.11.0.34486]
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: JavaAgent - Java Agent AppAgent directory [/layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.11.0.34486]
Agent logging directory set to [/layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.11.0.34486/logs]
[AD Agent init] Fri Dec 02 16:23:01 UTC 2022[INFO]: JavaAgent - Agent logging directory set to [/layers/paketo-buildpacks_appdynamics/appdynamics-java/ver22.11.0.34486/logs]
getBootstrapResource not available on ClassLoader
Started AppDynamics Java Agent Successfully.

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::       (v2.2.13.RELEASE)

2022-12-02 16:23:12.953  INFO 7cb5c5d32ffa --- [kground-preinit] o.h.v.i.u.Version                        : HV000001: Hibernate Validator 6.0.22.Final
2022-12-02 16:23:13.355  INFO 7cb5c5d32ffa --- [           main] c.a.s.c.t.c.c.MasonApplication           : Starting MasonApplication on 7cb5c5d32ffa with PID 1 (/workspace/BOOT-INF/classes started by cnb in /workspace)
2022-12-02 16:23:13.378  INFO 7cb5c5d32ffa --- [           main] c.a.s.c.t.c.c.MasonApplication           : No active profile set, falling back to default profiles: default
2022-12-02 16:23:17.298  INFO 7cb5c5d32ffa --- [           main] o.s.b.w.e.t.TomcatWebServer              : Tomcat initialized with port(s): 8080 (http)
2022-12-02 16:23:17.372  INFO 7cb5c5d32ffa --- [           main] o.a.c.h.Http11NioProtocol                : Initializing ProtocolHandler ["http-nio-8080"]
2022-12-02 16:23:17.374  INFO 7cb5c5d32ffa --- [           main] o.a.c.c.StandardService                  : Starting service [Tomcat]
2022-12-02 16:23:17.376  INFO 7cb5c5d32ffa --- [           main] o.a.c.c.StandardEngine                   : Starting Servlet engine: [Apache Tomcat/9.0.41]
2022-12-02 16:23:17.558  INFO 7cb5c5d32ffa --- [           main] o.a.c.c.C.[.[.[/]                        : Initializing Spring embedded WebApplicationContext
2022-12-02 16:23:17.558  INFO 7cb5c5d32ffa --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 3904 ms
2022-12-02 16:23:18.526  INFO 7cb5c5d32ffa --- [           main] o.s.s.c.ThreadPoolTaskExecutor           : Initializing ExecutorService 'applicationTaskExecutor'
2022-12-02 16:23:19.226  INFO 7cb5c5d32ffa --- [           main] o.s.b.a.e.w.EndpointLinksResolver        : Exposing 2 endpoint(s) beneath base path '/actuator'
2022-12-02 16:23:19.327  INFO 7cb5c5d32ffa --- [           main] o.a.c.h.Http11NioProtocol                : Starting ProtocolHandler ["http-nio-8080"]
2022-12-02 16:23:19.394  INFO 7cb5c5d32ffa --- [           main] o.s.b.w.e.t.TomcatWebServer              : Tomcat started on port(s): 8080 (http) with context path ''
2022-12-02 16:23:19.403  INFO 7cb5c5d32ffa --- [           main] c.a.s.c.t.c.c.MasonApplication           : Started MasonApplication in 7.551 seconds (JVM running for 19.788)

Have you tested setting the class count adjustment parameter I mentioned above to see if this makes a difference?

zhoufenqin commented 1 year ago

Hi @pivotal-david-osullivan thank you, I tried your above suggestion to increase metadata space(--env JAVA_OPTS=-XX:MaxMetaspaceSize=159425K), and it can solve the Terminating due to java.lang.OutOfMemoryError: Metaspace issue.

But I want to know why the metadata space value calculated by buildpack will lead to OOM because if the buildpack can calculate it correctly, we don't want to let customers config the java_opts manually.

I notice that only a few differences from your logs and my logs, but the Calculating JVM memory difference seems large, not sure if it does matters

your log shows:

Calculating JVM memory based on 6584516K available memory
Calculated JVM Memory Configuration: -XX:MaxDirectMemorySize=10M -Xmx5973124K -XX:MaxMetaspaceSize=99391K -XX:ReservedCodeCacheSize=240M -Xss1M (Total Memory: 6584516K, Thread Count: 250, Loaded Class Count: 15134, Headroom: 0%)

my log shows:

Calculating JVM memory based on 14506624K available memory
Calculated JVM Memory Configuration: -XX:MaxDirectMemorySize=10M -Xmx13895198K -XX:MaxMetaspaceSize=99425K -XX:ReservedCodeCacheSize=240M -Xss1M (Total Memory: 14506624K, Thread Count: 250, Loaded Class Count: 15140, Headroom: 0%)

I upload my builder images here and use the oom-app to test, can you help to try it again. Thanks so much :)

//======================== By the way, how to print buildpack debug level? I notice your log has some debug-level logs, like

Memory Calculation: (100% * (30531 + 12564 + 147 + 0)) * 0.35

I also want to know some detail logs

pivotal-david-osullivan commented 1 year ago

I could not reproduce even with your builder @zhoufenqin (I was already using your sample app). My suggestion was not to adjust the Metaspace directly but instead to adjust the class count variable at runtime which should achieve an increase also: BPL_JVM_CLASS_ADJUSTMENT=120%.

It may be helpful to share your container/runtime configuration also, this may be where the difference lies.

The extra debug output can be seen by setting the env var BP_DEBUG=true. I will continue to attempt to reproduce in the meantime.

showpune commented 1 year ago

cglib is widely used in spring and it will create the classes during runtime, how can we handle this case?

Normaly I saw the final metaspace size is less than 100m, I think it is too smaller according to me experience for spring project

dmikusa commented 1 year ago

@showpune It's a possibility but I don't think that we've observed this making a material difference in most apps. The formula we use counts the classes and then multiplies by a factor of 0.35. It then multiplies by 5,800 bytes per class. So if cglib generated 1000 extra classes that's only roughly a 2M difference in the calculation. There's overhead included in the calculation by default to account for things like this. If you are doing something that is causing an extremely large number of proxy classes to be calculated, then you'd need to adjust the setting @pivotal-david-osullivan mentioned to account for what your app is doing.

If you have a concern I would suggest you monitor your metaspace usage and see what is consuming the space. You can then tune accordingly.

@zhoufenqin @pivotal-david-osullivan

Memory Calculation: (100% (30531 + 12564 + 147 + 0)) 0.35

It is showing only 147 agent classes for AppDynamics. That seems low to me. I wonder if the agent changed something, some of the agents do things to hide the classes. We are looking at these extensions for class file counting now,

var ClassExtensions = []string{".class", ".classdata", ".clj", ".groovy", ".kts"}

Maybe there's an extension we need to add?

showpune commented 1 year ago

Hi @dmikusa ,

I tried to check with JFR to find the details in metaspace , but I go another issue in https://github.com/paketo-buildpacks/libjvm/issues/235

dmikusa commented 1 year ago

@showpune I think you should be able to use AppDynamics too, like if you're already using that. There's a lot of overlap between the two tools. Just not both at the same time. It appears like there's an issue between AppD & JFR there.