[Java][JVM][Tuning][Profiling] Biased lock disabled, again

Big fat warning

This article shows some JVM tuning using some JVM flags. It helped with application described below, but it doesn’t mean, that it will help in your application. You should never use any JVM flags without knowing what consequences they may produce.

About biased lock

From Oracle documentation:

-XX:+UseBiasedLocking

Enables a technique for improving the performance of uncontended synchronization. An object is “biased” toward the thread which first acquires its monitor via a monitorenter bytecode or synchronized method invocation; subsequent monitor-related operations performed by that thread are relatively much faster on multiprocessor machines. Some applications with significant amounts of uncontended synchronization may attain significant speedups with this flag enabled; some applications with certain patterns of locking may see slowdowns, though attempts have been made to minimize the negative impact.

Current state

Currently flag -XX:+UseBiasedLocking is enabled by default in JDK 8-14, but it is disabled and deprecated in JDK 15 (JEP 374).

Why this optimization can hurt?

Besides the fact, that documentation mentions:

(…) some applications with certain patterns of locking may see slowdowns (…)

there is one more aspect to consider. Revoking biased lock is a safepoint operation, which means it needs a Stop-the-world phase to do its job. This phase stops every application thread, so this may hurt.

JVM logs

With unified logger we can trace safepoint operations with Xlog:safepoint, but also biased lock can be traced with Xlog:biasedlocking.

[safepoint        ] Application time: 0.1950250 seconds
[safepoint        ] Entering safepoint region: RevokeBias
[biasedlocking    ] Revoking bias with potentially per-thread safepoint:
[biasedlocking    ] Revoking bias of object 0x00000007efbe15d0, mark 0x00007fa06805d305, type org.springframework...<removed, sorry>, prototype header 0x0000000000000305, allow rebias 0, requesting thread 0x00007fa068064800
[biasedlocking    ]  Revoked bias of object biased toward live thread (0x00007fa06805d000)
[biasedlocking    ]  Revoked bias of currently-unlocked object
[safepoint        ] Leaving safepoint region
[safepoint        ] Total time for which application threads were stopped: 0.0003424 seconds, Stopping threads took: 0.0000491 seconds

From that log we can understand what objects had biased lock, and how many STW phases were done just to revoke biased lock.

This can be nicely presented on pie chart. Following chart shows %count of safepoint operation type.

Usually %count is not what is really interesting, we need to look at time spent in those phases. Fortunately, from safepoints log we can also create pie chart that shows time wasted by each safepoint operation.

For those who prefer numbers we can also see this information in table:

So in this application revoking biased lock needs:

(count(RevokeBias) + count(BulkRevokeBias)) / (totalCount)

substituting with numbers (in blue frames on table) we have :

(254389 + 11815) / 367681 = 72%

72% of all STW phases. Time spent in those phases was:

(totalTime(RevokeBias) + totalTime(BulkRevokeBias)) / (totalTimeOfSTW)

substituting with numbers (in red frames on table) we have:

(51419.93 + 24277.09) / 523393.73 = 14%

14% of all STW phases time (without time to safepoint).

Context - tuned application

• JDK 11u4 by Oracle
• SpringBoot with embedded Tomcat
• Stateful web application
• Multiple instances (20) with 4 vCPU
• Heap size 8GB
• Peak usage between 17:00 and 18:00 (Monday-Friday)
• There is almost no thread synchronization in application, most of thread synchronization is done in frameworks and JDK.
• Around 200 Java threads are running between 17:00 and 18:00

Expectations

What I excpect from application with biased lock disabled:

• ~72% less STW phases
• I expect that time spent by user in application may drop by ~2%
• nice to have - less memory consumption, since bug JDK-8240723 will not be involved

State before tuning - peak usage

Data from peak usage from 1 day and 4 nodes:

Revoking biased lock costs 14% of all STW phases.

From user perspective: AVG time of processing requests in peak is ~410ms.

Tuning

Tuning is done simply by disabling one option through JVM arguments:

-XX:-UseBiasedLocking

State after tuning - peak usage

Data from peak usage from 1 day and 4 nodes:

From user perspective: AVG time of processing requests in peak is ~397ms. Comparing worst result from nodes without biased lock to best result from nodes with biased lock, the node without it was 2% faster from user perspective. Results were gathered for 1 week.

Results

• Count of STW phases was reduced by 71%
• Time spent in STW phases was reduced by 10%
• User time in application was reduced by at least 2% (2-8% with average 3%)
• Memory footprint of JVM process was lower on machines without biased lock

Final words

This is fifth application where I disabled biased lock on JVM 11. Four times it helped, one time it has degraded the performance.