Java Profiler jak to działa?

W życiu każdego człowieka który programuje (zwiemy ich programistami i programistkami) nadchodzi taki dzień, że trzeba coś przyspieszyć, bo coś wolno działa i nie do końca wiadomo dlaczego.
Wtedy wzrok takiego kogoś pada na profiler.
Który to profiler obiecuje, że wskaże nam miejsca gdzie nasz kod spędza najwięcej czasu.

Oczywiście zwykle wyniki z profilera nie są tym czego byśmy oczekiwali ;-) bo my byśmy chcieli jasnej informacji, że problem jest w danej linii, a zamiast tego dostajemy informację, że 90% czasu spędzono w metodzie doSth() ;-)

Ale nie o tym tutaj, a o czymś innym.
Zastanawialiście się kiedyś jak działa profiler? :-)

Ja zawsze myślałem, że używa jakichś sprytnych mechanizmów JVM, które mówią ile czasu trwało wykonanie danej metody i że tak naprawdę profiler robi tylko za interfejs do JVM.
Albo, że profiler modyfikuje kod i dodaje swój bytecode do mierzenia czasu...

W tym drugim miałem nawet trochę racji ;-)

A jak jest naprawdę? ;-)

Okazuje się, że profiler zwykle wcale nie wie ile czasu spędzono w metodzie czy metodach, ale używa sprytnej sztuczki by ten czas estymować.

Wiemy, że w Java'ie mamy wątki zwane też Thread'ami.
Mamy też Stack Trace, w którym każda ramka opisuje "linię" kodu w której jest JVM w danej metodzie. Ze Stack Trace'a możemy dowiedzieć się która metoda woła którą.
Zwykle Stack Trace'a widzimy w momencie gdy leci jakiś wyjątek i Stack Trace pozwala nam wyśledzić to miejsce.

Mamy też coś takiego jak Thread Dump, czyli zrzut stanu w postaci StackTrace + stan aktywności dla każdego z wątków.

I właśnie Thread Dump jest kluczowym elementem działania Profilerów ;-)

Profiler "po prostu" prosi z zadanym interwałem JVM o Thread Dump'y i zapisuje je sobie.
Dzięki temu dostaje "historię" tego gdzie dany wątek był w zadanym czasie.

Profiler używając Thread Dump'a próbkuje stan JVM i dzięki tym próbką może pokazać nam gorące fragmenty kodu, w których spędzamy najwięcej czasu*.

Ponieważ Thread Dump jest dość ciężką operacją to w trakcie profilowania prędkość całej aplikacji nam maleje, ale oznacza to też, że istnieje pewna "graniczna" częstotliwość próbkowania, a więc i to, że dokładność/rozdzielczość profilera jest ograniczona.
Stąd profiler może gubić pewne bardzo krótkie metody, albo mocno niedoszacowywać ilość ich wywołań. Co zwykle nie powinno być problemem, bo jeśli robimy 100 zrzutów na sekundę, a metodę wołamy milion razy i ani razu z wciągu tych 100 zrzutów nie byliśmy w tej metodzie to raczej nie ona stanowi nasz problem (ten fragment jest bardziej pisany w oparciu o intuicję niż fakty).

Tu istnieje teoretyczna metoda na poprawienie rozdzielczości, choć szczerze nie wiem czy jest stosowana (tzn. wiem, że jest stosowana np. w AppDynamics, więc pewnie DynaTrace i podobne narzędzia do monitorowania aplikacji też to mogą zrobić, ale w AppDynamics to jest robione "ręcznie" i raczej jest pomyślane jako mechanizm do zbierania metryk biznesowych czy technicznych z aplikacji, a nie metoda na profilowanie per se).
Otóż JVM pozwala na dodanie agenta, który w trakcie ładowania klas może dodać do tych klas swój kod. Jednym ze sposobów jest dodanie kodu na początku i na końcu metody. Ten kod może np. zapisywać informacje o czasie wykonania metody, albo o ilości wykonań metody.
Oczywiście technika ta ma też swoje wady. Bo trudno powiedzieć wtedy jaki procent czasu wykonania danej metody to wykonanie samej metody, a jaki to czas wykonania kodu mierzącego czas i zbierającego statystyki ;-)

Przyznam, że gdy w końcu dowiedziałem się jak działają profilery to trochę spadła mi wiara w ich skuteczność ;-) Nadal są świetnymi narzędziami, ale jednak nie magicznymi.
Wydaje mi się jednak, że teraz jakoś lepiej umiem korzystać z ich wyników.

A i jak potrzebujecie w normalnym życiu programisty czy programistki zajrzeć aplikacji w bebechy to fajnie jest użyć Java Mission Control. Fakt, sam używałem w celach "profilowych" Java Mission Control tylko w Java 8 i nie wiem do końca jak jest z licencją na JCM i jej dostępnością w Java 11...
Ale dzielę się tutaj przydatnymi opcjami do uruchamiania Java'y które w razie obecności JCM zapiszą nam śliczne pliki, które możemy obejrzeć w JCM**.

Poniższy zestaw opcji dla Java'y zapisuje FlightRecord do pliku rec.jfr
-XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:FlightRecorderOptions=dumponexit=true,dumponexitpath=rec.jfr -XX:StartFlightRecording=defaultrecording=true


(to wyżej to kopia z moich notatek z Notion (wcześniej z Evernote))

* - OK, tak naprawdę może pokazać nam też punkty, które nie są gorące, ale np. wątek tam na coś czeka, np. na sieć.
** - uwaga, Oracle coś spaprało i na Java 8 UI do JCM nie działa na macOS, stąd dobrze mieć jest do oglądania zapisów z JCM gdzieś 1.8.0_96 czy podobną.


Podobne posty^beta
Sztuczki tropiciela błędów, part 2 ;-)
Zinwigiluj się sam ;-)
Raport z emigracji ;-)
wait() i notify()/notifyAll() - najbardziej nierozumiane metody klasy Object ;-)
Inercja i koło wielokrotnego wynajdywania, czyli radosne macki piekieł w kodzie [alem pojechał w tytule ;-)]