Naprawianie wycieków pamięci w Tomcat

Problem

Jeden z naszych zespołów programistycznych tworzy aplikację z wykorzystaniem architektury opartej na mikroserwisach.  Składa się ona z około 20 usług uruchamianych na serwerach aplikacji Tomcat 8. Serwer uruchamiany jest na maszynie z systemem CentOS 7. Niedawno, w trakcie restartowania aplikacji, jedno z zadań Jenkinsa przerwał błąd i wyświetlony został poniższy stack trace:

Deploying ERROR: Build step failed with exception org.codehaus.cargo.container.ContainerException: Failed to deploy [C:\.jenkins\jenkins_home\jobs\Apsello_Timesheet_DeployDev_Delta_Deploy\workspace\TimesheetServer\build\libs\TimesheetBE##168_275052bbda394863d5ff75dedb8991b2f227d334.war]

Caused by: java.net.ConnectException: Connection refused: connect
at java.net.DualStackPlainSocketImpl.connect0(Native Method) 
at java.net.DualStackPlainSocketImpl.socketConnect(Unknown Source) 
at java.net.AbstractPlainSocketImpl.doConnect(Unknown Source) 
at java.net.AbstractPlainSocketImpl.connectToAddress(Unknown Source) 
at java.net.AbstractPlainSocketImpl.connect(Unknown Source) 
at java.net.PlainSocketImpl.connect(Unknown Source) 
at java.net.SocksSocketImpl.connect(Unknown Source) 
at java.net.Socket.connect(Unknown Source) 
at java.net.Socket.connect(Unknown Source) 
at sun.net.NetworkClient.doConnect(Unknown Source) 
at sun.net.www.http.HttpClient.openServer(Unknown Source) 
at sun.net.www.http.HttpClient.openServer(Unknown Source) 
at sun.net.www.http.HttpClient.parseHTTPHeader(Unknown Source) 
at sun.net.www.http.HttpClient.parseHTTP(Unknown Source) 
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(Unknown Source) 
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown Source) 
at org.codehaus.cargo.container.tomcat.internal.TomcatManager.invoke(TomcatManager.java:544)

Dochodzenie rozpoczęliśmy od  analizy logów Tomcata. W pliku catalina.out znajdował się trop, który ukierunkował nasze dalsze kroki:

Wniosek był prosty: zabrakło pamięci (metaspace). W zmiennych uruchomieniowych Tomcata przełącznik MaxMetaspaceSize  ustawiony był na ponad 1.25 GB. Nasze aplikacje nie powinny zużywać  więcej niż 450 MB, więc problem tkwił w zarządzaniu pamięcią. Aby zbadać jak Tomcat radzi sobie w tej kwestii, konieczne było dodanie zezwolenia na połączenia zdalne jmx do serwera oraz podłączenie się narzędziem VisualVM do serwera. W tym celu do pliku CATALINA_OPTS  dodaliśmy:

-Dcom.sun.management.jmxremote.authenticate=false
-Dcom.sun.management.jmxremote.port=9999
-Dcom.sun.management.jmxremote.ssl=false
-Djava.rmi.server.hostname=localhost

Śledząc zużycie zasobów od razu zauważyliśmy, że metaspace nie jest zwalniany przy redeployowaniu aplikacji. Każdy kolejny deploy wszystkich aplikacji powodował wzrost zużycia metaspace  o dodatkowe 450 MB. Z prostej kalkulacji wynika, że przy trzecim z rzędu ponownym wrzuceniu wszystkich aplikacji zużycie pamięci zbliża się do granicznego 1,25 GB, po przekroczeniu którego zgłaszany jest wyjątek i serwer przestaje odpowiadać.

Przeglądając zawartość logów Tomcata, znaleźliśmy kolejny ślad, który wskazywał użytego przez nas menadżera puli wątków połączeń do bazy danych z biblioteki c3p0.

Mar 30, 2017 2:59:30 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
WARNING: The web application [BackendApp] appears to have started a thread named [Resource Destroyer in BasicResourcePool.close()] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
java.lang.System.currentTimeMillis(Native Method)
com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3736)
com.mysql.jdbc.MysqlIO.quit(MysqlIO.java:2254)
com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4267)
com.mysql.jdbc.ConnectionImpl.close(ConnectionImpl.java:1531)
com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:642)
com.mchange.v2.c3p0.impl.NewPooledConnection.closeMaybeCheckedOut(NewPooledConnection.java:255)
com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.destroyResource(C3P0PooledConnectionPool.java:622)
com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.java:1076)
com.mchange.v2.resourcepool.BasicResourcePool.destroyResource(BasicResourcePool.java:1101)
com.mchange.v2.resourcepool.BasicResourcePool.destroyResource(BasicResourcePool.java:1062)
com.mchange.v2.resourcepool.BasicResourcePool.access$100(BasicResourcePool.java:44)
com.mchange.v2.resourcepool.BasicResourcePool$5.run(BasicResourcePool.java:1316)

Aby potwierdzić podejrzenia usunęliśmy c3p0 z projektu i przetestowaliśmy aplikację z podstawowym DataSource dostarczanym przez Hibernate.  Na środowisku  testowym, uruchomionym na  Windows OS wszystko działało (metaspace został poprawnie zwolniony przy restarcie aplikacji). Przywróciliśmy c3p0 i podjęliśmy próbę rozwiązania problemu.

