search

corretto / corretto-17

Amazon Corretto 17 is a no-cost, multi-platform, production-ready distribution of OpenJDK 17
GNU General Public License v2.0
216 stars 51 forks source link

Memory Consumption Increase after migrating to Amazon Corretto Java 17 #194

Open Rtkverma6 opened 2 months ago

Rtkverma6 commented 2 months ago

Dear Amazon Corretto Support Team,

I hope this message finds you well. We recently migrated our product from Java 8 to Amazon Corretto Java 17, and after the migration, we noticed a significant increase in memory consumption—roughly 2 to 3 times compared to what we observed while using Java 8.

We would like to understand whether this is an expected outcome when upgrading from Java 8 to Corretto Java 17, or if it might be indicative of a specific issue in our configuration or environment. Additionally, we are seeking guidance on possible workarounds or optimizations to reduce the memory footprint after the migration.

Some specific questions we have:

  1. Is it common for memory usage to increase when moving from Java 8 to Java 17? If so, what are the contributing factors?
  2. Are there any recommended JVM configurations or garbage collection settings that could help mitigate this increase in memory consumption?
  3. Could the newer garbage collectors (such as G1GC or others) or specific Java 17 features be contributing to the elevated memory usage?
  4. Are there any known issues related to memory management that we should be aware of with Amazon Corretto Java 17? We would appreciate your insights and recommendations to help us optimize our product's performance after this migration.

Thank you for your assistance.

WithEnoughCoffee commented 2 months ago

Were looking into this thank you.

simonis commented 2 months ago

@Rtkverma6 can you please share more details about your use case? I.e. provide the command line options you use for JDK 8 and 17, explain the way how you measure memory consumption and provide the data for JDK 8 and 17. Are you talking about an increase in heap memory usage or in the total native memory footprint (i.e. RSS) of the Java process? One difference between JDK 8 and 17 is that the default garbage collection has changed from Parallel to G1 GC which might use heap memory more aggressively. But without further information it is hard to diagnose your problem.

Rtkverma6 commented 2 months ago

Hi Simonis, Autumn,

In Java 8, we used to start our project with start.jar using megha user and ParNewGC GarbageCollector on jetty server using below command.

umask 0027; runuser megha -c "java -XX:+UseParNewGC -XX:MinHeapFreeRatio=20 \
-XX:MaxHeapFreeRatio=20 -Xmx${JVM_MEMORY_SIZE}m -jar start.jar etc/console-capture.xml \
-Dapp.home=$MEGHA_HOME -Djdk.tls.ephemeralDHKeySize=2048 -Djna.tmpdir=$MEGHA_HOME/tmp -Djava.io.tmpdir=$MEGHA_HOME/backup/app >> $MEGHA_JETTY_LOG 2>&1 & \
echo \$! > $MEGHAJETTY_PID_FILE"

After Java 17 Upgrade, as ParNewGC was not supported, we first used G1GC then we shifted to ParallelGC like below

umask 0027; runuser megha -c "java -XX:+UseParallelGC -XX:MinHeapFreeRatio=20 \
-XX:MaxHeapFreeRatio=20 -Xmx${JVM_MEMORY_SIZE}m -jar start.jar etc/jetty-logging.xml \
-Dapp.home=$MEGHA_HOME -Djdk.tls.ephemeralDHKeySize=2048 -Djna.tmpdir=$MEGHA_HOME/tmp -Djava.io.tmpdir=$MEGHA_HOME/backup/app >> $MEGHA_JETTY_LOG 2>&1 & \
echo \$! > $MEGHAJETTY_PID_FILE"

When we used G1GC, there were uneven spikes in heap memory usage like once it is 15% then in 1-1.5 hrs the heap memory usage goes to 60%. The heap memory consumption varies from 10% to 80% and sometimes it goes to OOM also and application crashes. So we assumed G1GC is not stable for our application and we shifted to ParallelGC.

After shifting to ParallelGC, the heap memory usage does not show abrupt hikes but have settled to around 50-60% heap usage which used to be 15-20% when using Java8.

