Biased lock wyłączone – znowu!
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.
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.
Jeśli wolimy dane liczbowe, można log przedstawić tabelarycznie:
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:
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:
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.
