Poszukując metod na zwiększenie wydajności programu do automatycznego doboru indeksów w bazach danych, który piszę w ramach swojego doktoratu, postanowiłem użyć profilera. Zawsze wydawało mi się, że profilowanie jest proste - podłączamy profiler do naszej aplikacji, czekamy aż uzbiera odpowiednio dużo danych i już po chwili z ładnych wykresów wiemy co i ile czasu w programie się wykonuje, i co warto optymalizować. Niestety, jak się wkrótce przekonałem, rzeczywistość nie jest taka piękna.

Pierwszy problem jaki się pojawił, to "jaki profiler wybrać"? Profilerów dla Javy jest mnóstwo, stąd zacząłem najpierw od tych darmowych. Profiler4J wyglądał obiecująco. Ściągnąłem, zainstalowałem i faktycznie po paru minutach mogłem nacieszyć się ładnym grafem wywołań, z ciężkimi metodami pokolorowanymi intensywnie na czerwono, z lekkimi - na bladoróżowo bądź biało.
Przystąpiłem więc do optymalizacji, oczekując dużego przyspieszenia, ponieważ profiler raportował 90% czasu spędzanego w jednej metodzie. No i tu spotkała mnie przykra niespodzianka. Przyspieszenie było niewielkie.
Pomyślałem, że może moje umiejętności pisania wydajnego kodu w Javie nie są najlepsze. Dopisałem więc kilka wywołań System.nanoTime() tu i ówdzie, i okazało się, że nowa wersja tej metody faktycznie wykonuje się kilka razy szybciej niż poprzednia wersja, więc całość programu powinna też przyspieszyć kilkukrotnie... no chyba, że zmierzone wcześniej 90% jest nieprawdziwe.

Zacząłem się dokładniej przyglądać profilerowi - jego ustawieniom oraz zasadzie działania. Spodziewałem się oczywiście, że wyniki podawane przez to narzędzie, podobnie jak przez każde inne narzędzie pomiarowe, są obarczone jakimś błędem, ale nie sądziłem, że ów błąd może być tak duży, żeby dla pojedynczej metody raportować wielokrotnie za duży udział. Dlatego wypróbowałem inny profiler (konkretnie był to profiler wbudowany w VisualVM) i niestety tu wyniki były dość zgodne z wynikami z Profiler4J. Czyli albo coś jest takiego w moim programie, co oszukuje profilery, albo profilery są do bani. :D

Zagadka szybko się rozwiązała po wykonaniu kilku prostych eksperymentów. Większość profilerów umożliwia określenie, które pakiety mają być uwzględniane, a które pominięte w pomiarach. Dzięki wypróbowaniu różnych ustawień doszedłem do następujących wniosków:

1. Szybkość działania profilowanego programu drastycznie zmienia się w zależności od liczby profilowanych metod. Profilując wszystko udało mi się doprowadzić do 20-krotnego spowolnienia aplikacji.
2. Profilowanie krótkich, często wywoływanych metod spowalnia dużo silniej niż profilowanie kolosów na 3 ekrany.
3. Profiler mierzy wykonywanie już spowolnionych przez siebie metod.

Wcześniej wspomniana problematyczna metoda właśnie wywoływała wielokrotnie bardzo małe, często jednolinijkowe metody (ale nie tylko gettery i settery), stąd profiler doświadczył ją dużo bardziej niż inne części kodu. Ogólnie problem jest poważny, bo żaden profiler nie potrafi nawet oszacować, jak bardzo to zjawisko może zakłócać podawane wyniki. A jak mawiał mój fizyk "Wynik pomiaru bez oszacowania błędu jest bezużyteczny".

Zacząłem zastanawiać się, czy nie istnieje jakiś inny sposób profilowania - bez ingerencji w kod. Znalazłem
to: JSamp oraz to: hprof. Nie mają wprawdzie GUI, nie robią grafów ani drzew wywołań, ale przynajmniej nie spowalniają programu i nie kłamią. Z drugiej strony są też bardzo rozbudowane komercyjne profilery, które zrobią wszystko łącznie z rozwieszeniem prania i wyprowadzeniem psa na spacer, ale też nie do końca to mi było potrzebne (to trochę jak kupowanie SUV, żeby jeździć do pracy w zatłoczonym centrum). To wszystko skłoniło mnie do napisania własnego, lekkiego profilera, który mam nadzieję zaoszczędzi wielu frustracji nie tylko mnie. Zapraszam wszystkich do testów.