Podejrzenie padło na niewłaściwy sposób zamykania puli połączeń przez Hibernate w trakcie rozłączania sesji. Potencjalne i potwierdzone przez społeczność rozwiązanie znaleźliśmy na stackoverflow (http://stackoverflow.com/a/17702965), jednak zastosowanie tego rozwiązania nie zmieniło nic.

Jako że biblioteka c3p0 jest nadal w fazie pre-produkcyjnej, zdecydowaliśmy się sprawdzić najnowszą dostępną wersję. Podmieniliśmy zależności z

org.hibernate:hibernate-c3p0:'4.3.11.Final'

na

org.hibernate:hibernate-c3p0:'5.2.9.Final'

Ponownie rozwiązanie zadziałało na naszym środowisku testowym, pamięć została poprawnie zwolniona, jednak na środowisku deweloperskim nie zrobiło to specjalnego wrażenia. Aby sprawdzić czy jakąś rolę odgrywa tutaj system operacyjny, zdecydowaliśmy się na utworzenie obrazu dockerowego i wyeliminowanie jak największej liczby różnic między środowiskami.

Wykorzystany przez nas plik Dockerfile dostępny jest tutaj.

Obraz zawiera Ubuntu OS , Tomcat 8 oraz Oracle JDK 8. Większość aplikacji (z wyjątkiem dwóch) uruchomionych na kontenerze utworzonym z obrazu nie zwolniło pamięci. Przeanalizowaliśmy różnicę między nimi, żeby zrozumieć co jest wyjątkowego w tych, które potrafiły zwolnić pamięć.

Poszukiwania wskazały na różnicę w zależnościach Gradle`a, a dokładniej na ich scope.  Aplikacje które poprawnie zwalniały pamięć miały ustawioną zależność mysql connector  na compile, podczas gdy w reszcie aplikacji było to providedRuntime.  Z jakiegoś powodu nasz Tomcat zachowywał się dziwnie przy współdzieleniu połączenia do bazy danych z innymi aplikacjami. Po zmianie scope na compile w pozostałych aplikacjach większość z nich poprawnie zwolniła pamięć w trakcie testów. Niestety, nie wszystkie. Te które opierały się naszym staraniom pozostawiały następującą informację w logach:

Mar 30, 2017 12:38:30 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
 WARNING: The web application [BackendApp] appears to have started a thread named [Resource Destroyer in BasicResourcePool.close()] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.lang.System.currentTimeMillis(Native Method)
 ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:127
 ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:440)
 ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:396)
 ch.qos.logback.classic.Logger.debug(Logger.java:503)
 com.mchange.v2.log.slf4j.Slf4jMLog$Slf4jMLogger$DebugLogger.log(Slf4jMLog.java:204)
 com.mchange.v2.log.slf4j.Slf4jMLog$Slf4jMLogger.log(Slf4jMLog.java:247)
 com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.java:1074)
 com.mchange.v2.resourcepool.BasicResourcePool.destroyResource(BasicResourcePool.java:1101)
 com.mchange.v2.resourcepool.BasicResourcePool.destroyResource(BasicResourcePool.java:1062)
 com.mchange.v2.resourcepool.BasicResourcePool.access$100(BasicResourcePool.java:44)
 com.mchange.v2.resourcepool.BasicResourcePool$5.run(BasicResourcePool.java:1316)

Dało to nam dodatkową wskazówkę – logstash appender nie jest prawidłowo zamykany przez niektóre aplikacje. Po przeanalizowaniu sedna problemu doszliśmy do wniosku, że najlepszym rozwiązaniem byłoby napisanie klasy ContextDestroyer, która zostałaby wywołana przez Tomcat, gdy aplikacja jest wyłączana i zamykałaby pozostałe wątki ręcznie. Dodaliśmy następujący komponent do naszych aplikacji:

Testy wykazały że tylko jedna z aplikacji nie zwalnia w całości zaalokowanej przez siebie pamięci. Był to Frontend, który przetrzymywał aktywne sesje. Jeśli wszystkie z nich zostały ręcznie zakończone z konsoli administracyjnej serwera przed restartem aplikacji, pamięć była poprawnie zwalniana. Zdecydowaliśmy się na kompromis w tym przypadku, ponieważ adekwatne rozwiązanie wymagałoby ustalenia limitu czasu na sesję użytkownika poniżej akceptowalnej wartości. Po wyłączeniu, aplikacja frontendowa będzie działać w tle dopóki nie upłynie limit czasu na wszystkie sesje i dopiero po tym czasie zostanie usunięta przy kolejnym restarcie aplikacji, a zaalokowana pamięć zwolniona.

To nie było nasze pierwsze podejście do tego, ale przy wcześniejszych próbach szukaliśmy pojedynczej przyczyny  wszystkich problemów. Warto pamiętać, że zamiast tego można napotkać wiele problemów naraz. Dlatego dobrze jest wyczerpująco badać wszystkie opcje przed porzuceniem jakiegokolwiek podejścia – gdybyśmy po drodze zrezygnowali z jednej z  poprawek “bo nie rozwiązuje problemu”, inne poprawki również by nie pomogły. Nasze wnioski? Nie poddawajcie się!