Troubleshooting aplikacji stworzonych w Javie

07.10.2021 | Aleksander Kostowski

Java

Wstęp

Po udanym wdrożeniu produkcyjnym naszej nowej rewolucyjnej aplikacji, nad którą pracowaliśmy w pocie czoła ostatnie miesiące, może okazać się, że staniemy się ofiarami własnego sukcesu. Przez pierwsze tygodnie aplikacja zbiera bardzo dobre recenzje, lawinowo rośnie liczba użytkowników oraz danych w systemie, które są przetwarzane. Nagle, po kilku dniach lub miesiącach (zależy od skali aplikacji), gdy wolumeny przetwarzanych informacji znacząco już wzrosły okazuje się, że aplikacja działa wolno, pojawiają się błędy, a użytkownicy są wściekli (w końcu jest ich już sporo i aplikacja szybko stała się dla nich krytyczna). Co gorsza, może okazać się, że aplikacja co chwilę się zawiesza i wymaga regularnego restartowania. Jak zapobiec takiej sytuacji na wcześniejszym etapie oraz w ostateczności jak szybko móc zdiagnozować i naprawić problem na produkcji – o tym chciałbym opowiedzieć w dalszej części artykułu.

Aplikacja wolno działa – i co teraz

Szybki rzut na procesy na hoście/pody w kubernetesie – wszystkie procesy aplikacyjne działają. Patrzymy dalej w logi – żadnych błędów, ale logów jakby trochę mniej. I faktycznie strona z naszą aplikacją długo się ładuje. O co może chodzić? Z pomocą przychodzą nam narzędzia diagnostyczne Javy, których nawet nie musimy znikąd pobierać, bo większość z nich jest dostarczana razem z binariami Java. Aby podejść do problemu metodycznie:

Zróbmy thread dumpa, żeby sprawdzić na czym wiszą wątki. Thread dump zawiera listę wątków wraz z aktualnym stacktracem wykonania – pozwoli nam to sprawdzić co się dzieje z wątkiem,
Zerknijmy w logi garbage collectora – jeśli mamy je włączone :) Dzięki temu wykluczymy sytuację, w której aplikacja działa wolno, ponieważ nie ma dostępnej pamięci na heapie i cały CPU jest wykorzystywany przez wywołania garbage collectora,
W przypadku, gdy pamięć jest zapchana zrzućmy heap dumpa do dalszej analizy (uwaga – heap dump zawiera dane wrażliwe takie jak hasła). Heap dump pozwoli nam przejrzeć zawartość pamięci i ustalić co zajmuje najwięcej przestrzeni.

Sprawdźmy zatem, jak te narzędzia wykorzystać w praktyce.

Przykładowa aplikacja

Do lepszego zobrazowania jak działają narzędzia do diagnostyki naszej aplikacji wykorzystamy bardzo prostą aplikację przygotowaną w Java 11 i Spring Boot 2. Do uruchomienia projektów będziesz potrzebował swojego ulubionego IDE z Maven oraz oczywiście Javę.

Kody źródłowe są dostępne tutaj:

https://github.com/akostowski/javaapptroubleshooting

Architektura aplikacji to 2 serwisy, które wystawiają API REST:

HelloApi – pobiera nazwę użytkownika oraz aktualną pogodę z serwisu WeatherApi i zwraca tekst powitalny.
WeatherApi – zwraca aktualną pogodę (losowo z puli 6 warunków pogodowych)

Po prawidłowym uruchomieniu obydwu serwisów powinniśmy móc zawołać endpoint hello:

curl http://localhost:8081/hello/Olek

Nice to meet you Olek. Today is very cloudy.

Thread dump

Teraz wystartujmy serwis WeatherApi z profilem Spring Boot throttling. Zasymuluje nam to sytuację, gdy jeden z serwisów, od którego zależymy zaczyna mieć dłuższe czasy odpowiedzi, a my nie przygotowaliśmy pod jego wywołanie circuit breakera. W naszym przykładzie sytuacja jest bardzo prosta, bo serwis HelloApi zależy tylko od jednego serwisu. W realnym systemie bez poprawnie skonfigurowanego systemu monitorującego znalezienie serwisu wprowadzającego opóźnienia może okazać się dużo trudniejsze.

Teraz ponownie wywołując serwis otrzymamy odpowiedź:

curl http://localhost:8081/hello/Olek