Also we analyzed our application side by side on Java 8 as well as Java 17 with same load and exactly same configuration like OS, RAM, resource loads etc. and then also we observed same heap memory consumption as above.

We are not talking about RSS of java process but heap memory usage. We use following command to log memory usage for megha user ps -o uid,pid,ppid,%cpu,%mem,start,time,stat,vsz,rss,lwp,nlwp,comm -u megha

Memory usage Pattern on Java 8 [root@localhost sys]# grep -iR "17675" 20240913.log UID PID PPID %CPU %MEM STARTED TIME STAT VSZ RSS LWP NLWP COMMAND 1001 17675 1 40.7 13.6 Sep 04 3-14:25:02 Sl 11297952 1068464 17675 197 java 1001 17675 1 40.7 13.5 Sep 04 3-14:25:54 Sl 11297952 1060048 17675 197 java 1001 17675 1 40.7 13.8 Sep 04 3-14:26:28 Sl 11297952 1085668 17675 197 java 1001 17675 1 40.7 13.7 Sep 04 3-14:27:20 Sl 11297952 1082132 17675 197 java 1001 17675 1 40.7 12.6 Sep 04 3-14:27:59 Sl 11297952 992580 17675 197 java 1001 17675 1 40.7 12.9 Sep 04 3-14:28:43 Sl 11297952 1020096 17675 197 java 1001 17675 1 40.7 13.3 Sep 04 3-14:29:34 Sl 11297952 1049968 17675 197 java 1001 17675 1 40.6 13.0 Sep 04 3-14:30:16 Sl 11297952 1020864 17675 197 java 1001 17675 1 40.6 13.3 Sep 04 3-14:31:10 Sl 11297952 1046468 17675 197 java 1001 17675 1 40.6 13.1 Sep 04 3-14:32:03 Sl 11297952 1029776 17675 197 java 1001 17675 1 40.6 13.4 Sep 04 3-14:32:48 Sl 11297952 1058816 17675 197 java 1001 17675 1 40.6 13.4 Sep 04 3-14:33:34 Sl 11297952 1058548 17675 197 java 1001 17675 1 40.6 13.3 Sep 04 3-14:34:26 Sl 11297952 1046524 17675 197 java 1001 17675 1 40.6 13.5 Sep 04 3-14:35:17 Sl 11297952 1062976 17675 197 java 1001 17675 1 40.6 14.1 Sep 04 3-14:36:10 Sl 11297952 1109228 17675 197 java 1001 17675 1 40.6 14.1 Sep 04 3-14:36:52 Sl 11297952 1111368 17675 197 java 1001 17675 1 40.6 13.0 Sep 04 3-14:37:39 Sl 11297952 1024828 17675 197 java 1001 17675 1 40.5 14.1 Sep 04 3-14:38:29 Sl 11297952 1113812 17675 197 java 1001 17675 1 40.5 14.1 Sep 04 3-14:39:13 Sl 11297952 1108348 17675 197 java

