A Funny Thing Happened on the Way to Java 8

Indeed is migrating from Java 7 to Java 8. We’re migrating in phases, starting with running our Java 7 compiled binaries on JRE 8, the Java 8 runtime. Rather than switch everything at once, we started with a few canary apps to get a sense for the kinds of problems we might find.

We selected our job search web app as our first canary. Last May, we switched a single job search server in production to JRE 8. We’d been running with JRE 8 in a QA environment for several weeks without any trouble. But when we switched to JRE 8 in production, the system load rose from 5 (a normal level) to 20 (an abnormal level): high enough to require a fix before proceeding. Fixing the problem required unusual measures.

Production metrics in Datadog

I started by looking at Datadog, a third-party, cloud-based metric and event correlation service that we use for real-time monitoring. The following Datadog graph shows the system load by host for every job search server in one of our data centers. The outlier (blue line) is the server running JRE 8.

figure-1-system-load-with-64m-codecache

Figure 1. System load for job search servers in a data center

Here is the median response time by host. Again, the server running JRE 8 is the outlier.

figure-2-median-response-time-64m-codecache

Figure 2. Median response time by host

The job search servers that were still on JRE 7 had normal system loads and normal median response times, so the problem was specific to the JRE 8 server.

It’s not unusual for a Java process to slow down because of garbage collection (GC) activity. We publish our GC metrics to Datadog, and the GC graphs for the JRE 8 instances looked normal.

Production log files

Next, I checked the web application log files. I retrieved every log message from the four hours when we used JRE 8, plus the log messages for the previous 24 hours. There were too many messages to read by hand. Instead, I focused on changes in the distribution of errors. I extracted the name of the associated Java class for each error and then generated histograms for different time periods.

The histograms showed a slight increase in memcached client timeouts during the JRE 8 period. They also showed we used an open-source memcached client library that is no longer maintained. A Google search didn’t turn up any JRE 8 specific problems with the library. I glanced through its source code but didn’t see any problems. I decided that the increase in timeouts was most likely just a side effect of the higher system load.

Reproducing the problem in QA

Since the evidence from our production environment didn’t identify the problem, the next step was to try to reproduce it in our QA environment. As I mentioned earlier, the web app had been running normally on JRE 8 in QA. That wasn’t surprising, because performance problems might not manifest themselves until the system is under enough load, and our QA servers don’t get as much traffic as our production servers. I hoped that if I increased traffic beyond normal QA levels, we would see the same symptoms.

I queried our Imhotep system to find the relative frequencies of our most common incoming requests. Then, using JMeter, I simulated that mixture of traffic and ran it twice while monitoring system load, once each with instances on JRE 7 and JRE 8. In both cases, the web app processed about 50 requests per second. The system load was about the same in both cases, too.

Fifty requests per second is a higher traffic load than we normally simulate in QA, but it is still not at the level we receive in production. When we started this effort, our production job search instances each served approximately 350 requests per second. To reproduce the problem in QA, I would need to get closer to that traffic volume.

Ruling out JMeter as a bottleneck

Why was our application pegged at 50 requests/sec? Before blaming the QA environment, I needed to rule out JMeter as the bottleneck. I installed JMeter on a second server, configured it like the first JMeter instance, and then ran both at the same time. If the two instances combined had run at more than 50 requests/sec, I would know JMeter was the bottleneck. In that case, the next step would be to add more JMeter instances until we either saturated the web app or caused the system load to rise to 20.

It turned out JMeter wasn’t the bottleneck. When I ran both instances at the same time, the aggregate throughput was still 50 requests/sec.

Eliminating slow services

The job search web app depends on 22 services. If some of them are slow enough, the web app will slow down, too. A service in QA may be slower than its production counterpart. We sometimes replace slow services with fake but fast versions when isolating the dependent application for performance analysis. I decided to create fake versions of the five services that our application uses the most.

Using the new fake services, JMeter drove the webapp at 100 requests/sec. JRE 8 was about 15% slower than JRE 7, but the system load still wasn’t very high — and the difference between JRE 7 and JRE 8 varied a lot from one run to the next. Still, since the numbers were different, I profiled the performance of both configurations using YourKit.

YourKit

YourKit is a Java profiler you attach to a Java process to collect and analyze runtime statistics. Once attached, you can create a performance snapshot: an aggregation of stack traces from every Java thread from multiple points in time. YourKit provides multiple ways to visualize a performance snapshot, including a hot spot view that shows which methods consumed the most time. Since our web app on JRE 8 consumed a lot more CPU than on JRE 7, I expected the respective hot spot views to differ.

The views were about the same, presumably because I still hadn’t put the systems under enough load in QA.

Taking performance profiles in production

At this point, I could have invested more time trying to reproduce the problem in QA, but instead I decided to use YourKit in production. We took performance snapshots in production with both JRE 7 and JRE 8. The only significant difference between the two was that the JRE 8 configuration seemed to use a lot more CPU. In fact, it used much more CPU than the performance snapshot could account for. It was as if the application was busy doing something in the background that YourKit couldn’t measure. We then decided to try profiling with the perf command.

Using the perf command

A Java process is more than a collection of Java code; it’s also a JVM composed of multi-threaded C++. A Java profiler can’t measure what that C++ code does; for that, you need a different kind of profiler, like the Linux perf command.

The perf command can collect call stacks from a Linux process. It uses the process’s debug symbol table to map a call stack’s addresses from virtual addresses to symbolic names of functions and methods. The JVM binary doesn’t contain a debug symbol table for your Java code, but there’s a way to query a Java process for its Java debug symbol table, too.

In production, we configured perf to capture the call stack for every web app thread every ~10ms for 30 seconds. That yielded about 11,000 call stacks. I aggregated the data into a flame graph (Figure 3).