Nice to meet you Olek. Today is very sunny.

Możemy natomiast zauważyć, że przyszła ona dopiero upływie kilku sekund. Chcąc sprawdzić, co dzieje się na serwerze w trakcie tych kilku sekund i dlaczego musimy tak długo czekać na odpowiedź możemy zrzucić z serwera thread dumpa. Istnieje kilka sposób na zrzucenie thread dumpa z aplikacji Javowej, my użyjemy narzędzia jcmd, które jest dostarczane razem z binariami Javy:

jcmd.exe 21580 Thread.print > watki.txt

Powyższe polecenie zrzuci nam do pliku stan wszystkich wątków maszyny wirutalnej Java wraz ze stacktracem dla procesu o numerze PID 21580 (numer PID możesz sprawdzić w logach uruchomienia aplikacji – Spring Boot loguje: Starting HelloApplication using Java 11.0.6 on xxx with PID 21580). Zatem wywołujemy nasz serwis, a następnie zrzucamy thread dumpa z procesu HelloApi:

curl http://localhost:8081/hello/Olek jcmd.exe 21580 Thread.print > watki.txt

Domyślnie Spring Boot loguje nazwę wątku obsługującego żądanie http, co znacząco ułatwi nam analizę:

21580 --- [nio-8081-exec-3] p.a.helloapi.rest.HelloController : Entering welcome method for name: Olek

Teraz wystarczy tylko w zrzuconym thread dumpie poszukać wątku o nazwie nio-8081-exec-3:

"http-nio-8081-exec-3" #31 daemon prio=5 os_prio=0 cpu=0.00ms elapsed=1128.60s tid=0x0000015ef2f27000 nid=0x5694 runnable  [0x00000029a41fc000] 
     java.lang.Thread.State: RUNNABLE 
      at java.net.SocketInputStream.socketRead0(java.base@11.0.6/Native Method) 
      at java.net.SocketInputStream.socketRead(java.base@11.0.6/SocketInputStream.java:115) 
      at java.net.SocketInputStream.read(java.base@11.0.6/SocketInputStream.java:168) 
      at java.net.SocketInputStream.read(java.base@11.0.6/SocketInputStream.java:140) 
      at java.io.BufferedInputStream.fill(java.base@11.0.6/BufferedInputStream.java:252) 
      at java.io.BufferedInputStream.read1(java.base@11.0.6/BufferedInputStream.java:292) 
      at java.io.BufferedInputStream.read(java.base@11.0.6/BufferedInputStream.java:351) 
      - locked <0x0000000627e25518> (a java.io.BufferedInputStream) 
      at sun.net.www.http.HttpClient.parseHTTPHeader(java.base@11.0.6/HttpClient.java:746) 
      at sun.net.www.http.HttpClient.parseHTTP(java.base@11.0.6/HttpClient.java:689) 
      at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(java.base@11.0.6/HttpURLConnection.java:1610) 
      - locked <0x0000000627e1a968> (a sun.net.www.protocol.http.HttpURLConnection) 
      at sun.net.www.protocol.http.HttpURLConnection.getInputStream(java.base@11.0.6/HttpURLConnection.java:1515)     
      - locked <0x0000000627e1a968> (a sun.net.www.protocol.http.HttpURLConnection) 
      at java.net.HttpURLConnection.getResponseCode(java.base@11.0.6/HttpURLConnection.java:527) 
      at org.springframework.http.client.SimpleBufferingClientHttpRequest.executeInternal(SimpleBufferingClientHttpRequest.java:82) 
      at org.springframework.http.client.AbstractBufferingClientHttpRequest.executeInternal(AbstractBufferingClientHttpRequest.java:48) 
      at org.springframework.http.client.AbstractClientHttpRequest.execute(AbstractClientHttpRequest.java:66) 
      at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:776) 
      at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:711) 
      at org.springframework.web.client.RestTemplate.getForEntity(RestTemplate.java:361) 
      at pl.akostowski.helloapi.rest.HelloController.welcome(HelloController.java:23) 
      at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.6/Native Method) 
      at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.6/NativeMethodAccessorImpl.java:62) 
      at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.6/DelegatingMethodAccessorImpl.java:43) 
      at java.lang.reflect.Method.invoke(java.base@11.0.6/Method.java:566) …

W powyższym stacktrace oprócz klas Javowych możemy też znaleźć swojsko brzmiącą nazwę:

