Image by USMC Archives
; license: CC
The other day I had to analyze search latency spikes in Elasticsearch for a customer. When latency spikes are involved, one of the first things I want to know is the "noiseness" of the host where the problem occurs.
A great tool that helps with this analysis is Gil Tene's jHiccup. It records hiccups in the application and also in a control process. One thing that bugged me about jHiccup for a long time is that you need to Microsoft Excel to visualize the data. However, I don't own an MS Office license and as much as I like jHiccup, I won't buy a license just for that.
So I thought about alternatives. At Elastic, we store our benchmark results also in Elasticsearch and visualize the data in Kibana. As I wanted to analyze multiple data sources anyway, it made sense to import the data into Elasticsearch. jHiccup comes with a tool, called jHiccupLogProcessor that can convert jHiccup files to CSV. After a few unsatisfying experiences with a few CSV to JSON converters, I hacked together a small Python script that can convert just jHiccup's CSV file format to Elasticsearch bulk requests and imported the file with curl.
This approach worked but is also cumbersome. Apart from that I figured other people might benefit from an import tool to Elasticsearch too. So I spiced up the script a little bit and the result is hiccup2es. Although it is really basic, it is a start and allows you to import data into Elasticsearch in one step. It even creates the index for you.
It is quite easy to use (I hope). Suppose you have a CSV jHiccup log called "hiccuplog.csv" that has been created by jHiccupLogProcessor. Then you can import the data into your local Elasticsearch cluster in one step:
python3 hiccup2es.py --input-file=hiccuplog.csv --create-index
That's it! hiccup2es assumes a lot of defaults, so if you want to know what you can configure, run hiccup2es --help to find out.
After the data are imported, you can easily create a nice looking visualization in Kibana. Here is a hiccup log during a benchmark I ran on my local machine:
I hope you find hiccup2es as useful as I do. If you want to know more, just contact me on Twitter. If you find a problem or can think of any enhancement, just raise an issue on Github.
jcmd is one of those neat tools that only a few people seem to know about. It is a command line tool that is shipped with each Oracle JDK installation and provides basic information about a running Java process, which is practical for unobtrusively inspecting a running production instance.
How to Use jcmd
To use jcmd we need to specify the process id of a running Java process. When jcmd is invoked without any arguments, it prints a list of all running Java processes:
daniel@thebe:~ $ jcmd
10322 name.mitterdorfer.demos.jcmd.Main
10307 org.gradle.launcher.GradleMain run
10325 sun.tools.jcmd.JCmd
Next, we can list the available commands for a process by issuing jcmd <<PID>> help:
daniel@thebe:~ $ jcmd 10322 help
10322:
The following commands are available:
JFR.stop
JFR.start
JFR.dump
JFR.check
VM.native_memory
VM.check_commercial_features
VM.unlock_commercial_features
ManagementAgent.stop
ManagementAgent.start_local
ManagementAgent.start
Thread.print
GC.class_stats
GC.class_histogram
GC.heap_dump
GC.run_finalization
GC.run
VM.uptime
VM.flags
VM.system_properties
VM.command_line
VM.version
help
For more information about a specific command use 'help '.
The supported options vary from process to process (e.g. due to VM options). For this example, there are four categories of commands:
- JFR: These are commands that control Java Flight Recorder which is really great for monitoring an application and deserves its own post (or even a series of posts). Note that while you are allowed to use Java Flight Recorder during development you need to obtain a separate license from Oracle to use it on production systems 1.
- VM: Basic information about the running JVM instance
- GC: Basic information about GC behavior and commands to force a GC or finalization
- Others: help, options to control the Java management agent and taking thread dumps
There is also one option that is not listed here, called "PerfCounter.print". It prints JVM-internal performance counters which contain lots of details on the behavior of components like the classloader, the JIT, the GC and a few others. To get started, the commands listed above should do but if you are really curios just try it.
A Practical Example
Suppose an application takes ages to start on a production system although it worked fine in development. To determine what's going on, we can take a thread dump:
daniel@thebe:~ $ jcmd 10378 Thread.print
10378:
2015-04-20 11:21:04
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.0-b70 mixed mode):
"Attach Listener" #10 daemon prio=9 os_prio=31 tid=0x00007fa7ef008000 nid=0x5b03 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
[...]
"main" #1 prio=5 os_prio=31 tid=0x00007fa7ee800000 nid=0x1903 waiting on condition [0x0000000102dbf000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at name.mitterdorfer.demos.jcmd.Main.main(Main.java:8)
"VM Thread" os_prio=31 tid=0x00007fa7ec857800 nid=0x3503 runnable
"GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007fa7ee80d000 nid=0x2503 runnable
[...]
"GC task thread#7 (ParallelGC)" os_prio=31 tid=0x00007fa7ec80b800 nid=0x3303 runnable
"VM Periodic Task Thread" os_prio=31 tid=0x00007fa7ed801800 nid=0x5903 waiting on condition
JNI global references: 7
Can you see what's going on? The main thread is in TIMED_WAITING state which means it is sleeping. Although this is not a very realistic example, such a thread dump once helped me find a weird startup issue in production: The logging framework of an application was misconfigured to log everything on DEBUG level but without specifying one of our application's file appenders. Therefore, no log statement ever reached the application's log files but it seemed that the application was not doing anything for minutes. I took a few thread dumps which revealed the problem quickly: Most thread dumps revealed that a debug statement was issued deep in library code. We corrected the log configuration and the application started smoothly again.
Summary
jcmd supports basic inspections in limited environments such as a production machine. Sure, there are more sophisticated tools like jconsole, Java Mission Control or third-party tools like AppDynamics. However, for a quick glimpse jcmd is quite handy as it comes with every JDK installation and requires no graphical interface.
Image by Juan Antonio Capó Alonso; license: CC
InterruptedException is among the most misunderstood exceptions in the JDK. How often did we come across exception handlers like this one:
public void enqueue(Object value) {
try {
queue.put(value);
} catch (InterruptedException e) {
// ignore
}
}
Or even:
public void enqueue(Object value) {
try {
queue.put(value);
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
}
In most cases, these handler implementations are wrong.
Stopping a Thread in Java
To understand why these exception handlers are wrong, we have to know the purpose of this exception. As its name indicates, some method has been interrupted during execution. In Java, cancellation of a running thread is cooperative. That means that we cannot force a thread to terminate from the outside 1 but instead we can just request that it interrupts itself and rely that the code executed within a thread will notice the request and act accordingly. To achieve that, each thread manages a flag, the interruption status. It can be set with Thread#interrupt() and reset with Thread#interrupted(). Additionally, Thread#isInterrupted() is used to check the interruption status.
Let's suppose a user wants to cancel a background operation running in a dedicated thread. To do so, client code calls interrupt() on this thread. Assuming that the background operation is in progress, i.e. it has been started but it has not yet finished, the thread can be in one of those states:2
- RUNNABLE: That means code is currently being executed or the corresponding thread is at least eligible for scheduling.
- BLOCKED, WAITING or TIMED_WAITING: Loosely speaking, the thread does not make any progress, because it is waiting on some event to occur like acquisition of a monitor or a timeout.
If the thread is in RUNNABLE state, it is rather simple to respond properly to interruption. We can periodically check the status of the interrupted flag with Thread#isInterrupted():
class ComplicatedCalculator implements Runnable {
@Override
public void run() {
while (!Thread.currentThread.isInterrupted()) {
// calculate something here
}
}
}
ComplicatedCalculator periodically checks the interruption status of the thread it is currently running in by calling Thread.currentThread.isInterrupted(). This ensures that the corresponding thread can terminate timely upon a request to interrupt itself.
However, what shall we do if the code is not in the state RUNNABLE, i.e. in one of the states BLOCKED, WAITING or TIMED_WAITING? Consider this simulation that recalculates its state roughly every second. There is InterruptedException again:
class Simulation implements Runnable {
@Override
public void run() {
while (!Thread.currentThread.isInterrupted()) {
// ... simulation calculations here ...
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
// empty
}
}
}
}
To understand what's wrong here, consider you are the implementor of Thread#sleep(). How should you indicate that the method did not return normally but has been interrupted? You could use a special return code, but this is brittle because it places the burden of checking the return value on the caller. Instead, Thread#sleep() resets the thread's interrupt status and throws InterruptedException. This means, whenever InterruptedException is thrown, some part of the system requested to terminate the current thread while it was not in RUNNABLE state, and we should get out of the way as quickly as possible.
In general, there are multiple strategies on how to handle InterruptedException:
- Rethrow: Classes which implement blocking operations like
BlockingQueue can just rethrow InterruptedException.
- Catch, restore and terminate: Classes that implement an existing interface like
Runnable cannot rethrow InterruptedException as it is a checked exception and needs to be included in the method signature. So they need another means to communicate interruption to code higher up the call stack. It should catch InterruptedException, restore the interruption status and terminate as soon as possible.
- Catch and terminate: This is a variation of the strategy above. Subclasses of
Thread do not need to restore the interruption flag as they are already at the top of the call stack and there is no one else that cares about the interruption status.
There are cases which justify other strategies, but for the majority of situations, these three strategies work fine.
Canonical Solution
To conclude the simulation example, support for interruption can be implemented using the "catch, restore and terminate" strategy as follows:
class Simulation implements Runnable {
@Override
public void run() {
while (!Thread.currentThread.isInterrupted()) {
// ... simulation calculations here ...
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
// restore interruption status of the corresponding thread
Thread.currentThread.interrupt();
}
}
}
}
The run loop will terminate quickly when the corresponding thread is interrupted either in Thread#sleep() or immediately after calculation hence guaranteeing timely termination of the corresponding thread. By the way: If the simulation would have contained just an empty catch block, it is almost impossible to ever interrupt it. As Thread#sleep() will reset the interruption status flag when it throws InterruptedException, the check at the beginning of the loop will hardly ever have a chance to observe that the interruption status flag is set.
Cancellation in Thread Pools
Java 5 has brought us ExecutorService, which means that client code does not have a Thread reference to call interrupt() on it. Instead, ExcecutorService#submit(Runnable) returns a Future. To request interruption, just invoke Future#cancel(true). Here's a minimalistic example:
Simulation simulation = new Simulation();
ExecutorService e = Executors.newFixedThreadPool(4);
Future<?> f = e.submit(simulation);
// ...
// now cancel the running simulation
f.cancel(true);
This is not the only situation where interruption occurs in a thread pool: ExecutorService#shutdownNow() will terminate all running tasks by calling Thread#interrupt() internally on pool threads. So proper handling of InterruptedException is also important to shutdown a thread pool properly.
This is the fifth and last post in a series about microbenchmarking on the JVM with the Java Microbenchmarking Harness (JMH). In the previous post, I have introduced JMH with a Hello World benchmark. Now, let's dig a bit deeper to find out more about the capabilities of JMH.
A Date Format Benchmark
In this blog post, we'll implement a microbenchmark that compares the multithreaded performance of different date formatting approaches in Java. In this microbenchmark, we can exercise more features of JMH than just in a Hello World example. There are three contenders:
- JDK
SimpleDateFormat wrapped in a synchronized block: As SimpleDateFormat is not thread-safe, we have to guard access to it using a synchronized block.
- Thread-confined JDK
SimpleDateFormat: One alternative to a global lock is to use one instance per thread. We'd expect this alternative to scale much better than the first alternative, as there is no contention.
FastDateFormat from Apache Commons Lang: This class is a drop-in replacement for SimpleDateFormat (see also its Javadoc)
To measure how these three implementations behave when formatting a date in a multithreaded environment, they will be tested with one, two, four and eight benchmark threads. The key metric that should be reported is the time that is needed per invocation of the format method.
Phew, that's quite a bit to chew on. So let's tackle the challenge step by step.
Choosing the Metric
Let's start with the metric that we want to determine. JMH defines the output metric in the enum Mode. As the Javadoc of Mode is already quite detailed, I won't duplicate the information here. After we've looked at the options, we choose Mode.AverageTime as benchmark mode. We can specify the benchmark mode on the benchmark class using @BenchmarkMode(Mode.AverageTime). Additionally, we want the output time unit to be µs.
import org.openjdk.jmh.annotations.*;
import java.util.concurrent.TimeUnit;
@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.MICROSECONDS)
public class DateFormatMicroBenchmark {
// more code to come...
}
When the microbenchmark is run, results will be reported as µs/op, i.e. how many µs one invocation of the benchmark method took. Let's move on.
Defining Microbenchmark Candidates
Next, we need to define the three microbenchmark candidates. We need to keep the three implementations around during a benchmark run. That's what @State is for in JMH. We also define the scope here; in our case either Scope.Benchmark, i.e. one instance for the whole benchmark and Scope.Thread, i.e. one instance per benchmark thread. The benchmark class now looks as follows:
import org.apache.commons.lang3.time.FastDateFormat;
import org.openjdk.jmh.annotations.*;
import java.text.DateFormat;
import java.text.Format;
import java.util.Date;
import java.util.concurrent.TimeUnit;
@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.MICROSECONDS)
public class DateFormatMicroBenchmark {
// This is the date that will be formatted in the benchmark methods
@State(Scope.Benchmark)
public static class DateToFormat {
final Date date = new Date();
}
// These are the three benchmark candidates
@State(Scope.Thread)
public static class JdkDateFormatHolder {
final Format format = DateFormat.getDateInstance(DateFormat.MEDIUM);
public String format(Date d) {
return format.format(d);
}
}
@State(Scope.Benchmark)
public static class SyncJdkDateFormatHolder {
final Format format = DateFormat.getDateInstance(DateFormat.MEDIUM);
public synchronized String format(Date d) {
return format.format(d);
}
}
@State(Scope.Benchmark)
public static class CommonsDateFormatHolder {
final Format format = FastDateFormat.getDateInstance(FastDateFormat.MEDIUM);
public String format(Date d) {
return format.format(d);
}
}
}
We defined holder classes for each Format implementation. That's needed, as we need a place to put the @State annotation. Later on, we can have JMH inject instances of these classes to benchmark methods. Additionally, JMH will ensure that instances have a proper scope. Note that SyncJdkDateFormatHolder achieves thread-safety by defining #format() as synchronized. Now we're almost there; only the actual benchmark code is missing.
Multithreaded Benchmarking
The actual benchmark code is dead-simple. Here is one example:
@Benchmark
public String measureJdkFormat_1(JdkDateFormatHolder df, DateToFormat date) {
return df.format(date.date);
}
Two things are noteworthy: First, JMH figures out that we need an instance of JdkDateFormatHolder and DateToFormat and injects a properly scoped instance. Second, the method needs to return the result in order to avoid dead-code elimination.
As we did not specify anything, the method will run single-threaded. So let's add the last missing piece:
@Benchmark
@Threads(2)
public String measureJdkFormat_2(JdkDateFormatHolder df, DateToFormat date) {
return df.format(date.date);
}
With @Threads we can specify the number of benchmark threads. The actual benchmark code contains methods for each microbenchmark candidate for one, two, four and eight threads. It's not particularly interesting to copy the whole benchmark code here, so just have a look at Github.
Running the Benchmark
This benchmark is included in benchmarking-experiments on Github. Just follow the installation instructions, and then issue java -jar build/libs/benchmarking-experiments-0.1.0-all.jar "name.mitterdorfer.benchmark.jmh.DateFormat.*".
Results
I've run the benchmark on my machine with an Intel Core i7-2635QM with 4 physical cores and Hyperthreading enabled. The results can be found below:
Unsurprisingly, the synchronized version of SimpleDateFormat does not scale very well, whereas the thread-confined version and FastDateFormat are much better.
There's (Much) More
DateFormatMicroBenchmark is a more realistic use case of a microbenchmark than what we have seen before in this article series. As you have seen in this example, JMH has a lot to offer: Support for different scopes for state, multithreaded benchmarking and customization of reported metrics.
Apart from these features, JMH provides a lot more such as support for asymmetric microbenchmarks (think readers and writers), control on the behavior of the benchmark (How many VM forks are created? Which output formats should be used for reporting? How many warm-up iterations should be run?), etc. etc.. It also supports arcane features such as the possibility to control the certain aspects of compiler behavior with the @CompilerControl annotation, a Control class that allows to get information about state transitions in microbenchmarks, support for profilers and many more. Just have a look at the examples yourself, or look for usages of JMH in the wild, such as JCTools microbenchmarks from Nitsan Wakart, the benchmark suite of the Reactor project or Chris Vest's XorShift microbenchmark.
Alternatives
There are also some alternatives to JMH, but for me none of them is currently as compelling as JMH:
- Handwritten benchmarks: In this posting series, I've demonstrated multiple times that without very intimate knowledge of JVM's inner workings, we almost certainly get it wrong. Cliff Click, who architected the HotSpot server compiler, put it this way:
Without exception every microbenchmark I've seen has had serious flaws [...] Except those I've had a hand in correcting.
- Caliper: An open-source Java microbenchmarking framework by Google. This seems to be the only "serious" alternative to JMH but still has its weaknesses.
- JUnitPerf: JUnitPerf is a JUnit extension for performance tests. It decorates unit tests with timers. Although you might consider it for writing microbenchmarks, it is not as suitable as other solutions. It does not provide support for warm-up, multithreaded testing, controlling the impact of JIT, etc.. However, if all you need is a coarse-grained measurement of the runtime of an integration test, then JUnitPerf might be for you. JUnitPerf can be one of your defense lines against system-level performance regressions, as you can easily integrate these tests in your automated build.
- Performance Testing classes by Heinz Kabutz: Heinz Kabutz wrote a set of performance testing classes in issue 124 of the The Java Specialists' Newsletter. I would not consider it a fully-fledged framework but a set of utility classes.
Final Thoughts
Although writing correct microbenchmarks on the JVM is really hard, JMH helps to avoid many issues. It is written by experts on the OpenJDK team and solves issues you might not even knew you may have had in a handwritten benchmark, e.g. false sharing. JMH makes it much easier to write correct microbenchmarks without requiring an intimate knowledge of the JVM at the level of an engineer on the HotSpot team. JMH's benefits are so compelling that you should never consider rolling your own handwritten microbenchmarks.
Questions or comments?
Just ping me on Twitter
I have recently stumbled across a nice idiom called the cheap read-write lock. It is intended for very frequent concurrent reads of a field where synchronization would lead to too much contention. I think that the idiom is a bit odd and begs for an explanation.
Usage Scenario
For the sake of demonstration consider the following situation: Our system has a globally available calendar that holds the current day within the year. Every part of the system may read the current day. Once a day, a background thread will update it. Note that this scenario might not justify using the idiom in practice, but the example is sufficient for illustrating it.
@NotThreadSafe
public final class SystemCalendar {
// may be a value between 0 and 364
private int currentDayOfYear;
public int getCurrentDayOfYear() {
return currentDayOfYear;
}
public void advanceToNextDay() {
// let's ignore leap years for this example...
this.currentDayOfYear = (this.currentDayOfYear + 1) % 365;
}
}
That's all nice and well, but this code is not thread safe. To demonstrate why, follow me on a short detour. The picture below illustrates what could happen to currentDayOfYear on a hypothetical and very simple multicore system. We assume that the updating thread always runs on CPU1 and reader threads run on CPU2. On initial access, the value of currentDayOfYear is read from main memory and cached on each CPU separately. The yellow circle indicates the currently known value of currentDayOfYear to any part of the system.
As you can see, the value has been updated on CPU1, but it has never been reconciled with main memory and thus never reached CPU2. How can this happen? Java 5 has brought us JSR 133, better known as the Java Memory Model, which defines a happens‑before order between memory accesses. I won't go into the details here, but we failed to establish a happens‑before order between writes and reads of currentDayOfYear, which allowed the runtime to cache its value in each processor separately. Let's fix it:
@ThreadSafe
public final class SystemCalendar {
private int currentDayOfYear;
public synchronized int getCurrentDayOfYear() {
return currentDayOfYear;
}
public synchronized void advanceToNextDay() {
this.currentDayOfYear = (this.currentDayOfYear + 1) % 365;
}
}
By marking both methods as synchronized, we have established a happens‑before order. Writes will now be flushed to main memory, and the value will be fetched from main memory before reads (This is not entirely correct and the reality is more complicated, but this mental model is sufficient for understanding the idiom. If you are interested in the details, have a look at the MESI protocol).
Problem solved? You bet! But let's suppose that there are thousands of concurrent readers of currentDayOfYear. As a result, #getCurrentDayOfYear() will suffer from heavy contention. Each reader has to obtain the monitor on SystemCalendar.this just to ensure it gets the most recent value of currentDayOfYear.
Removing the synchronization on #getCurrentDayOfYear() in this situation is fatal, as the class would not be thread safe anymore. JLS §17.4.4 states: "An unlock action on monitor m synchronizes‑with all subsequent lock actions on m [...]" (you can substitute synchronizes‑with with happens‑before for our purposes). The mentioned "subsequent lock action" we want is exactly the acquisition of the monitor lock by #getCurrentDayOfYear() after #advanceToNextDay() has been called. Only then, we have established a happens‑before order and are thus able to see the new value. Too bad: It seems we are stuck with the lock.
It turns out we can relax the constraint by declaring currentDayOfYear as volatile instead of marking #getCurrentDayOfYear() as synchronized. That's essentially the cheap read-write lock:
@ThreadSafe
public final class SystemCalendar {
private volatile int currentDayOfYear;
public int getCurrentDayOfYear() {
return currentDayOfYear;
}
public synchronized void advanceToNextDay() {
this.currentDayOfYear = (this.currentDayOfYear + 1) % 365;
}
}
Why does this work? Both synchronized and volatile establish a happens‑before order, but only synchronized guarantees that the guarded block is executed atomically. The setter performs multiple operations that have to be atomic, so synchronizing the method is the correct choice. However, the getter performs only one action, namely a read of the field, which is atomic (as per guarantee of the JLS). This allows us to use volatile instead of synchronized to establish a happens‑before order.
When to use the cheap read-write lock?
This idiom may be applied when reads far outweigh writes and synchronization would lead to too much contention. You should not just assume that there is a bottleneck but actually measure it before and after applying this idiom.
When to avoid the cheap read-write lock?
In short: almost always. In the original article, Brian Goetz warns firmly that you should not use this idiom lightly. First, you should empirically demonstrate that there is a performance problem and using the cheap read-write lock eliminates it. The code should be properly encapsulated and be documented very well. You must not use the cheap read-write lock if you deviate from the standard use case above. For example, the idiom is obviously insufficient if your getter consists of multiple statements.
Alternatives
The safer alternative in most similar situations that occur in practice will be ReadWriteLock, which is provided by the JDK since Java 5:
@ThreadSafe
public final class SystemCalendar {
private final ReadWriteLock lock = new ReentrantReadWriteLock();
private final Lock readLock = lock.readLock();
private final Lock writeLock = lock.writeLock();
private int currentDayOfYear;
public int getCurrentDayOfYear() {
readLock.lock();
try {
return currentDayOfYear;
} finally {
readLock.unlock();
}
}
public void advanceToNextDay() {
writeLock.lock();
// The try - finally block is not strictly necessary in this case
// but it is the common idiom when using locks. You almost always want to use it.
try {
this.currentDayOfYear = (this.currentDayOfYear + 1) % 365;
} finally {
writeLock.unlock();
}
}
}
Since Java 8 you can also use StampedLock.
Conclusion
With careful thought and a very good understanding of the runtime behavior of our system, we are able to relax the cost that may be introduced by synchronized access to highly contended code paths with a lot of reads. Which technique is sufficient to solve a performance problem is best demonstrated by intensively profiling your system in different usage scenarios. While the cheap read-write lock is certainly not something you'll pull out every day, it is a nice technique for your concurrency toolbox.
If you have any questions or comments just ping me on Twitter.