In the flame graph, the y axis is stack depth. Any box at the top represents code that was on CPU when a sample was taken. The box below it is its caller, and so on. The flame graph in Figure 3 is really tall because our call stacks are deep. The x axis is just an alphabetical sort. The wider the box, the more call stacks it appears in. Green boxes are Java code, yellow is C++ code in the JVM, and red is C code in the JVM. Lightness and saturation are chosen for contrast and have no special meaning.

figure-3-first-flame-graph

Figure 3. Flame graph showing job search call stacks

Figure 4 shows the bottom portion of the flame graph:

figure-4-zoomed-first-flame-graph

Figure 4. Flame graph zoomed view

The CompileBroker::compiler_thread_loop (left, in yellow area) appears in 39% of call stacks. That is the bytecode compiler, the part of the JVM that converts frequently used bytecode into machine instructions. The value 39% seemed like a lot, and it represented something in the background that we couldn’t measure with YourKit.

Why would it consume so much time? The bytecode compiler writes its machine code to a dedicated area of memory called the codecache, which has a configurable size. There are JVM settings to configure what happens when the codecache fills up, but by default, the JVM is supposed to make room by flushing older entries. YourKit showed that our codecache was close to full, so it seemed worthwhile to try increasing the maximum size.

Doubling the codecache

We doubled the codecache size in production from 64MB to 128MB, restarted the web app, and let it run over the weekend. The application behaved normally and the system load stayed at a normal level. We ran the perf command and flame-graphed the results (Figure 5).

figure-5-zoomed-second-flame-graph-128m-codecache

Figure 5. Flame graph zoomed view after doubling the codecache

The width of the CompileBroker::compiler_thread_loop box (right) shows that the HotSpot compiler was less busy than before: about 20% of call stacks vs. about 40% before.

Codecache fluctuation

Even with a 128MB codecache, we eventually ran into trouble. Figure 6 shows what happened. The flat blue line is the maximum codecache size, and the purple curve below it is the amount of codecache used. At about 8am, the usage curve began to fluctuate and didn’t stabilize again until about 3am the next day.

figure-6-datadog-codecache-fluctuation

Figure 6. Codecache graph from Datadog showing fluctuation

The codecache churn slowed response times. Figure 7 shows the median response times for every job search server in that data center. The outlier in orange is the JRE 8 server. It’s about 50% worse than the rest.

figure-7-median-response-times-128m-codecache

Figure 7. Job search web app median response times

The right size for our web app

Our new codecache size of 128MB was still only half of the Java 8 default. To try to address the performance problem, we decided to double the size again to 256MB. We hoped our codecache usage would level off below this size. If 256MB still wasn’t enough, we could try doubling once more. If that didn’t work, we would experiment with JVM optimizer settings to reduce the codecache usage.

One factor in our favor was our deployment schedule. We usually redeploy this web app at least once a week and often multiple times per week. Aside from the Christmas holidays, we never go two weeks without redeploying. We decided to configure a total of 8 instances with a 256MB codecache and let them run for at least a week. We didn’t detect any problems, so we declared it a success.

Why more codecache?

The default codecache size for JRE 8 is about 250MB, about five times larger than the 48MB default for JRE 7. Our experience is that JRE 8 needs that extra codecache. We have switched about ten services to JRE 8 so far, and all of them use about four times more codecache than before.

One big contributor to the 4x multiplier is tiered compilation. The JVM has two bytecode compilers: C1, optimized for fast startup, and C2, optimized for throughput of long-running processes. In earlier Java versions, C1 and C2 were mutually exclusive; you chose C1 with the ‑client switch or C2 with the ‑server switch. Java 7 introduced tiered compilation, which runs C1 at startup and then switches to C2 for the remainder of the process. Tiered compilation is intended to boost startup times for long-running server processes and, according to Oracle, can yield better long-term throughput than C2 alone. In Java 7 you have to explicitly enable it, but in Java 8 it is on by default. In QA, when I disabled tiered compilation on JRE 8, the codecache size dropped by 50%.

Java 8 also uses more codecache because it optimizes more aggressively than Java 7 does. For example, the InlineSmallCode option controls how short a previous compiled method needs to be in order to be inlined. Java 8 raised the default from 1000 to 2000, which means the Java 8 optimizer allows longer methods to be inlined than before. If you inline more methods, and the inlined methods are bigger, you need more codecache.

Do developers migrating to Java 8 need to worry about this?

If you don’t override the default codecache size and have 100MB per JVM to spare, you can probably ignore the codecache increase. Most Indeed services do not override the default codecache size. They will use more codecache on Java 8 than on Java 7, but the codecache is still a lot smaller than our average heap size.

If you do override the default codecache size but are not memory-constrained, it will probably suffice to remove the override. I recommend monitoring your codecache size just to be safe. This Github project includes an example that shows how to upload JMX codecache statistics to Datadog.

If you are already memory-constrained, you may want to measure how disabling tiered compilation affects your startup time, long-term performance, and memory consumption.


Acknowledgments

Connor Kelly and Mike Salsone in our Operations team supported this project, patiently putting up with lots of unusual requests.

Indeed software engineers David Wahler and Chen Yang helped me interpret the YourKit profiles. David also suggested using the perf command and helped me interpret the flame graphs.

References

Brendan Gregg is a Netflix engineer who specializes in performance measurement. His website is full of performance-related articles, and his talks on YouTube are worth watching. Brendan popularized using flame graphs for visualizing performance data. He also contributed JVM changes that made it possible to view Java symbols in perf data.

When I first learned about codecache, I checked the Oracle documentation for conceptual material and relevant JVM settings:

Tweet about this on TwitterShare on FacebookShare on LinkedInShare on Google+Share on RedditEmail this to someone