at pl.akostowski.helloapi.rest.HelloController.welcome(HelloController.java:23)

Rzut oka w kody źródłowe:

Widzimy, że wątek http czekał na odpowiedź z innego serwisu http i to było przyczyną dłuższego działania naszego endpointa.

Narzędzie thread dump jest niezwykle przydatne podczas analizy działania aplikacji – pozwala nam zweryfikować jaka jest liczba wątków, jak duże są pule wątków oraz co w danym momencie wątek robi. Zalecane jest, aby wykonać kilka thread dumpów w odstępie kilku-kilkunastu sekund – dzięki temu będziemy mogli stwierdzić czy stan wątków się zmienia, czy stale oczekują na tym samym zdarzeniu.

Garbage collector

Na potrzeby analizy logów garbage collectora ponownie wykorzystamy serwis HelloApi, ale tym razem wywołując endpoint http://localhost:8081/unzip. Działanie endpointa jest bardzo proste – otrzymuje na wejściu spakowany zipem plik tekstowy, a następnie go rozpakowuje oraz zwraca jego długość bez uwzględnienia białych znaków. Wystartujmy ponownie aplikację HelloApplication; tym razem podając jako parametr VMki maksymalną wielkość heapa 64 MB:

-Xmx64m

Do wywołania serwisu możemy użyć przykładowego pliku gutenberg.zip, który znajduje się w test/resources:

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip

Wywołajmy tę usługę trzykrotnie:

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip

File content size is 15610047

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip

File content size is 15610047

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip

{"timestamp":"2021-05-06T13:31:30.835+00:00","status":500,"error":"Internal Server Error","message":"","path":"/unzip"}

Za trzecim razem otrzymujemy z serwera 500-tkę. W logach serwera widać natomiast:

java.lang.OutOfMemoryError: Java heap space

Sprawdźmy zatem jak zmieniała się zajętość heapa Javy podczas kolejnych wywołań – tylko gdzie są logi garbage collectora? Nigdzie, ponieważ jeszcze ich nie włączyliśmy :) To bardzo istotny element – domyślnie Java nie loguje działania garbage collectora – musimy to jawnie włączyć. Wystarczy, że do parametrów VM Java dodamy:

-Xlog:gc*,age*,ergo*:file=logsgc.log:tags,uptime,time,level:filecount=1,filesize=50m

oraz przeładujemy naszą aplikację – w głównym folderze powinien pojawić się plik logsgc.log.

Następnie ponownie trzykrotnie wywołujemy nasz serwis:

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip 

File content size is 15610047 

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip 

File content size is 15610047 

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip 

