Log4j2自定义Hibernate Appender导致内存泄漏问题

Question

Log4j2自定义Hibernate Appender导致内存泄漏问题

10

我们将应用程序从自己的小型日志组件迁移到Log4j2。该应用程序在我们最大的安装中每天运行约60,000个作业。我们编写了自己的Appender，并使用Hibernate将其写入我们的数据库（请参见InnovaIntegrationsportalHibernateAppender）。

运行约36小时后，JVM崩溃并显示内存不足异常/错误（OOME）。分析hprof后，我发现org.apache.logging.log4j.core.appender.AbstractManager类的数量为763.5MB。

有关分析的截图，请参见附件（2019-04-12 13_20_45-eclips...）。

请参见https://issues.apache.org/jira/browse/LOG4J2-2589。

进一步深入研究后，我尝试在测试类中重现此行为并对其结果进行了分析（请参见screenshot-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");
  }
}

更新 2019 年 02 月 05 日

我切换到 JDBC 日志记录器并改变了数据库。第一个测试运行良好，但当我通过 XML 配置编程方式添加 fileappender + logger，并引用文件附加程序和 jdbc 追加程序时，我得到了空文件和没有数据库条目。

我在 GitHub 上创建了一个测试项目，请参见：https://github.com/stefanwendelmann/JavaLogging

- Stefan Höltker

1

使用Hibernate/JPA写入表格？那是过度杀伤力了。我会使用简单的JDBC连接（如果您是Spring用户，则使用JdbcTemplate）。我希望看到池化的JDBC连接。您把这个问题搞得太复杂了。 - duffymo

@duffymo 感谢您的澄清。最初的问题是，我在系统中有大约200个不同版本的作业。所有作业都有两个参数用于Loglevel：Logelevel File和Logevel DB。因此，现在的目标是通过jobid编程生成一个Logger，该Logger引用jdbc appender，并且在ref中是Loglevel DB。第二个目标是通过编程方式生成一个File Appender，我可以从同一个Logger中引用该Appender并使用Loglevel File。 - Stefan Höltker

2个回答

0

很可能，Hibernate 将对象保存在其缓存中。尝试在提交后立即使用 evict 将它们清除。

- Alexander Pavlov

谢谢您的建议。我在提交后添加了em.clear()，但仍然没有改变。此外，我认为em.close()已经关闭了em，所有引用em的对象都可以被垃圾回收。 - Stefan Höltker

我不记得Hibernate的细节 - 它是否默认具有二级缓存？或者您可以为应用程序或实体启用它吗？确保日志记录不会添加到二级缓存中。 - Alexander Pavlov

我是指“你可能已经启用了它” - Alexander Pavlov

网页内容由stack overflow 提供, 点击上面的

可以查看英文原文，
原文链接

- Borislav Markov · Accepted Answer

我正在查看： 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记录日志。它设计用于以另一种方式工作，而不是动态添加/删除附加程序，因为您必须对对象进行所有的动物园保护。对您来说，可能更容易创建一个Facade模式，并在其中隐藏复杂性，并仅公开几个用于写入数据库的方法。

"Original Answer"翻译成"最初的回答"