Каждый, кто разрабатывал веб-приложения на Java, сталкивался с проблемой утечек памяти при остановках и переустановках своих программ. Если же об этом ты слышишь впервые, то могу заверить: с очень большой вероятностью твои творения текут. Причин может быть огромное множество, и об одной из них я бы хотел рассказать в этой статье.

INFO


Даже если ты никогда не пользовался ни Spring, ни Log4j 2, то после прочтения этой статьи ты все равно получишь довольно четкое представление о том, почему такого рода утечки могут возникать и как с ними бороться.

Хотя эта статья и создана для разработчиков, в ней почти отсутствует программный код: все, что нас будет интересовать, — это конфигурационные файлы. Мы будем наблюдать, как простое подключение новой библиотеки в нашу программу будет приводить к утечкам памяти, а небольшие правки в конфигурации — исправлять их. Впрочем, давай обо всем по порядку.

 

Разговорчивый Spring

Роль Spring Framework при разработке промышленных Java-приложений трудно переоценить. Spring способен в разы сократить объем программного кода, который тебе придется написать и сопровождать, а при умелом использовании — сделать программу простой, понятной и адаптируемой к изменчивым требованиям заказчика.

При тестировании и эксплуатации любой системы обязательно возникнет необходимость анализировать ее поведение. Для этого, как правило, используются специальные библиотеки для ведения журнала операций, или, современным языком, библиотеки для вывода логов (логирования).

Приведем простой пример. С помощью Spring-WS можно вызывать сторонние SOAP-службы. Ты отправляешь запрос в такую службу, получаешь ответ, выполняешь над ответом какие-нибудь операции и выводишь результат. Пользователь твоей системы смотрит на этот результат и говорит тебе, что он некорректный, а значит, с его точки зрения, твоя программа содержит ошибки.

Возможно, этот пользователь прав. А возможно, ты получил некорректный ответ из сторонней службы. Единственный способ узнать — это чтение логов, которые пишет твоя система. Ты можешь проверить корректность твоего запроса и корректность ответа, который тебе пришел. В случае с SOAP-службами можно выводить в лог XML запросов и ответов. Тогда у тебя будут железные аргументы, что ошибка не на твоей стороне, если это действительно так.

Ты можешь сам написать код, который будет логировать XML-сообщения перед отправкой и после получения ответа. Однако не стоит усложнять свою программу лишней логикой, если Spring-WS уже логирует эти сообщения за тебя. Твоя задача заключается только в том, чтобы перенаправить логи Spring-WS в ту систему логирования, которая используется в программе. Например, в Log4j 2.

Далее я приведу пример простого веб-приложения, которое выводит логи Spring через конфигурацию Log4j 2. При этом будут наблюдаться утечки памяти при остановке и удалении приложения из контейнера сервлетов.

 

Учимся слушать

Создадим пустой проект веб-приложения на основе Apache Maven. Назовем его, например, spring-log4j2-memory-leaks. В нем почти не будет программного кода: нас интересуют только конфигурационные файлы и вывод логов в консоль. Сначала в файле pom.xml объявим только одну зависимость:

<dependencies>
    <dependency>
        <groupId>org.springframework</groupId>
        <artifactId>spring-web</artifactId>
        <version>4.3.3.RELEASE</version>
    </dependency>
</dependencies>

Чтобы Spring инициализировал свой контекст при старте веб-приложения, необходимо зарегистрировать его в дескрипторе развертывания (web.xml):

<?xml version="1.0" encoding="UTF-8"?>
<web-app xmlns="http://xmlns.jcp.org/xml/ns/javaee" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/javaee http://xmlns.jcp.org/xml/ns/javaee/webapp_3_1.xsd" version="3.1">
    <listener>
        <listener-class>org.springframework.web.context.ContextLoaderListener</listener-class>
    </listener>
    <context-param>
        <param-name>contextConfigLocation</param-name>
        <param-value>/WEB-INF/spring/applicationContext.xml</param-value>
    </context-param>
</web-app>

Здесь файл applicationContext.xml пуст. Сейчас нам не нужно каким-то особым образом конфигурировать Spring:

<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-4.3.xsd">
</beans>

Соберем и опубликуем наше приложение. В этой статье в качестве контейнера сервлетов будет использоваться Apache Tomcat версии 8.0.38. При запуске приложения он выводит в лог сообщения об инициализации контекста Spring:

15-Oct-2016 12:16:03.923 INFO [http-apr-8080-exec-10] org.springframework.web.context.ContextLoader.initWebApplicationContext Root WebApplicationContext: initialization started
15-Oct-2016 12:16:04.303 INFO [http-apr-8080-exec-10] org.springframework.web.context.support.XmlWebApplicationContext.prepareRefresh Refreshing Root WebApplicationContext: startup date [Sat Oct 15 12:16:04 MSK 2016]; root of context hierarchy
15-Oct-2016 12:16:04.493 INFO [http-apr-8080-exec-10] org.springframework.beans.factory.xml.XmlBeanDefinitionReader.loadBeanDefinitions Loading XML bean definitions from ServletContext resource [/WEB-INF/spring/applicationContext.xml]
15-Oct-2016 12:16:04.738 INFO [http-apr-8080-exec-10] org.springframework.web.context.ContextLoader.initWebApplicationContext Root WebApplicationContext: initialization completed in 815 ms

Теперь подключим к проекту Log4j 2:

<dependencies>
    <dependency>
        <groupId>org.springframework</groupId>
        <artifactId>spring-web</artifactId>
        <version>4.3.3.RELEASE</version>
    </dependency>
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-web</artifactId>
        <version>2.7</version>
    </dependency>
</dependencies>

Также создадим для него файл с конфигурацией (log4j2.xml):

<?xml version="1.0" encoding="UTF-8" ?>
<Configuration status="debug">
    <Properties>
        <Property name="pattern">[%thread] %d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %c{1} - %msg%n</Property>
    </Properties>
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="${pattern}" />
        </Console>
    </Appenders>
    <Loggers>
        <Root level="trace">
            <AppenderRef ref="Console" />
        </Root>
    </Loggers>
</Configuration>

Как видишь, конфигурация предельно проста: логи Log4j 2 выводятся в консоль в определенном формате.

Теперь если мы опять соберем проект и опубликуем его, то увидим, что в логах появилось большое количество записей об инициализации контекста Log4j 2:

2016-10-15 12:41:32,949 http-apr-8080-exec-29 DEBUG Starting LoggerContext[name=/spring-log4j2-memory-leaks-1.0] from configuration at file:/C:/Program%20Files/apache-tomcat-8.0.38/webapps/spring-log4j2-memory-leaks-1.0/WEB-INF/log4j2.xml
...
2016-10-15 12:41:33,130 http-apr-8080-exec-29 DEBUG LoggerContext[name=/spring-log4j2-memory-leaks-1.0, org.apache.logging.log4j.core.LoggerContext@2e7453a5] started OK with configuration XmlConfiguration[location=C:\Program Files\apache-tomcat-8.0.38\webapps\spring-log4j2-memory-leaks-1.0\WEB-INF\log4j2.xml].

Однако мы все еще не видим логов Spring! Дело в том, что в нем используется Apache Commons Logging, а значит, мы должны подключить в наш проект Commons Logging Bridge для перенаправления логов из Commons Logging в Log4j 2. Для этого необходимо только добавить новую зависимость в проект:

<dependencies>
    <dependency>
        <groupId>org.springframework</groupId>
        <artifactId>spring-web</artifactId>
        <version>4.3.3.RELEASE</version>
    </dependency>
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-web</artifactId>
        <version>2.7</version>
    </dependency>
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-jcl</artifactId>
        <version>2.7</version>
    </dependency>
</dependencies>

В очередной раз пересоберем и опубликуем проект. Теперь мы можем наблюдать в логах низкоуровневые детали инициализации контекста Spring. Это означает, что Spring-WS из нашего примера в начале статьи также будет выводить в лог XML, которые он отправляет и получает. И не только он. Все библиотеки Spring будут извещать нас о том, что они делают. К примеру, Spring JDBC выведет в лог запросы к БД, Spring AMQP — сообщения из очереди и так далее. В нашем программном коде будет меньше вызовов логгера, а значит, он станет проще.

 

Утечки памяти

На этой оптимистической ноте следовало бы завершить статью, однако настройка нашего веб-приложения еще не закончена. Дело в том, что если мы перезапустим нашу программу, например нажав на кнопку Reload в административной панели Tomcat’а, как показано на рис. 1, то создадим утечку памяти.

Рис. 1. Кнопка Reload
Рис. 1. Кнопка Reload

Ты спросишь, откуда я знаю, что появилась утечка? Есть несколько несложных способов проверить. Самый простой — кнопка Find leaks в административной панели Tomcat’а (рис. 2).

Рис. 2. Кнопка Find leaks
Рис. 2. Кнопка Find leaks

Эта кнопка запускает очистку мусора и выводит на экран список приложений, которые не запущены, но для которых не удалось освободить всю используемую память (рис. 3).