Memory Usage Pattern on Java 17 with G1GC UID PID PPID %CPU %MEM STARTED TIME STAT VSZ RSS LWP NLWP COMMAND 1001 3082 1 7.1 44.6 Aug 28 1-03:36:39 Sl 12085156 3506444 3082 127 java 1001 3082 1 7.1 44.6 Aug 28 1-03:36:58 Sl 12085156 3508008 3082 127 java 1001 3082 1 7.1 44.7 Aug 28 1-03:37:20 Sl 12085156 3512012 3082 129 java 1001 3082 1 7.1 44.7 Aug 28 1-03:37:42 Sl 12085156 3515888 3082 127 java 1001 3082 1 7.1 52.0 Aug 28 1-03:38:07 Sl 12085156 4090516 3082 127 java 1001 3082 1 7.1 52.1 Aug 28 1-03:38:30 Sl 12085156 4094308 3082 127 java 1001 3082 1 7.1 52.1 Aug 28 1-03:38:53 Sl 12085156 4098644 3082 127 java 1001 3082 1 7.1 52.2 Aug 28 1-03:39:12 Sl 12085156 4102388 3082 127 java 1001 3082 1 7.1 31.7 Aug 28 1-03:39:44 Sl 12085156 2491096 3082 127 java 1001 3082 1 7.1 53.5 Aug 28 1-03:40:08 Sl 12085156 4201888 3082 127 java 1001 3082 1 7.1 53.6 Aug 28 1-03:40:27 Sl 12085156 4214532 3082 127 java 1001 3082 1 7.1 54.7 Aug 28 1-03:40:45 Sl 12085156 4295112 3082 127 java 1001 3082 1 7.1 56.8 Aug 28 1-03:41:06 Sl 12085156 4466296 3082 127 java 1001 3082 1 7.1 57.5 Aug 28 1-03:42:04 Sl 12085156 4516036 3082 127 java 1001 3082 1 7.1 57.6 Aug 28 1-03:43:21 Sl 12085156 4530048 3082 127 java 1001 3082 1 7.1 57.7 Aug 28 1-03:43:39 Sl 12085156 4533136 3082 127 java 1001 3082 1 7.1 27.5 Aug 28 1-03:44:22 Sl 12085156 2159584 3082 127 java 1001 3082 1 7.1 27.3 Aug 28 1-03:45:00 Sl 12085156 2150924 3082 127 java 1001 3082 1 7.1 26.4 Aug 28 1-03:45:43 Sl 12085156 2075364 3082 127 java 1001 3082 1 7.1 28.1 Aug 28 1-03:46:22 Sl 12085156 2206700 3082 127 java 1001 3082 1 7.1 44.2 Aug 28 1-03:46:47 Sl 12085156 3478356 3082 127 java 1001 3082 1 7.1 50.2 Aug 28 1-03:47:08 Sl 12085156 3943884 3082 127 java 1001 3082 1 7.1 50.8 Aug 28 1-03:47:28 Sl 12085156 3994276 3082 127 java 1001 3082 1 7.1 51.2 Aug 28 1-03:47:48 Sl 12085156 4024152 3082 127 java

Memory usage Pattern on Java 17 with ParallelGC [root@localhost sys]# grep -iR "113577" 20240913.log UID PID PPID %CPU %MEM STARTED TIME STAT VSZ RSS LWP NLWP COMMAND 1001 113577 1 8.6 50.6 Sep 04 18:12:09 Sl 6385156 1184812 113577 75 java 1001 113577 1 8.6 49.8 Sep 04 18:12:59 Sl 6385156 1153668 113577 74 java 1001 113577 1 8.6 49.9 Sep 04 18:13:21 Sl 6385156 1156796 113577 73 java 1001 113577 1 8.6 49.9 Sep 04 18:14:10 Sl 6385156 1155752 113577 74 java 1001 113577 1 8.6 50.8 Sep 04 18:15:21 Sl 6385156 1192732 113577 74 java 1001 113577 1 8.6 50.3 Sep 04 18:16:08 Sl 6385156 1172344 113577 74 java 1001 113577 1 8.6 51.1 Sep 04 18:16:55 Sl 6385156 1201824 113577 73 java 1001 113577 1 8.6 50.5 Sep 04 18:17:45 Sl 6385156 1180548 113577 73 java 1001 113577 1 8.6 50.6 Sep 04 18:18:32 Sl 6385156 1182380 113577 73 java 1001 113577 1 8.6 50.2 Sep 04 18:20:16 Sl 6385156 1166404 113577 75 java 1001 113577 1 8.6 49.5 Sep 04 18:21:17 Sl 6385156 1140400 113577 73 java 1001 113577 1 8.6 50.6 Sep 04 18:22:56 Sl 6385156 1183276 113577 74 java 1001 113577 1 8.6 59.8 Sep 04 18:23:44 Sl 6385156 1153048 113577 73 java 1001 113577 1 8.6 50.8 Sep 04 18:24:09 Sl 6385156 1190796 113577 74 java 1001 113577 1 8.6 50.4 Sep 04 18:25:20 Sl 6385156 1177480 113577 73 java 1001 113577 1 8.6 50.6 Sep 04 18:26:07 Sl 6385156 1181952 113577 74 java 1001 113577 1 8.6 50.0 Sep 04 18:26:53 Sl 6385156 1158924 113577 74 java 1001 113577 1 8.6 49.8 Sep 04 18:27:18 Sl 6385156 1151132 113577 73 java 1001 113577 1 8.6 51.1 Sep 04 18:28:06 Sl 6387068 1204496 113577 74 java 1001 113577 1 8.6 50.4 Sep 04 18:28:56 Sl 6387068 1175088 113577 74 java 1001 113577 1 8.6 49.9 Sep 04 18:30:07 Sl 6387068 1154776 113577 74 java 1001 113577 1 8.6 51.2 Sep 04 18:31:42 Sl 6387068 1207864 113577 73 java 1001 113577 1 8.6 50.7 Sep 04 18:32:53 Sl 6387068 1186216 113577 74 java 1001 113577 1 8.6 51.1 Sep 04 18:33:18 Sl 6387068 1201920 113577 73 java 1001 113577 1 8.6 50.7 Sep 04 18:33:42 Sl 6387068 1185480 113577 73 java 1001 113577 1 8.6 50.1 Sep 04 18:34:54 Sl 6387068 1164252 113577 74 java

