W niniejszym artykule opisano wybrane zagadnienia tuningu JVM za pomocą wybranych flag JVM. Zabiegi te pozwoliły zoptymalizować opisaną poniżej aplikację – nie gwarantuję jednak, że sprawdzą się w innych aplikacjach. Nie używaj flag JVM jeśli nie wiesz, do jakich skutków mogą doprowadzić!
Czym jest biased lock?
Wyciąg z dokumentacji Oracle:
Czym jest 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.
Stan obecny
Flaga -XX:+UseBiasedLocking jest domyślnie włączona w JDK 8-14, lecz już w JDK 15 jest wyłączona i niezalecana (JEP 374).
Dlaczego taka optymalizacja może być szkodliwa?
Poza wspomnianym już w dokumentacji problemem tj.:
(...) some applications with certain patterns of locking may see slowdowns (...)
należy liczyć się z jeszcze inną kwestią. Odwołanie biased lock jest operacją safepoint, której wykonanie wymaga fazy stop-the-world. Faza ta przerywa pracę każdego wątku aplikacji, co może być niekorzystne.
Logi JVM
Zunifikowany logger umożliwia śledzenie operacji safepoint za pomocą Xlog:safepoint, lecz pracę biased lock można śledzić również za pomocą 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
W logu tym można sprawdzić, które obiekty miały blokadę biased lock, oraz ile etapów stop-the-world trzeba było wykonać, aby odwołać biased lock. Można to przedstawić wyraźnie na wykresie kołowym. Na poniższym wykresie widzimy odsetek operacji safepoint.
![](https://assets-global.website-files.com/611f85497dc1fc2d6579757e/61697e71420dad5d385e624f_wykres_1-1024x683.jpeg)
Sam odsetek nie jest zwykle istotny – warto natomiast przyjrzeć się długości wykonywania danego etapu. Na podstawie logu safepoints można również wygenerować wykres kołowy dla czasów wykonywania każdej operacji safepoint.
![](https://assets-global.website-files.com/611f85497dc1fc2d6579757e/61697e716fd1ae4fdb73e580_wykres_2-1024x683.jpeg)
Jeśli wolimy dane liczbowe, można log przedstawić tabelarycznie:
![](https://assets-global.website-files.com/611f85497dc1fc2d6579757e/61697e710f41435139ee7e36_tabela_1.png)
W omawianej aplikacji odwołanie biased lock wymaga:
(count(RevokeBias) + count(BulkRevokeBias)) / (totalCount)
podstawiając dane liczbowe otrzymujemy:
(254389 + 11815) / 367681 = 72%
72% ze wszystkich faz stop-the-world. Czas wykonania tych faz był następujący:
(totalTime(RevokeBias) + totalTime(BulkRevokeBias)) / (totalTimeOfSTW)
podstawiając dane liczbowe otrzymujemy:
(51419.93 + 24277.09) / 523393.73 = 14%
14% czasu dla wszystkich faz stop-the-world (bez time to safepoint).
Kontekst: aplikacja dostrojona
- JDK 11u4 Oracle
- SpringBoot z wbudowanym Tomcat
- Stanowa aplikacja webowa
- Wiele instancji (20) każda na 4 procesorach wirtualnych
- Rozmiar heap: 8GB
- Szczytowe wykorzystanie w godz. 17:00-18:00 (od pon. do pt.)
- W aplikacji niemal w ogóle nie ma synchronizacji wątków – większość wątków synchronizowana jest we frameworkach i JDK.
- W godzinach 17:00-18:00 pracuje ok. 200 wątków Java.
Oczekiwania
Czego spodziewam się po aplikacji z wyłączoną biased lock:
- Ok. 72% mniej faz stop-the-world
- Oczekuję, że czas pracy użytkownika w aplikacji może skrócić się o ok. 2%.
- Przy okazji może: mniejsze zużycie pamięci, ponieważ nie występuje bug JDK-8240723.
Stan przed dostrojeniem: szczytowe wykorzystanie
Dane ze szczytowego użycia aplikacji z 1 dnia dla 4 węzłów:
![](https://assets-global.website-files.com/611f85497dc1fc2d6579757e/61697e71335ab4312e5d411c_wykres_3-1024x683.jpeg)
![](https://assets-global.website-files.com/611f85497dc1fc2d6579757e/61697e712811573808cf2f8d_wykres_4-1024x683.jpeg)
![](https://assets-global.website-files.com/611f85497dc1fc2d6579757e/61697e7128115709a7cf2f8e_tabela_2.png)
Odwołanie biased lock wymaga 14% wszystkich faz stop-the-world.
Jak aplikacja wygląda z perspektywy użytkownika? Średni czas przetwarzania żądań w szczycie wynosi ok. 410 ms.
Dostrajanie
Dostrojenie aplikacji polega po prostu na wyłączeniu konkretnej opcji za pomocą argumentów JVM:
-XX:-UseBiasedLocking
Stan po dostrojeniu: szczytowe wykorzystanie
Dane ze szczytowego użycia aplikacji z 1 dnia dla 4 węzłów:
![](https://assets-global.website-files.com/611f85497dc1fc2d6579757e/61697e728bfa97aebb781eae_wykres_5-1024x683.jpeg)
![](https://assets-global.website-files.com/611f85497dc1fc2d6579757e/61697e7248019cdf4c546b47_wykres_6-1024x683.jpeg)
![](https://assets-global.website-files.com/611f85497dc1fc2d6579757e/61697e723991e168824a4059_tabela_3.png)
Jak aplikacja wygląda z perspektywy użytkownika? Średni czas przetwarzania żądań w szczycie wynosi ok. 397 ms. W porównaniu najgorszych wyników na węzłach bez biased lock z najlepszymi wynikami z węzłów z włączoną biased lock wynika, że z perspektywy użytkownika węzeł po tuningu pracował o 2% szybciej. Wyniki rejestrowano w okresie 1 tygodnia.
Wyniki
- Spadek liczby faz stop-the-world o 71%.
- Czas wykonywania faz stop-the-world skrócił się o 10%.
- Czas pracy użytkownika w aplikacji skrócił się przynajmniej o 2% (2-8%, średnio o 3%).
- Proces JVM zajął mniej pamięci operacyjnej na maszynach z wyłączoną biased lock.
Podsumowanie
Jest to piąta aplikacja, w której wyłączyłem biased lock na JVM 11. W czterech przypadkach wyłączenie blokady zwiększyło wydajność, w jednym przypadku zaś wydajność spadła.