Рис. 3. Утечки памяти
Рис. 3. Утечки памяти

На рисунке видно, что в памяти остались классы от трех запусков нашего приложения. Чем большее число раз мы будем перезапускать программу, тем больше классов не будет очищено и тем больше памяти будет потреблять Tomcat.

Неочищенный мусор логгера также можно увидеть в MBean Browser в Oracle Java Mission Control (рис. 4).

Рис. 4. Oracle Java Mission Control
Рис. 4. Oracle Java Mission Control

Еще один способ — с помощью команды jmap -histo [tomcat pid]. В результате ты увидишь множество классов из твоего приложения, которые дублируются столько раз, сколько ты перезапускаешь приложение, плюс то, что сейчас работает (в нашем случае: 3 + 1 = 4). Пример:

2065: 1 24 org.apache.logging.log4j.core.impl.Log4jContextFactory
2066: 1 24 org.apache.logging.log4j.core.impl.Log4jContextFactory
2067: 1 24 org.apache.logging.log4j.core.impl.Log4jContextFactory
2068: 1 24 org.apache.logging.log4j.core.impl.Log4jContextFactory

Можно задать резонный вопрос: а так ли часто мы перезапускаем веб-приложения? Ответ простой: часто. Например, при установке новой версии. Или при изменении конфигурации программы. Если ты захочешь изменить уровень логирования в приложении с debug на info, то ты откроешь *.war-файл и отредактируешь в нем log4j2.xml. Tomcat автоматически подхватит твои изменения и сделает рестарт приложения, что, в свою очередь, вызовет утечку памяти.

 

Ни шагу назад: исправляем утечки

Теперь, когда наличие проблемы не вызывает сомнений, возникает логичный вопрос, что же эту проблему вызвало. На него есть два ответа, и оба верные.

Первый, самый простой: добавление в проект зависимости log4j-jcl. И действительно, если убрать эту зависимость, то проблема уходит. Но также исчезают и логи Spring, а мы хотим их видеть в нашем проекте.

Второй ответ состоит в том, что при остановке веб-приложения сначала уничтожается контекст Log4j 2, а потом — Spring. Это приводит к интересному эффекту: при уничтожении своего контекста Spring активно пишет в лог, однако при этом Log4j 2 уже уничтожен! Ему ничего не остается, как выполнить повторную инициализацию. Это можно увидеть в логах:

2016-10-15 16:02:26,185 http-apr-8080-exec-87 DEBUG Stopped XmlConfiguration[location=C:\Program Files\apache-tomcat-8.0.38\webapps\spring-log4j2-memory-leaks-1.0\WEB-INF\log4j2.xml] OK

Это сообщение о том, что Log4j 2 остановлен. Однако далее инициализация происходит заново:

2016-10-15 16:02:26,405 http-apr-8080-exec-87 DEBUG Starting LoggerContext[name=564a4bbb, org.apache.logging.log4j.core.LoggerContext@ a67f645]...
...
2016-10-15 16:02:26,481 http-apr-8080-exec-87 DEBUG LoggerContext[name=564a4bbb, org.apache.logging.log4j.core.LoggerContext@a67f645] started OK.

Tomcat об этом не знает и со спокойной совестью завершает работу с приложением, не выполняя повторное уничтожение контекста, что и вызывает утечку памяти.

Чтобы понять, почему так происходит, нужно разобраться в механизме создания и уничтожения контекстов в Tomcat’е и в любом другом контейнере сервлетов, который поддерживает спецификацию Servlet Spec 3.0+.

Если разработчик библиотеки хочет, чтобы при использовании его детища в веб-окружении выполнялись подготовительные действия, то ему следует реализовать интерфейс ServletContainerInitializer, в котором есть единственный метод onStartup.

У Log4j 2 и Spring есть свои реализации этого интерфейса, которые называются, соответственно, Log4jServletContainerInitializer и SpringServletContainerInitializer.

Таким образом, при старте нашего веб-приложения первым делом Tomcat вызывает метод onStartup у каждой из этих двух реализаций. При этом если покопаться в документации к Log4j 2, то можно найти информацию о том, что Log4jServletContainerInitializer обязан вызываться первым.

Впрочем, с этим как раз все в порядке: если поставить точки останова внутри обеих реализаций onStartup, то увидим, что Log4jServletContainerInitializer действительно вызывается в первую очередь. Об этом позаботились разработчики Log4j 2, установив необходимый порядок вызовов в своем файле web-fragment.xml.