Could you please provide guidance regarding questions asked in initial note. Thank you for your assistance.

shipilev commented 2 months ago

I would highly suspect the GC behavior with only -Xmx set is different between G1 and Parallel. I think you need to study the GC logs when running with Parallel and G1 to see how GC size their respective heaps over the course of workload lifecycle.

Our usual recommendation is to set -Xmx == -Xms, and add -XX:+AlwaysPreTouch. This would set the heap upfront at startup, and remove any specific GC behaviors w.r.t. heap resizing policies. Plus, it is safer, since you will know all that memory is available if JVM ever needs it.

We are not talking about RSS of java process but heap memory usage.

To be extra clear, we are talking about Java heap memory usage?

Because the memory usage data you provided does talk about VSZ and RSS of Java process :) BTW, that memory usage data also is confusing to me, here is taking the first lines of relevant blocks, and reformatting them for easy comparison:


UID     PID PPID  %CPU  %MEM  STARTED TIME      STAT       VSZ     RSS    LWP  NLWP COMMAND

# Memory usage Pattern on Java 8
1001  17675    1  40.7  13.6  Sep 04 3-14:25:02   Sl  11297952 1068464  17675   197 java

# Memory Usage Pattern on Java 17 with G1GC
1001   3082    1   7.1  44.6  Aug 28 1-03:36:39   Sl  12085156 3506444   3082   127 java

# Memory usage Pattern on Java 17 with ParallelGC
1001 113577    1   8.6  50.6  Sep 04 18:12:09     Sl   6385156 1184812 113577    75 java

From this, I can see that VSZ for Parallel GC is almost twice as low in JDK 17, and RSS is only 10% larger in JDK 17. Yet, MEM% says 13.6% in JDK 8 case, and 50.6% in JDK 17 case! How does that make sense? AFAIU, MEM% is the ratio of RSS to the amount of physical memory on the machine. So RSS and MEM% numbers are disagreeing with each other. The only plausible theory I have is that they are running in very different environments.

Rtkverma6 commented 2 months ago

Hi Shipilev,

Sorry for late response from my side

We will use "-Xmx == -Xms, and add -XX:+AlwaysPreTouch." and will update if there are any improvement with these flags on memory consumption.

### To be extra clear, we are talking about Java heap memory usage? I further checked and as u said MEM% is the ratio of RSS to the amount of physical memory on the machine, it's the total native memory footprint (i.e. RSS) of the Java process.

Let me share the mem consumption stats for better understanding from a different environment. These are the stats for Memory usage Pattern on Java 17 with ParallelGC All other stats were fine I guess

