Spring и log4j2 в веб-приложении: боремся с утечками памяти

Добавить комментарий

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

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

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

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

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

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

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

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

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

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

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

Создадим пустой проект веб-приложения на основе 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/web-app_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

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

<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>

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

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

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 в log4j2. Для этого необходимо только добавить новую зависимость в проект:

<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» в административной панели томката, как показано на рисунке ниже, то создадим утечку памяти.

Ты спросишь, откуда я знаю, что появилась утечка? Есть несколько несложных способов проверить. Самый простой – кнопка «Find leaks» в административной панели томката:

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

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

Неочищенный мусор логгера также можно увидеть в MBean Browser в 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. Томкат автоматически подхватит твои изменения и сделает рестарт приложения, что в свою очередь вызовет утечку памяти.

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

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

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

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

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

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

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.

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

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

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

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

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

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

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

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

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

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

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

…
 
servletContext.addListener(new Log4jServletContextListener());
 
…

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

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

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

  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.

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

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

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

Есть другой способ добиться того же эффекта, не написав при этом ни строчки кода: отключить инициализатор у log4j2 и объявить 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/web-app_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 отключает инициализатор контекста log4j2. Такая конфигурация «делает вид», что приложение запущено в контейнере сервлетов 2.5 или более раннем, то есть в таком, который не поддерживает инициализаторы.

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

  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;

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

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

Выводы

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

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

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

Ссылки на проекты:

С web.xml: https://burov4j.ru/archives/spring-log4j2-memory-leaks-with-web-xml.zip;

Без web.xml: https://burov4j.ru/archives/spring-log4j2-memory-leaks-without-web-xml.zip.

Статья также была опубликована в журнале “Хакер” в декабрьском номере: https://xakep.ru/2016/12/14/spring-log4j-memory-leaks/

Добавить комментарий

Ваш адрес email не будет опубликован. Обязательные поля помечены *