[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.

alt text

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.

alt text

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

alt text

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

Expectations

What I excpect from application with biased lock disabled:

State before tuning - peak usage

Data from peak usage from 1 day and 4 nodes:

alt text

alt text

alt text

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:

alt text

alt text

alt text

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

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.