Log4j2 自定义 Hibernate Appender 的内存泄漏

Question

我们将应用程序从自己的小型日志记录组件移至 Log4j2。 在我们最大的安装中，该应用程序每天运行大约 60.000 个作业。

我们编写自己的 Appender，它使用 Hibernate 写入我们的数据库（请参阅 InnovaIntegrationsportalHibernateAppender）。

在运行约 36 小时后，JVM 因内存不足异常/错误 (OOME) 而崩溃，分析 hprof 我看到 org.apache.logging.log4j.core 类的数量为 763.5MB。 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 记录器并更改了数据库。 第一次测试还不错，但是当我以编程方式将带有 ref 的 fileappender + logger 从 xml config 添加到 fileappender 和 jdbc appender 时，我得到了空文件并且没有 db 条目。

我在github上做了一个测试项目见：https://github.com/stefanwendelmann/JavaLogging

Answer 1

我在看： 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 进行日志记录。它旨在以另一种方式工作，而不是动态添加/删除附加程序，因为您必须完成所有对象的动物园管理。您可能更容易只制作一个外观模式并隐藏那里的复杂性，并且只公开几个用于在 DB 中写入的方法。

Answer 2

Hibernate 可能会将对象保存在其缓存中。提交后立即尝试evict他们。