使用Log4j2自定义Hibernate Appender发生内存泄漏 [英] Memory leak with Log4j2 custom Hibernate Appender
问题描述
我们将应用程序从自己的小型日志记录组件移至Log4j2. 在我们最大的安装程序中，该应用程序每天可以运行约60.000个工作.
We moved our application from a own small logging component to Log4j2. The application runs about 60.000 jobs per day at our biggest installation.
我们编写了自己的Appender，该Appender使用Hibernate写入了数据库(请参阅InnovaIntegrationsportalHibernateAppender).
We write our own Appender which writes using Hibernate to our DB (see InnovaIntegrationsportalHibernateAppender).
在约36小时的运行时间后，JVM因内存不足异常/错误(OOME)而崩溃，分析hprof后，我发现org.apache.logging.log4j.core类的数量为73.6MB. appender.AbstractManager
After a runtime of ~36h the JVM crashed with Out of Memory Exception/Error(OOME), analysing the hprof i saw that there is a amount of 763,5MB of the class org.apache.logging.log4j.core.appender.AbstractManager
请参阅附加的分析屏幕快照(2019-04-12 13_20_45-eclips ...)
see screenshot of the Analyse attached (2019-04-12 13_20_45-eclips...)
https://issues.apache.org/jira/browse/LOG4J2-2589
深入研究，我尝试在测试类中重构行为并分析其结果(请参见屏幕截图1).
Going deeper i tried to reconstruct the behavior in a test class and profiled its result (see screenshot-1).
对我来说似乎是内存泄漏.
Looks like a memory leak to me.
InnovaIntegrationsportalHibernateAppender
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&时，来自xml config的jdbc appender，我得到了空文件，没有数据库条目.
I moved to the JDBC logger and changed the DB. The first test was about fine, but when i programatically add a fileappender + logger with ref to the fileappender & jdbc appender from xml config, i got empty files and no db entries.
我在github上制作了一个测试项目，请参见: https://github.com/stefanwendelmann/JavaLogging
I made up a test project on github see: https://github.com/stefanwendelmann/JavaLogging
推荐答案
我正在查看: https://github.com/stefanwendelmann/JavaLogging/blob/master/src/test/java/LoggerTest.java
我认为这是正在发生的事情
I think this is what is happening:
private static final LoggerContext ctx ...
Configuration config = ctx.getConfiguration();
config.addAppender(fullAppender);
，并且您永远不会删除它，因此它会一直添加到静态字段中.您可以调试并查看Log4j2的内容.我还没有调试.
and you never remove it, so it keeps adding in the static field. You can debug and see what is inside Log4j2. I haven't debugged yet.
内存泄漏通常是通过静态字段和类加载器来实现的.
Memory leaks are coming through static fields and through classloaders usually.
最好的选择是远离使用jdbc进行日志记录.它被设计为以另一种方式工作，而不是动态添加/删除附加程序，因为您必须对对象进行所有动物保管.对于您而言，仅制作外观模式并隐藏其中的复杂性并仅公开几种在DB中进行写入的方法可能会更容易.
Best option is to move away from logging with jdbc. It is designed to work in another way and not to dynamically add/remove appenders, because you have to do all the zookeeping of objects. It may be easier for you to just make a facade pattern and hide the complexity there and only expose couple of methods for write in DB.
这篇关于使用Log4j2自定义Hibernate Appender发生内存泄漏的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！
