More CPUs but less throughput?



Thread contentions can be tricky to find with basic monitoring, especially if your application reaches a maximum throughput but you don't receive an alert from your monitoring system.


Furthermore, you may face this problem only when deploying your application in production because concurrency problems are more visible on a multi-core system.


This is another good reason to always perform a benchmark campaign on the target architecture.





Thread contention symptoms



While your application is under a maximum load you can observe that:



  • Your application is not fully CPU bound. i.e. the percentage of time that the CPUs were idle is more than 10%

  • There are no obvious limitations (i.e: you can check that all of the following items are true):

    • the percent of CPU iowait is low.

    • the disk and network bandwidth usage is fine,

    • the throughput of the garbage collector is good

    • there are no database bottleneck

    • the datasources pool size is larger than the number of running threads




Although it may appear to be significant, in this situation, the number of context switches per second is not relevant.


It's possible that someone has put some Thread.sleep in the application.





Detecting the thread contention



The easiest way to see contentions is by using VisualVM when the application is under load and looking at the Threads tab. In the worst case you will see something like this:



Contention-threads
VisualVM threads timeline



The red line shows the threads that are either in a monitor region or waiting in an entry set for the monitor.


The monitor is the mechanism that Java uses to support synchronization. You can find more information about the monitor here.





Analyzing



Now click on the Thread Dumps button and look at the BLOCKED threads, you should find many BLOCKED threads waiting for the same locks:



Contention-thread-dump
VisualVM threads dump



In this case threads are locked on the StreamHandler.publish method:


StreamHandler.java:174   public synchronized void publish(LogRecord record) {


This syncrhonized instruction becomes a problem on high concurrency.





Automating thread contention detection



VisualVM is doing a great job here but what if you want to have a metric of the thread contention in your continuous integration benchmark job?


The JMX Threading MBean (java.lang:type=Threading) exposes thread contention statistics. First you need to enable it by setting the property ThreadContentionMonitoringEnabled to True. Then invoking the dumpAllThreads method of the same mbean will return a list of thread objects with the number of times that each thread has been blocked and the amount of time they were waiting in a monitor state.


After having a hard time getting jmxsh to do this for me, I started writing a command line tool that can work like iostat, vmstat or sar, something like a jmxstat. Thanks to the social coding, GitHub already owns a jmxstat project done by Jonathan Lee.


One fork later I got something like this:


$ jmxstat --help
Usage:
java -jar jmxstat.jar <host:port> [--peformGC] [--contention] [mbean.name[attribute.field], ...] [interval [count]]

$ jmxstat localhost:1089 --contention Catalina:type=ThreadPool,name=http-0.0.0.0-8080[currentThreadsBusy] 2
date currentThreadsBusy blockedCount blockedTimeMs
11:20:56 0 239762 81
...
11:25:28 10 491564 499889
...

The --contention option adds the blockedCount and blockedTimeMs columns. These are the sum of blocked count and time for all threads.


In addition jmxstat can trace any mbean attribute and performs a Full Garbage Collection without having to install an X server! Visit the GitHub page for more information about jmxstat.


Here is an example of contention monitoring during a benchmark with a rampup from one to ten threads generated from the jmxstat output 1



Contention-jmxoutput Blocked count and times chart



I wasn't able to measure the tool overhead on our benchmarks but of course it may depend on the tested application so it must be checked first.


This metric is now part of our daily bench monitoring report.





Footnotes:



For information about the Nuxeo Platform, please visit our product page or request a custom demo to see how we can help your organization.

1 This kind of chart can be easily generated using tcsv2png