The last blog post talked lots about Logging vs Memory with an emphasis on memory allocation, and discussed some possible improvements. However, I didn't run this through with an actual application. That's what this blog post is about.
TL;DR JDK 11 is better in some counter-intuitive ways. If you are still using JDK 1.8, you can reap some significant performance improvements and reduce memory allocation rates just by recompiling and running with a more recent version of the JDK.
Load Testing Framework
My usual load test tool is Gatling, which is very good at nailing down complex scenarios and running various complex feeds and random feeds. There are various tutorials and guides and you can run it with CI using Taurus.
I recommend downloading the stand alone version and running a script from the
The goal here is to have some sustained requests rather than some crazy amount of load, so we fire up 500 concurrent users over 500 seconds with 500 requests each:
It's not very sophisticated, but it doesn't need to be. I'm running this on a laptop, with both Gatling and the app on the same hardware, so a stress test would be minimally accurate in any case.
I ran this play application using the following JVM options, using
sbt stage to create a production version of Play:
For the logging, I set up
logback.xml with the following:
As you can see, there are no surprises here. I bumped up the ring buffer size and added a listener just in case.
JDK 14 with Shenandoah
The first thing I tried was the ideal use case: JDK 14 using Shenandoah.
The settings here are for web applications specifically here: the
compact setting runs GC cycles continuously providing prompt space reclaimation. Pacing is disabled as it adds extra latency, and isn't relevant with
Initially, I was interested in seeing how Shenandoah's GC interacts with high memory allocation rates, and compare it to the premature tenuring in G1GC under high memory allocation rates. I had trouble using GC logs with gceasy.io, but was able to verify the object allocation rate with Yourkit 2020.7, using the object allocation count recording.
This works great! The CPU runs at around 35%, split evenly over all cores, but that's Gatling.
But look at those allocation rates. Look at that heap.
When I ran with
INFO at the root level, the mean rate was 350 K/s, with the highest allocation rate was 419 K/s.
When I turn on
DEBUG at the root level, the allocation rate is around 350 K/s.
When I turn on
TRACE at the root level, the allocation rate is still between 350 K/s and 400 K/s.
I worried at first that I was dropping
TRACE statements from the async appender as the queue filled up. But no: adding a
FailureSummaryLoggingAppenderListener did not result in a warning, and the JSON file was full of tracing statements. The application as a whole was also in good shape: the vast majority of HTTP responses completed in less than 5 milliseconds. The CPU wasn't breaking a sweat. There were just way fewer allocations than I expected.
Here's the GC logs and Gatling load test results for reference:
So even without running a heavy load test, I learned some things that run counter to my intuition. The next question is how much of this is real.
JDK 1.8 with G1GC
Repeating the exact same experiment with JDK 1.8 and G1GC, using
Ah-ha. The allocation rate is 2.6 M/s. This is still way below the limits of what the JVM is capable of, but more in line with what I'd expect.
In addition, G1GC took up to 2.5 GB of heap before collapsing again, as opposed to Shenandoah which barely took up 512 MB.
The average duration of GC pauses was 655 ms, as opposed to 5ms with Shenandoah.
I tried running it with
INFO. Interestingly, I saw around 1000 allocations per second under JDK 1.8 when idle. In JDK 11, the idle allocation rate was 761/s. In JDK 14, it was 351/s.
When I ran logging at
INFO level, I was still seeing an allocation rate of 2.5 M/s. So, logging is not a significant source of memory allocation here; most of the garbage is in the framework itself, processing HTTP requests.
TRACE GC logs under 1.8:
I'm not sure why the CPU doesn't show Gatling in the Yourkit view, but it shows under htop. I think it's just 1.8 not having as much info.
Next up – run JDK 11 with G1GC.
JDK 11 with G1GC
Let's try JDK 11 with
TRACE logging, but running with G1GC. This should at least give us an apple-to-apples comparison between 1.8 and 11.
Interesting. Same results. Whatever the improvement is, it's in JDK 11, not related to JDK 14 or G1GC.
Now let's try JDK 14 with G1GC.
JDK 14 with G1GC
Same results as JDK 11.
The allocation rate was the same – around 300 K/s or even lower than that. I sometimes saw it dip down to 276 K/s. You can see how slowly the heap grows compared to 1.8.
Whatever it is that causes allocation rates to drop, it's not the garbage collector – it's something else. It could be the improvements in string concatenation added in JDK 1.9, or it could be improvements to the JIT compiler.
Because JDK 14 comes with Graal's JVMCI compiler included, we can turn that on as well and see if scalar replacement helps any. I did not see much of a difference between JVMCI and C2 here.
We Don't Have To Do Zero Allocation
The advancement of garbage collection in newer JVMs means that there does not need to be as much focus on garbage-free and frugal memory techniques as there has been in the past. As Martin Thompson says in Evolution of Financial Exchange Architectures:
Garbage collection is one of the systemic events. That was the big one that most people started to realize. You run on something like parallel old in Java, or most of the various garbage collectors in C#, and you get these huge pauses. CMS was probably the better choice in finance for a long time, but it still had these full GCs that were nasty, and stop-the-world. People went with one of two approaches, either a huge memory space, and you just hoped and prayed that you didn't get in an event that was nasty before the end of the trading day. At the end of the trading day, you triggered a full GC and you cope with it. Or, you just write-no-allocate in your application. Those are the major approaches people took.
Then things start to change. People discovered C4, the Azul's Zing, concurrently compacting collector, which was just revolutionary, where we could run at high allocation rates, and not get really nasty GC pauses. Part of the history of that is that was originally designed for the Vega CPU where you're looking at up to 1000 CPU cores. Things like Amdahl's law was in your face all of the time. Stop-the-world events really got to hurt you. They're designed to cope with this and have a very responsive system. That's changed things a lot. The nice thing is it's inspired other things going forward. We've got GC Shenandoah. G1, just ignore in this space because it still is not really a proper concurrent collector. That's since C4 leads the way. ZGC is very much inspired by it but running way behind. It's not generational. It's got various other issues. Shenandoah is looking nice, especially on smaller heaps. We're getting progress in this area. It's changing how we think about this. We don't have to do zero allocation, like we did in the past. [emphasis added]
I knew that I'd see improvements with newer GCs, but the improvements here are such that I'm still taking stock.
Clearly it's entirely possible to log an application at
TRACE using the newer JVMs without impacting your CPU or GC. There's a lot you can do with that.
Note that you are still dependent on the IO bandwidth of your disk drive. This load test didn't stress the NVMe SSD drive in the laptop, but cloud instances typically have around 250MB/sec of IO. However, it's entirely possible to set up a
tmpfs volume with 1 GB, and write all debugging and trace information to memory – a c5 large instance has 8 GB going free, and Shenandoah means you can run a Play application in 512 MB and still have headroom.