我们将我们的应用程序从一个自己的小型日志记录组件转移到 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 记录器并更改了数据库。 第一次测试还不错，但是当我以编程方式从 xml 配置中将带有 ref 的 fileappender + logger 添加到 fileappender 和 jdbc appender 时，我得到空文件并且没有数据库条目。
我在github上做了一个测试项目见:https://github.com/stefanwendelmann/JavaLogging
最佳答案
我正在看: 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 中写入的方法可能更容易。
关于java - Log4j2 自定义 Hibernate Appender 的内存泄漏，我们在Stack Overflow上找到一个类似的问题： https://stackoverflow.com/questions/55905449/