Обрати внимание на интересную деталь: в интерфейсе ServletContainerInitializer есть метод onStartup, но нет ничего похожего на, скажем, метод onDestroy. Так какой же метод должен вызвать контейнер сервлетов, чтобы уничтожить контекст?

В Servlet Spec 2.5 и более ранних версиях инициализация и уничтожение контекстов происходили только в реализациях интерфейса ServletContextListener в методах contextInitialized и contextDestroyed. Однако в последних версиях спецификации, а значит, и в нашем случае реализации этого интерфейса тоже используются. Если мы внимательно изучим пакеты с исходными кодами Log4j 2 и Spring, то сможем найти их: это классы Log4jServletContextListener и ContextLoaderListener. У обоих уничтожение контекста реализовано в методе contextDestroyed.

Здесь появляется сразу множество вопросов. Как Tomcat понимает, когда и в какой последовательности вызывать все эти методы? Откуда ему известно о классах, которые их реализуют? Зачем нужен contextInitialized, если есть onStartup? Давай попробуем разобраться.

Выше я писал, что onStartup всегда вызывается в первую очередь, и это действительно так. Классы, которые реализуют этот метод, должны быть зарегистрированы в файле META-INF.services/javax.servlet.ServletContainerInitializer. Ты можешь его увидеть как в Log4j 2, так и в Spring. Tomcat просматривает этот файл и вызывает onStartup для каждого зарегистрированного там инициализатора.

Давай теперь заглянем «под капот» Log4jServletContainerInitializer. Там можно увидеть интересную строчку кода:

servletContext.addListener(new Log4jServletContextListener());

В ней регистрируется Log4jServletContextListener, у которого потом при остановке приложения будет вызван contextDestroyed. При этом в contextInitialized также создается контекст логгера, если он еще не был создан. Такое может быть, только если наш контейнер сервлетов не поддерживает спецификацию 3.0 или если мы отключили Log4jServletContainerInitializer. Все это тоже описано в документации к Log4j 2.

Теперь давай сделаем финт ушами. Поставим точку останова на этой строчке кода и посмотрим, что находится внутри переменной servletContext. А находится там, вот уж неожиданность, ContextLoaderListener. Напомню, что это реализация ServletContextListener от Spring. Она каким-то образом умудрилась попасть туда даже раньше, чем вызвался первый инициализатор! Это значит, что ее contextInitialized будет вызван до contextInitialized Log4j 2, а contextDestroyed — после. Эту картину мы и наблюдали ранее: сначала уничтожается логгер, а потом — Spring.

В итоге у нас начинает складываться интересная последовательность действий, которую выполняет Tomcat:

  1. Регистрирует ContextLoaderListener.
  2. Вызывает onStartup у Log4jServletContainerInitializer (в нем регистрируется Log4jServletContextListener).
  3. Вызывает onStartup у SpringServletContainerInitializer.
  4. Вызывает contextInitialized у ContextLoaderListener.
  5. Вызывает contextInitialized у Log4jServletContextListener.
  6. Вызывает contextDestroyed у Log4jServletContextListener.
  7. Вызывает contextDestroyed у ContextLoaderListener.

Встает интересный вопрос: почему ContextLoaderListener регистрируется раньше всего остального, а не, скажем, в SpringServletContainerInitializer? Ответ прост: мы сами его зарегистрировали в дескрипторе развертывания в начале статьи, а по спецификации web.xml имеет более высокий приоритет (п. 8.2.2).

С другой стороны, если бы мы этого не сделали, то Spring не инициализировался бы вовсе, так как SpringServletContainerInitializer не выполняет напрямую регистрацию ContextLoaderListener. Вместо этого он ищет в пакетах нашего приложения реализации своего собственного интерфейса WebApplicationInitializer и вызывает у них метод onStartup. В нашем проекте ничего подобного нет, поэтому SpringServletContainerInitializer, по сути, «ничего не делает». Давай попробуем удалить файл web.xml и вместо него добавить в наш проект такой класс:

public class MyWebApplicationInitializer extends AbstractContextLoaderInitializer {
    @Override
    protected WebApplicationContext createRootApplicationContext() {
        XmlWebApplicationContext appContext = new XmlWebApplicationContext();
        appContext.setConfigLocation("/WEB-INF/spring/applicationContext.xml");
        return appContext;
    }
}

Здесь AbstractContextLoaderInitializer, в свою очередь, реализует интерфейс WebApplicationInitializer.

