Утечка памяти с помощью пользовательского приложения Hibernate Log4j2 - PullRequest
Новая
       13

Утечка памяти с помощью пользовательского приложения Hibernate Log4j2

10 голосов
/ 29 апреля 2019

Мы переместили наше приложение из собственного небольшого компонента регистрации в Log4j2.Приложение выполняет около 60 000 заданий в день при нашей самой большой установке.

Мы пишем наш собственный Appender, который пишет с помощью Hibernate, в нашу БД (см. InnovaIntegrationsportalHibernateAppender).

После времени выполнения ~ 36 ч JVMпроизошел сбой при исключении / ошибке «Недостаточно памяти» (OOME) при анализе hprof, который я обнаружил, что существует 763,5 МБ класса org.apache.logging.log4j.core.appender.AbstractManager

см. скриншотприкрепленного анализа (2019-04-12 13_20_45-eclips ...)

https://issues.apache.org/jira/browse/LOG4J2-2589

Идя глубже, я попытался восстановить поведение в тестовом классе и профилировать его результат (см.скриншот-1).

Похоже на утечку памяти.

InnovaIntegrationsportalHibernateAppender 

package de.itout.innova.log4j.innova_log4j_appender;

import de.itout.innova.ssp.entities.ssp.entities.*;
import de.itout.jpa.util.*;
import java.io.*;
import java.util.*;
import javax.persistence.*;
import org.apache.logging.log4j.core.*;
import org.apache.logging.log4j.core.appender.*;
import org.apache.logging.log4j.core.config.plugins.*;
import org.apache.logging.log4j.core.layout.*;

/**
 *
 * @author swendelmann
 */
@Plugin(name = "InnovaIntegrationsportalHibernateAppender", category = "Core", elementType = "appender")
public class InnovaIntegrationsportalHibernateAppender extends AbstractAppender
{

  private String schnittstelle;
  private String version;
  private String laufId;
  private EntityManager em;

  public InnovaIntegrationsportalHibernateAppender(String name, Filter filter, Layout<? extends Serializable> layout)
  {
    super(name, filter, layout);
  }

  public InnovaIntegrationsportalHibernateAppender(String name, Filter filter, Layout<? extends Serializable> layout, boolean ignoreExceptions)
  {
    super(name, filter, layout, ignoreExceptions);
  }

  private InnovaIntegrationsportalHibernateAppender(String name, Filter filter, Layout<? extends Serializable> layout, boolean ignoreExceptions, String schnittstelle, String version, String laufId)
  {
    super(name, filter, layout, ignoreExceptions);
    this.schnittstelle = schnittstelle;
    this.version = version;
    this.laufId = laufId;
  }

  // Your custom appender needs to declare a factory method
  // annotated with `@PluginFactory`. Log4j will parse the configuration
  // and call this factory method to construct an appender instance with
  // the configured attributes.
  @PluginFactory
  public static InnovaIntegrationsportalHibernateAppender createAppender(
          @PluginAttribute("name") String name,
          @PluginElement("Layout") Layout<? extends Serializable> layout,
          @PluginElement("Filter") final Filter filter,
          @PluginAttribute("schnittstelle") String schnittstelle,
          @PluginAttribute("version") String version,
          @PluginAttribute("laufId") String laufId
  )
  {
    if (name == null)
    {
      LOGGER.error("No name provided for InnovaIntegrationsportalHibernateAppender");
      return null;
    }
    if (layout == null)
    {
      layout = PatternLayout.createDefaultLayout();
    }
    if (laufId == null || laufId.isEmpty())
    {
      LOGGER.error("No laufid provided for InnovaIntegrationsportalHibernateAppender");
    }
    return new InnovaIntegrationsportalHibernateAppender(name, filter, layout, true, schnittstelle, version, laufId);
  }

  @Override
  public void append(LogEvent event)
  {
    try
    {

      em = JPAUtil.getEntityManager("SSP");
      em.getTransaction().begin();
      LauflogPK lauflogPK = new LauflogPK(schnittstelle, version, laufId, getNextLaufLogPos());
      Lauflog lauflog = new Lauflog(lauflogPK);
      lauflog.setLevel(event.getLevel().name());
      Date eventDateTime = new Date(event.getTimeMillis());
      lauflog.setLastchangeAenderungsdatum(eventDateTime);
      lauflog.setLastchangeAenderungszeit(eventDateTime);
      lauflog.setLastchangeBenutzer("WENDELMANN");
      lauflog.setLastchangeLogflag('A');
      lauflog.setText(event.getMessage().getFormattedMessage());
      em.persist(lauflog);
      em.getTransaction().commit();
    }
    catch (Throwable t)
    {
      em.getTransaction().rollback();
      LOGGER.error("Cant commit to Database InnovaIntegrationsportalHibernateAppender ", t);
      //TODO Log to file
    }
    finally
    {
      try
      {
        if (em != null)
        {
          em.close();
        }
      }
      catch (Throwable t)
      {
        LOGGER.error("Cant close em: ", t);
      }
    }

  }

  /**
   * SELECT ISNULL(MAX(POS)+1,0) FROM LAUFLOG
   * @return 
   */
  private int getNextLaufLogPos()
  {
    Integer i = (Integer) em.createQuery("SELECT MAX(l.lauflogPK.pos)+1 FROM Lauflog l WHERE l.lauflogPK.schnittstelle = :schnittstelle AND l.lauflogPK.version = :version AND l.lauflogPK.lauf = :lauf ")
            .setParameter("schnittstelle", this.schnittstelle)
            .setParameter("version", this.version)
            .setParameter("lauf", this.laufId)
            .getSingleResult();
    if (i == null)
    {
      return 0;
    }
    else
    {
      return i;
    }
  }

}