[root@localhost sys]# grep -iR "31413" * UID PID PPID %CPU%MEM STARTED TIME STAT VSZ RSS LWP NLWP COMMAND 20240904.log: 1001 31413 1 8.7 50.6 Aug 28 14:38:36 Sl 6680776 1954600 31413 77 java 20240904.log: 1001 31413 1 8.7 50.4 Aug 28 14:38:58 Sl 6680776 1947256 31413 76 java 20240904.log: 1001 31413 1 8.7 50.2 Aug 28 14:39:25 Sl 6680776 1941000 31413 77 java 20240904.log: 1001 31413 1 8.7 50.3 Aug 28 14:39:53 Sl 6680776 1942172 31413 77 java 20240904.log: 1001 31413 1 8.7 50.2 Aug 28 14:40:17 Sl 6680776 1940128 31413 77 java 20240904.log: 1001 31413 1 8.7 50.1 Aug 28 14:40:41 Sl 6680776 1936664 31413 76 java 20240904.log: 1001 31413 1 8.7 50.4 Aug 28 14:41:09 Sl 6680776 1949332 31413 77 java 20240904.log: 1001 31413 1 8.7 50.3 Aug 28 14:41:32 Sl 6680776 1944516 31413 77 java 20240904.log: 1001 31413 1 8.7 50.5 Aug 28 14:41:55 Sl 6680776 1951348 31413 76 java 20240904.log: 1001 31413 1 8.7 50.4 Aug 28 14:42:21 Sl 6680776 1949096 31413 78 java 20240904.log: 1001 31413 1 8.7 51.3 Aug 28 14:42:48 Sl 6680776 1983460 31413 76 java 20240904.log: 1001 31413 1 8.7 51.6 Aug 28 14:43:12 Sl 6680776 1993212 31413 76 java 20240904.log: 1001 31413 1 8.7 51.4 Aug 28 14:45:09 Sl 6680776 1986448 31413 78 java 20240904.log: 1001 31413 1 8.7 52.4 Aug 28 14:45:35 Sl 6680776 2025012 31413 79 java 20240904.log: 1001 31413 1 8.7 52.1 Aug 28 14:45:59 Sl 6680776 2013936 31413 80 java 20240904.log: 1001 31413 1 8.7 52.0 Aug 28 14:46:27 Sl 6680776 2008284 31413 77 java 20240904.log: 1001 31413 1 8.7 51.9 Aug 28 14:46:51 Sl 6680776 2007384 31413 76 java 20240904.log: 1001 31413 1 8.7 51.8 Aug 28 14:47:14 Sl 6680776 2001232 31413 77 java 20240904.log: 1001 31413 1 8.7 51.5 Aug 28 14:47:41 Sl 6680776 1991756 31413 77 java 20240904.log: 1001 31413 1 8.7 51.4 Aug 28 14:48:04 Sl 6680776 1986656 31413 77 java 20240904.log: 1001 31413 1 8.7 51.1 Aug 28 14:48:27 Sl 6680776 1975900 31413 76 java 20240904.log: 1001 31413 1 8.7 52.0 Aug 28 14:48:54 Sl 6680776 2009708 31413 77 java 20240904.log: 1001 31413 1 8.7 51.8 Aug 28 14:49:17 Sl 6680776 2003820 31413 77 java 20240904.log: 1001 31413 1 8.7 51.8 Aug 28 14:49:41 Sl 6680776 2003856 31413 76 java 20240904.log: 1001 31413 1 8.7 52.6 Aug 28 14:50:07 Sl 6680776 2031772 31413 78 java 20240904.log: 1001 31413 1 8.7 50.8 Aug 28 14:50:31 Sl 6680776 1963940 31413 76 java 20240904.log: 1001 31413 1 8.7 50.6 Aug 28 14:50:55 Sl 6680776 1957496 31413 76 java 20240904.log: 1001 31413 1 8.7 50.6 Aug 28 14:51:20 Sl 6680776 1956060 31413 78 java

If you have any other suggestions related to flags that can be added or steps that can be taken to reduce %MEM, please provide.

Thanks for your assistance.