{"timestamp":"2021-05-06T13:31:30.835+00:00"","status":500,"error":"Internal Server Error","message":"","path":"/unzip"}

Nic się nie zmieniło, natomiast teraz jesteśmy bogatsi o logi z garbage collectora, które możemy przeanalizować.

Od wersji Java 9 domyślnym garbage collectorem jest G1 GC, który dzieli heapa na małe regiony (w naszym przypadku 1 MB), które następnie przypisuje do jednej z trzech przestrzeni:

Old
Survivor
Eden

Obiekty, które nie mieszą się w pojedynczym regionie są przenoszone do dodatkowej przestrzeni Humongous.

Po trzecim wywołaniu usługi unzip w logach garbage collectora pojawił się wpis To-space exhausted:

[2021-05-17T13:00:40.632+0200][92.755s][info][gc            ] GC(277) To-space exhausted 
[2021-05-17T13:00:40.632+0200][92.755s][info][gc,phases     ] GC(277)   Pre Evacuate Collection Set: 0.0ms 
[2021-05-17T13:00:40.632+0200][92.755s][info][gc,phases     ] GC(277)   Evacuate Collection Set: 0.2ms 
[2021-05-17T13:00:40.632+0200][92.755s][info][gc,phases     ] GC(277)   Post Evacuate Collection Set: 1.8ms 
[2021-05-17T13:00:40.632+0200][92.755s][info][gc,phases     ] GC(277)   Other: 0.2ms 
[2021-05-17T13:00:40.632+0200][92.755s][info][gc,heap       ] GC(277) Eden regions: 1->0(3) 
[2021-05-17T13:00:40.632+0200][92.755s][info][gc,heap       ] GC(277) Survivor regions: 0->0(1) 
[2021-05-17T13:00:40.632+0200][92.755s][info][gc,heap       ] GC(277) Old regions: 14->15 
[2021-05-17T13:00:40.632+0200][92.755s][info][gc,heap       ] GC(277) Humongous regions: 49->49

Sugeruje on, że garbage collector nie ma wystarczająco miejsca na heapie, aby wykonać promocje obiektów pomiędzy przestrzeniami. Poniżej wpisu To-space exhausted znajduje się statystyka pokazująca ile regionów w danej przestrzeni zostało utworzonych. Widzimy, że najwięcej miejsca na heapie zajmują wspomniane wcześniej Humongous regions, czyli obiekty nie mieszące się w pojedynczym regionie 1 MB. Spróbujmy zatem prześledzić nasz log z garbage collectora, żeby sprawdzić jak zmieniała się liczba regionów humongous:

[2021-05-17T12:59:11.585+0200][3.705s][info][gc,heap      ] GC(0) Humongous regions: 0->0 ... 
[2021-05-17T13:00:25.304+0200][77.425s][info][gc,heap       ] GC(8) Humongous regions: 0->0 
[2021-05-17T13:00:25.429+0200][77.550s][info][gc,heap       ] GC(9) Humongous regions: 1->1 
[2021-05-17T13:00:25.554+0200][77.675s][info][gc,heap       ] GC(10) Humongous regions: 3->2 
[2021-05-17T13:00:25.652+0200][77.779s][info][gc,heap       ] GC(11) Humongous regions: 5->3 
[2021-05-17T13:00:25.773+0200][77.894s][info][gc,heap       ] GC(12) Humongous regions: 3->3 
[2021-05-17T13:00:25.888+0200][78.008s][info][gc,heap       ] GC(13) Humongous regions: 3->3 
[2021-05-17T13:00:26.074+0200][78.194s][info][gc,heap       ] GC(14) Humongous regions: 3->3 
[2021-05-17T13:00:26.268+0200][78.389s][info][gc,heap       ] GC(15) Humongous regions: 8->5 
[2021-05-17T13:00:26.385+0200][78.509s][info][gc,heap       ] GC(16) Humongous regions: 5->5 
.. 
[2021-05-17T13:00:26.907+0200][79.027s][info][gc,heap       ] GC(21) Humongous regions: 5->5 
[2021-05-17T13:00:27.004+0200][79.129s][info][gc,heap       ] GC(22) Humongous regions: 15->10 
[2021-05-17T13:00:27.099+0200][79.220s][info][gc,heap       ] GC(23) Humongous regions: 10->10 
.. 
[2021-05-17T13:00:28.542+0200][80.662s][info][gc,heap       ] GC(36) Humongous regions: 10->10 
[2021-05-17T13:00:28.619+0200][80.739s][info][gc,heap       ] GC(38) Humongous regions: 29->19 
[2021-05-17T13:00:28.713+0200][80.833s][info][gc,heap       ] GC(39) Humongous regions: 19->19 
... 
[2021-05-17T13:00:30.852+0200][82.972s][info][gc,heap       ] GC(77) Humongous regions: 19->19 
[2021-05-17T13:00:33.440+0200][85.561s][info][gc,heap       ] GC(79) Humongous regions: 34->34 
[2021-05-17T13:00:33.484+0200][85.605s][info][gc,heap       ] GC(80) Humongous regions: 34->34 
[2021-05-17T13:00:33.536+0200][85.657s][info][gc,heap       ] GC(82) Humongous regions: 15->15 
[2021-05-17T13:00:33.615+0200][85.735s][info][gc,heap       ] GC(83) Humongous regions: 16->16 
[2021-05-17T13:00:33.658+0200][85.778s][info][gc,heap       ] GC(84) Humongous regions: 16->16 
[2021-05-17T13:00:33.756+0200][85.876s][info][gc,heap       ] GC(86) Humongous regions: 18->17 
[2021-05-17T13:00:33.861+0200][85.982s][info][gc,heap       ] GC(87) Humongous regions: 17->17 
[2021-05-17T13:00:33.903+0200][86.024s][info][gc,heap       ] GC(89) Humongous regions: 17->17 
[2021-05-17T13:00:33.993+0200][86.114s][info][gc,heap       ] GC(91) Humongous regions: 20->18 
[2021-05-17T13:00:34.088+0200][86.209s][info][gc,heap       ] GC(92) Humongous regions: 18->18 
.. 
[2021-05-17T13:00:34.344+0200][86.465s][info][gc,heap       ] GC(97) Humongous regions: 18->18 
[2021-05-17T13:00:34.440+0200][86.561s][info][gc,heap       ] GC(99) Humongous regions: 23->20 
[2021-05-17T13:00:34.514+0200][86.634s][info][gc,heap       ] GC(100) Humongous regions: 20->20 
.. 
[2021-05-17T13:00:35.147+0200][87.268s][info][gc,heap       ] GC(114) Humongous regions: 20->20 
[2021-05-17T13:00:35.223+0200][87.344s][info][gc,heap       ] GC(116) Humongous regions: 30->25 
... 
[2021-05-17T13:00:36.866+0200][88.986s][info][gc,heap       ] GC(157) Humongous regions: 25->25 
[2021-05-17T13:00:36.908+0200][89.029s][info][gc,heap       ] GC(158) Humongous regions: 44->34 
[2021-05-17T13:00:36.948+0200][89.069s][info][gc,heap       ] GC(159) Humongous regions: 34->34 [2021-05-17T13:00:37.008+0200][89.129s][info][gc,heap       ] GC(161) Humongous regions: 34->34 
... 
[2021-05-17T13:00:39.478+0200][91.598s][info][gc,heap       ] GC(271) Humongous regions: 34->34 
[2021-05-17T13:00:40.611+0200][92.731s][info][gc,heap       ] GC(273) Humongous regions: 49->49 
[2021-05-17T13:00:40.617+0200][92.738s][info][gc,heap       ] GC(274) Humongous regions: 49->49 
[2021-05-17T13:00:40.628+0200][92.749s][info][gc,heap       ] GC(276) Humongous regions: 49->49 
[2021-05-17T13:00:40.632+0200][92.755s][info][gc,heap       ] GC(277) Humongous regions: 49->49

Widzimy, że wielkość przestrzeni Humongous stale rosła, aby finalnie osiągnąć wartość 49, powyżej której garbage collector nie jest już w stanie prawidłowo działać.

No dobrze – z logów garbage collectora udało nam się ustalić, że z kolejnymi wywołaniami serwisu rośnie nam zajętość obiektów na heapie w przestrzeni Humongous, które nie są zwalniane przez garbage collectora. Ale jak możemy się dowiedzieć co to są za obiekty? Do tego celu możemy skorzystać z kolejnego narzędzia dostarczanego wraz z Javą – Heap Dumpa.

Heap dump

W celu wygenerowania heap dumpa użyjemy znanego już nam narzędzia jcmd:

jcmd.exe 2600 GC.heap_dump naszheapdump.hprof

W wyniku działania komendy otrzymamy plik z zawartością pamięci JVM aplikacji HelloApi. Tak wygenerowany plik możemy następnie otworzyć np. w darmowym narzędziu Eclipse Memory Analyzer:

Wybierzmy akcję Dominator Tree, aby sprawdzić, które obiekty zajmują najwięcej miejsca na heapie:

Po rozwinięciu największego obiektu okazuje się, że miejsce na heapie zajmują obiekty sesyjne Tomcata, a konkretnie obiekty klasy pl.akostowski.helloapi.rest.ZipController. Możemy pójść dalej i zobaczyć wychodzące referencje dla takiego obiektu (opcja List objects -> with outgoing references):

Ponad 15 MB zajmuje String znajdujący się w atrybucie detectedText. Rzut oka w kod klasy:

I widzimy, że wszystko się zgadza – beany ZipControllera są w scopie SessionScope, a w polu detectedText jest przechowywany zdekompresowany plik.

Na koniec spróbujmy poprawić błąd z wyciekiem pamięci – w naszym przypadku nie ma potrzeby, aby wynik dekompresji zapisywać w sesji użytkownika – wystarczy zatem, że pole detectedText przeniesiemy do ciała metody:

Wywołujemy wielokrotnie serwis:

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip

File content size is 15610047

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip

File content size is 15610047

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip

File content size is 15610047

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip

File content size is 15610047

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip

File content size is 15610047

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip

File content size is 15610047

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip

File content size is 15610047

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip

File content size is 15610047

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip

File content size is 15610047

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip

File content size is 15610047

Błąd z brakiem pamięci na serwerze już nie występuje. Możemy jeszcze zerknąć w logi garbage collectora:

[2021-05-17T14:47:08.759+0200][23.552s][info][gc,heap       ] GC(152) Humongous regions: 34->19
[2021-05-17T14:47:08.792+0200][23.586s][info][gc,heap       ] GC(153) Humongous regions: 19->19
[2021-05-17T14:47:08.848+0200][23.641s][info][gc,heap       ] GC(155) Humongous regions: 1->1
[2021-05-17T14:47:08.927+0200][23.720s][info][gc,heap       ] GC(156) Humongous regions: 3->2
[2021-05-17T14:47:09.012+0200][23.805s][info][gc,heap       ] GC(157) Humongous regions: 5->3
[2021-05-17T14:47:09.097+0200][23.891s][info][gc,heap       ] GC(158) Humongous regions: 3->3
[2021-05-17T14:47:09.185+0200][23.978s][info][gc,heap       ] GC(159) Humongous regions: 3->3
[2021-05-17T14:47:09.270+0200][24.063s][info][gc,heap       ] GC(160) Humongous regions: 8->5
[2021-05-17T14:47:09.353+0200][24.147s][info][gc,heap       ] GC(161) Humongous regions: 5->5
[2021-05-17T14:47:09.434+0200][24.228s][info][gc,heap       ] GC(162) Humongous regions: 5->5
[2021-05-17T14:47:09.516+0200][24.310s][info][gc,heap       ] GC(163) Humongous regions: 5->5
[2021-05-17T14:47:09.599+0200][24.392s][info][gc,heap       ] GC(164) Humongous regions: 5->5
[2021-05-17T14:47:09.689+0200][24.482s][info][gc,heap       ] GC(165) Humongous regions: 5->5
[2021-05-17T14:47:09.768+0200][24.561s][info][gc,heap       ] GC(166) Humongous regions: 5->5
[2021-05-17T14:47:09.847+0200][24.641s][info][gc,heap       ] GC(167) Humongous regions: 15->10

Widzimy, że tym razem garbage collector potrafi zwalniać regiony typu Humongous (ponieważ nie zawierają już referencji do obiektów sesyjnych) co zabezpiecza nas przed wystąpieniem wyjątku OutOfMemory. Co prawda nadal występują zdarzenia To-space exhausted wskazujące na nieefektywne działanie garbage collectora. Spróbujmy zatem i to naprawić poprzez drobną modyfikację w kodzie:

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip

File content size is 15610047

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip

File content size is 15610047

curl -F "file=@gutenberg.zip" http://localhost:8081/unzip

File content size is 15610047

Dla tak przygotowanej poprawki serwis nadal działa prawidłowo (a nawet szybciej), w logach garbage collectora przestał pojawiać się komunikat To-space exhausted, a liczba obiektów w przestrzeni Humongous jest wyraźnie mniejsza:

[2021-05-17T16:03:48.139+0200][1.884s][info][gc,heap      ] GC(0) Humongous regions: 0->0
[2021-05-17T16:03:48.827+0200][2.573s][info][gc,heap      ] GC(1) Humongous regions: 0->0
[2021-05-17T16:03:49.592+0200][3.338s][info][gc,heap       ] GC(3) Humongous regions: 0->0
[2021-05-17T16:03:50.637+0200][4.383s][info][gc,heap       ] GC(5) Humongous regions: 0->0
[2021-05-17T16:03:51.380+0200][5.126s][info][gc,heap       ] GC(6) Humongous regions: 0->0
[2021-05-17T16:04:03.408+0200][17.153s][info][gc,heap       ] GC(7) Humongous regions: 21->10
[2021-05-17T16:04:03.414+0200][17.159s][info][gc,heap       ] GC(9) Humongous regions: 10->10
[2021-05-17T16:04:09.251+0200][22.997s][info][gc,heap       ] GC(10) Humongous regions: 29->0
[2021-05-17T16:04:09.396+0200][23.142s][info][gc,heap       ] GC(12) Humongous regions: 11->5
[2021-05-17T16:04:09.549+0200][23.294s][info][gc,heap       ] GC(14) Humongous regions: 15->10
[2021-05-17T16:04:10.406+0200][24.152s][info][gc,heap       ] GC(16) Humongous regions: 29->0
[2021-05-17T16:04:10.576+0200][24.322s][info][gc,heap       ] GC(18) Humongous regions: 11->5
[2021-05-17T16:04:10.759+0200][24.505s][info][gc,heap       ] GC(20) Humongous regions: 15->10
[2021-05-17T16:04:11.600+0200][25.345s][info][gc,heap       ] GC(22) Humongous regions: 29->0
[2021-05-17T16:04:11.770+0200][25.515s][info][gc,heap       ] GC(24) Humongous regions: 11->5
[2021-05-17T16:04:11.955+0200][25.701s][info][gc,heap       ] GC(26) Humongous regions: 15->10
[2021-05-17T16:04:12.772+0200][26.518s][info][gc,heap       ] GC(28) Humongous regions: 29->0
[2021-05-17T16:04:12.935+0200][26.681s][info][gc,heap       ] GC(30) Humongous regions: 11->5
[2021-05-17T16:04:13.118+0200][26.863s][info][gc,heap       ] GC(32) Humongous regions: 15->10
[2021-05-17T16:04:14.006+0200][27.752s][info][gc,heap       ] GC(34) Humongous regions: 29->0
[2021-05-17T16:04:14.213+0200][27.960s][info][gc,heap       ] GC(36) Humongous regions: 11->5
[2021-05-17T16:04:14.440+0200][28.186s][info][gc,heap       ] GC(38) Humongous regions: 15->10
[2021-05-17T16:05:38.226+0200][111.972s][info][gc,heap       ] GC(40) Humongous regions: 29->0
[2021-05-17T16:05:38.446+0200][112.191s][info][gc,heap       ] GC(42) Humongous regions: 11->5
[2021-05-17T16:05:38.662+0200][112.407s][info][gc,heap       ] GC(44) Humongous regions: 15->10
[2021-05-17T16:05:39.750+0200][113.496s][info][gc,heap       ] GC(46) Humongous regions: 29->0

Testy wydajnościowe

Jak dotąd nie poruszyliśmy tematu testów wydajnościowych, które tak naprawdę są kluczem do późniejszego sukcesu. Wybór dostępnych narzędzi oraz sama metodologia przeprowadzenia testów wydajnościowych to niezwykle rozległy temat nadający się z pewnością na osobny artykuł.

Chciałbym jednak podkreślić dlaczego tak ważne jest ich wcześniejsze uruchomienie (choćby w ograniczonym zakresie). Przede wszystkim pozwoli nam poznać charakterystykę naszej aplikacji – będziemy mogli oszacować jakiej wielkości pula wątków oraz pula połączeń do bazy jest potrzebna do obsłużenia N użytkowników, ile instancji serwera będziemy potrzebowali, co jest wąskim gardłem naszej aplikacji. Zdobywając tę wiedzę na środowisku testowym zapewnimy sobie spokój i komfort na środowisku produkcyjnym - patrząc na parametry serwera będziemy w stanie szybko ocenić czy działa on prawidłowo. Jeśli nie zdobędziemy tej wiedzy wcześniej niż w momencie wystąpienia problemu na produkcji oznacza to większe straty finansowe (bo naprawa awarii będzie się przedłużała) oraz pracę pod ogromnym stresem (bo produkcja nie działa).

Kolejną zaletą wykonania testów wydajnościowych na środowisku testowym jest możliwość poznania narzędzi, które ułatwią nam analizę błędu - w przypadku wystąpienia problemu na produkcji będziemy już wiedzieli z którego narzędzia oraz w jaki sposób skorzystać co znacząco skróci czas rozwiązywania problemu.

Podsumowanie

Za pomocą kilku narzędzi dostępnych ze standardową instalacją Javy byliśmy w stanie zdiagnozować problemy wydajnościowe w naszej aplikacji, a następnie je naprawić. Thread dump, logi garbage collectora oraz heap dump okazują się nieocenionym wsparciem w przypadku, gdy aplikacja działa wolno, a w logach nie mamy żadnych informacji o błędach. Warto uruchomić te narzędzia już na środowiskach testowych po to, aby:

Poznać specyfikę ich działania, zaznajomić się z komendami i interfejsem
Poznać charakterystykę działania swojej aplikacji (wymagania pamięciowe, czasy działania garbage collectora)
Nauczyć się ich szybko i poprawnie używać w przypadku, gdy wystąpi taka konieczność