package de.itout.innova.log4j;

import de.itout.innova.log4j.innova_log4j_appender.*;
import de.itout.jpa.util.*;
import java.io.*;
import java.nio.charset.*;
import org.apache.logging.log4j.*;
import org.apache.logging.log4j.core.*;
import org.apache.logging.log4j.core.appender.*;
import org.apache.logging.log4j.core.config.*;
import org.apache.logging.log4j.core.layout.*;
import org.junit.*;

/**
 *
 * @author swendelmann
 */
public class ProfilingTest
{

  QEntityManager em;
  private org.apache.logging.log4j.Logger logg = LogManager.getLogger();
  // Potential memory leak
  final LoggerContext ctx = (LoggerContext) LogManager.getContext(false);

  public ProfilingTest()
  {
  }

  @Before
  public void setUp()
  {
    em = JPAUtil.getEntityManager("SSP");
  }

  @After
  public void tearDown()
  {
    em.close();
  }

  @Test
  public void testProfiling()
  {
    logg.trace("Start the Main Method");
    int runs = 1000;
    int logs = 10;
    String allSicherungsVerzeichnis = "target/sicherungsverzeichnis/";
    logg.debug("Start Test mit " + runs + " durchläufen");
    for (int i = 0; i < runs; i++)
    {
      String laufid = "LD0" + i;

      File laufLogFile = new File(allSicherungsVerzeichnis + laufid + "_full.log");

      Configuration config = ctx.getConfiguration();

      // Full File Logger
      Layout layout = PatternLayout.newBuilder()
        .withConfiguration(config)
        .withPattern(PatternLayout.SIMPLE_CONVERSION_PATTERN)
        .withCharset(Charset.forName("UTF-8"))
        .build();

      Appender fullAppender = FileAppender.newBuilder()
        .setConfiguration(config)
        .setName(laufid + "FULL")
        .withFileName(laufLogFile.getAbsolutePath())
        .withAppend(true)
        .withImmediateFlush(true)
        .setIgnoreExceptions(false)
        .setLayout(layout)
        .build();

      fullAppender.start();
      config.addAppender(fullAppender);

      // Hibernate Logger
      Appender appender = InnovaIntegrationsportalHibernateAppender.createAppender(laufid, null, null, "LISA_4711", "LI0001", laufid);

      appender.start();

      AppenderRef ref = AppenderRef.createAppenderRef(laufid, Level.ALL, null); // HIER LOGLEVEL DB EINSTELLEN
      AppenderRef refFull = AppenderRef.createAppenderRef(laufid + "FULL", Level.ALL, null); // HIER LOGLEVEL Datei einstellen
      AppenderRef[] refs = new AppenderRef[]
      {
        ref, refFull
      };

      LoggerConfig loggerConfig = LoggerConfig
        .createLogger(false, Level.ALL, laufid, "true", refs, null, config, null);
      loggerConfig.addAppender(appender, Level.ALL, null); // HIER LOGLEVEL ebenfalls einstellen
      loggerConfig.addAppender(fullAppender, Level.ALL, null); // HIER LOGLEVEL Datei einstellen
      config.addLogger(laufid, loggerConfig);

      ctx.updateLoggers();

      org.apache.logging.log4j.Logger log = LogManager.getLogger(laufid);

      for (int j = 0; j < logs; j++)
      {
        log.info("Ich bin nur eine Info und soll nur in das FullFile logging!");
        log.warn("Ich bin ein böser warning und soll in das FullFile und in das Innova Integrationsportal Hibernate Logging");
      }

      appender.stop();
      fullAppender.stop();

      config.removeLogger(laufid);
      config.removeLogger(laufid + "FULL");
      ctx.updateLoggers();
    }
    logg.trace("Fertig");
  }
}

Обновление 02.05.2019

Я перешел на регистратор JDBC и изменил базу данных.Первый тест прошел нормально, но когда я программно добавил fileappender + logger с ref в fileappender и jdbc appender из конфигурации xml, я получил пустые файлы и никаких записей в БД.

Я создал тестовый проект наgithub см .: https://github.com/stefanwendelmann/JavaLogging

Ответы [ 2 ]

2 голосов
/ 03 мая 2019

Я смотрю на: https://github.com/stefanwendelmann/JavaLogging/blob/master/src/test/java/LoggerTest.java

Я думаю, что это то, что происходит: 

private static final LoggerContext ctx ...

Configuration config = ctx.getConfiguration();

config.addAppender(fullAppender);

и вы никогда не удаляете его, поэтому он продолжает добавляться в статическое поле. Вы можете отладить и посмотреть, что внутри Log4j2. Я еще не отлажен.

Утечки памяти происходят через статические поля и обычно через загрузчики классов.

Лучший вариант - отойти от регистрации с помощью jdbc. Он предназначен для работы по-другому, а не для динамического добавления / удаления аппендеров, потому что вы должны выполнять всю работу по зооуправлению объектами. Возможно, вам будет проще просто создать шаблон фасада и скрыть всю сложность, предоставив только несколько методов для записи в БД.

0 голосов
/ 29 апреля 2019

Вероятно, Hibernate хранит объекты в своем кэше. Попробуйте evict их сразу после коммита.

...