This article describes selected JVM tuning issues using selected JVM flags. These treatments allowed to optimize the application described below - however, I do not guarantee that they will work in other applications. Do not use JVM flags if you do not know what effects they can lead to!
What is biased lock?
Extract from Oracle documentation:
What is biased lock
-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 status
The -XX:+UseBiasedLocking flag is enabled by default in JDK 8-14, but already in JDK 15 it is disabled and not recommended(JEP 374).
Why can this optimization be harmful?
In addition to the problem already mentioned in the documentation, ie:
(...) some applications with certain patterns of locking may see slowdowns (...)
another issue must be reckoned with. Canceling a biased lock is a safepoint operation whose execution requires a stop-the-world phase. This phase interrupts every thread in the application, which can be disadvantageous.
JVM logs
Unified logger allows safepoint operations to be tracked using Xlog:safepoint, but biased lock operation can also be tracked using 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
In this log you can see which objects had a biased lock, and how many stop-the-world steps it took to cancel the biased lock. This can be shown clearly in a pie chart. In the chart below, we see the percentage of safepoint operations.
The percentage itself is usually not important - but it is worth looking at the length of execution of a given step. From the safepoints log, you can also generate a pie chart for the execution times of each safepoint operation.
If we prefer numerical data, the log can be tabulated:
In the application in question, the appeal of biased lock requires:
(count(RevokeBias) + count(BulkRevokeBias)) / (totalCount)
Substituting the figures we get:
(254389 + 11815) / 367681 = 72%
72% of all stop-the-world phases. The execution time of these phases was as follows:
(totalTime(RevokeBias) + totalTime(BulkRevokeBias)) / (totalTimeOfSTW)
Substituting the figures we get:
(51419.93 + 24277.09) / 523393.73 = 14%
14% of the time for all stop-the-world phases (excluding time to safepoint).
Context: tuned application
- Oracle JDK 11u4
- SpringBoot with Tomcat embedded
- State web application
- Multiple instances (20) each on 4 virtual processors
- Heap size: 8GB
- Peak usage from 5:00 pm to 6:00 pm (Mon to Fri).
- There is almost no thread synchronization in the application - most threads are synchronized in the framework and JDK.
- About 200 Java threads are running between 5:00 and 6:00 pm.
Expectations
What I expect from an app with biased lock disabled:
- Approximately 72% fewer stop-the-world phases
- I expect that the user's working time in the application can be reduced by about 2%.
- By the way it can: less memory usage, because there is no bug JDK-8240723.
Pre-tuning condition: peak usage
Peak application usage data from day 1 for 4 nodes:
The biased lock cancellation requires 14% of all stop-the-world phases.
How does the application look from the user's perspective? The average peak request processing time is about 410 ms.
Tuning
Application tuning simply involves disabling a specific option with JVM arguments:
-XX:-UseBiasedLocking
Post-tuning status: peak usage
Peak application usage data from day 1 for 4 nodes:
How does the application look from the user's perspective? The average peak request processing time is about 397 ms. Comparing the worst results on nodes without biased lock with the best results from nodes with biased lock enabled shows that from the user's perspective, the tuned node worked 2% faster. The results were recorded over a period of 1 week.
Results
- Decrease in the number of stop-the-world phases by 71%.
- The time to perform stop-the-world phases was reduced by 10%.
- The user's work time in the application decreased by at least 2% (2-8%, 3% on average).
- The JVM process took up less RAM on machines with biased lock disabled.
Summary
This isthefifth application in which I have disabled the biased lock on JVM 11. In four cases, disabling the lock increased performance, while in one case performance decreased.