Теперь если мы запустим и остановим наше приложение, то по логам или по точкам останова можем увидеть, что последовательность вызовов у Tomcat’а изменилась:

  1. Вызывает onStartup у Log4jServletContainerInitializer (в нем регистрируется Log4jServletContextListener).
  2. Вызывает onStartup у SpringServletContainerInitializer (в нем регистрируется ContextLoaderListener).
  3. Вызывает contextInitialized у Log4jServletContextListener.
  4. Вызывает contextInitialized у ContextLoaderListener.
  5. Вызывает contextDestroyed у ContextLoaderListener.
  6. Вызывает contextDestroyed у Log4jServletContextListener.

Теперь логгер уничтожается в последнюю очередь. Если проверим Tomcat на утечки памяти, то обнаружим, что они пропали.

Есть другой способ добиться того же эффекта, не написав при этом ни строчки кода: отключить инициализатор у Log4j 2 и объявить Log4jServletContextListener в web.xml. Тогда наш дескриптор развертывания примет следующий вид:

<?xml version="1.0" encoding="UTF-8"?>
<web-app xmlns="http://xmlns.jcp.org/xml/ns/javaee" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/javaee http://xmlns.jcp.org/xml/ns/javaee/webapp_3_1.xsd" version="3.1">
    <listener>
        <listener-class>org.apache.logging.log4j.web.Log4jServletContextListener</listener-class>
    </listener>
    <listener>
        <listener-class>org.springframework.web.context.ContextLoaderListener</listener-class>
    </listener>
    <context-param>
        <param-name>isLog4jAutoInitializationDisabled</param-name>
        <param-value>true</param-value>
    </context-param>
    <context-param>
        <param-name>contextConfigLocation</param-name>
        <param-value>/WEB-INF/spring/applicationContext.xml</param-value>
    </context-param>
</web-app>

Здесь очень важно, чтобы Log4jServletContextListener был объявлен very first, то есть выше, чем что-либо еще, в том числе и ContextLoaderListener. Установка параметра isLog4jAutoInitializationDisabled в значение true отключает инициализатор контекста Log4j 2. Такая конфигурация «делает вид», что приложение запущено в контейнере сервлетов 2.5 или более раннем, то есть в таком, который не поддерживает инициализаторы.

Теперь последовательность вызовов у Tomcat’а будет немного другой:

  1. Регистрирует Log4jServletContextListener.
  2. Регистрирует ContextLoaderListener.
  3. Вызывает onStartup у Log4jServletContainerInitializer (ничего не происходит, так как указан параметр isLog4jAutoInitializationDisabled = true).
  4. Вызывает onStartup у SpringServletContainerInitializer (ничего не происходит, так как в приложении нет ни одной реализации WebApplicationInitializer).
  5. Вызывает contextInitialized у Log4jServletContextListener.
  6. Вызывает contextInitialized у ContextLoaderListener.
  7. Вызывает contextDestroyed у ContextLoaderListener.
  8. Вызывает contextDestroyed у Log4jServletContextListener.

Здесь логгер также уничтожается в последнюю очередь, что и устраняет утечку памяти, как в предыдущем случае.

Оба решения довольно просты и лаконичны, в отличие от зубодробительных причин возникновения этой проблемы. Какое из них применять — решать тебе.

 

Выводы

Борьба с утечками памяти при остановках и переустановках веб-приложений вообще довольно-таки нетривиальная и сложная задача. Часто для решения таких проблем приходится с головой зарываться в чужой исходный код. Хорошее руководство на эту тему можно найти и в документации к Tomcat’у: http://wiki.apache.org/tomcat/MemoryLeakProtection. Однако, как правило, его недостаточно.

В общем случае можно посоветовать каждый раз при подключении новой, незнакомой тебе библиотеки проверять, вызывает ли она утечки памяти или нет. В каких-то случаях достаточно перенести эту библиотеку в папку lib Tomcat’а (например, драйвер JDBC), а в других решение не столь очевидно.

С другой стороны, можно вообще не заморачиваться на эту тему. С подобными утечками система может стабильно работать годами, потребляя при этом памяти больше, чем нужно. Но сможешь ли ты спать спокойно по ночам, зная, что в твоей программе есть серьезный баг? Надеюсь, эта статья не даст тебе это сделать :).

WWW


Ссылка на проект с web.xml
Ссылка на проект без web.xml

  • Подпишись на наc в Telegram!

    Только важные новости и лучшие статьи

    Подписаться

    • 1 комментарий
    Подписаться
    Уведомить о
    1 Комментарий
    Старые
    Новые Популярные
    Межтекстовые Отзывы
    Посмотреть все комментарии