JVM and Docker memory problems
When it comes to running Java applications in Docker with default configuration and running it with wrong set of values for Java Virtual Machine (JVM) arguments gives problems.
Lets have a look at a problem that I came across during my day to day work, my team was responsible for developing and managing a java application which was developed mainly based on Odata protocol and Apache Olingo framework. In simple words this application was responsible to handle requests and data between the client application and the database. This Java application was configured to run in Openliberty server with Docker and JDK11. Let’s call this application as Odata Provider (ODP).
The testing team was responsible to perform some running tests on this Java application. When they were running the tests, they encountered a strange error, out of no where the JVM gets killed or the container gets killed. This container was running and managed by a Kubernetes cluster in Rancher.
The only information we had was the log message from the Openliberty server and the message saying that JVM or the Docker container got killed due to not enough of memory. Check below images,
In the log messages there was not much information available to identify the cause. This was happening randomly when running the tests. As the first step did some configuration changes in order to get more details from the log but couldn’t get much details since JVM gets killed. Because till it gets killed it is operating normally and no unusual information to be found in the logs as well.
Therefore, following are the steps I followed to analyze the above problem.
1. Ran a test with similar configuration and tried to analyze it with VisualVM.
Since there were not much information to identify the cause, I started running the same test by configuring my own namespace and deploying Odata container in it. I connected VisualVM tool to the container running in Rancher to get details about what is going on inside the JVM. There are many ways to get JVM information running inside a docker container like getting heap dumps from inside the container, but I took this approach, since VisualVM has more support in identifying the causes.
When the tests were executing, I was watching the behavior of the heap allocation and noticed that used heap is getting increased (which is normal when loading model classes) but with that, heap allocation also getting increased without increasing the “Garbage Collection” (GC) activity (or with less GC). Check the below image and the circled area there were many increases like that until the JVM got killed (yes, I also got the same error after some time). It made me wonder whether this issue can be a potential memory leak in our application.
But there was a limitation to get a memory dump through VisualVM since I was connecting remotely to a container running in Rancher and I thought it would be more easy to recreate the problem in my local machine and analize it through VisualVM if it is a memory leak. So I continued my investigation to the 2nd step.
2. I ran a test by configuring ODP locally without using a docker container.
Configured an Openliberty instance on my local machine by deploying ODP .war file and ran the same test on it. When analyzing using VisualVM, I noticed the similar kind of growth in JVM heap but not like before. The heap wasn’t increasing after some level and noticed used heap was stabilizing after some time. Then ran a memory profiler and analyzed the memory and found large objects which were using high amount of memory but after some time I noticed that, count of those live objects was not growing.
This made me realize it has to be something related to docker container and JVM memory, then it came to my mind that we are using -XX:MaxRAMPercentage JVM argument when configuring our ODP container and setting it to 95% in app-odata.yaml.
Now everything started to add up 😊
Usually when we run Java applications on containers, if we haven’t specified max, min values to the JVM heap, JVM does calculations and assigns values. It is happening based on the resources and memory available on the container, but most of the time it ends up by calculating wrong values (not a big problem for small java apps). So, when the used heap size is reaching the calculated ceiling value (which is wrong since max allocation is wrong) JVM recalculates a ceiling (which is again wrong) and increases the heap without forcing GC to run. This happens till it reaches the limits of the container, when it exceeds the limits, it decides to kill the JVM which consumes its memory. Sometimes container itself runs out of memory and gets killed due to the memory consumption of JVM.
Now another problem comes to mind, why we got that error because we had already set max as -XX:MaxRAMPercentage=95.0. What was the reason behind it?
The reason was the value we are setting. It is too high and when JVM reaches 95% (maximum allocated value for JVM by gradually increasing the ceiling) it runs out of the limits of the container and leads us to the same problem. So, we must set proper values with care. When the JVM has lot of memory allocated as the maximum limit, till its ceiling reaches a value nearly to that maximum value, it doesn’t enforce much GC activities to free used heap assuming that it has more memory and the other reason is, increment of GC activities affects the throughput of the application running in JVM. So, after realizing the cause, continued 3rd step
3. Changed the max and min values to 75% and 20% in app-odata.yaml, deployed it and ran 5 Jmeter tests with 5000 requests each to load model classes to the application simultaneously (total 25000)
Noticed that with new configuration, JVM forces GC to run and it frees up the used heap effectively when it reaches the ceiling.
Now it seems the issue has been fixed with the new configuration. 😊
References: