[
https://issues.apache.org/jira/browse/LOG4J2-2589?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17078099#comment-17078099
]
Stefan Höltker commented on LOG4J2-2589:
----------------------------------------
The AbstractConfiguration helped to "flatten-the-curve" as one say today :D of
the used Heap (left side with AbstractConfiguration and removeAppender(), right
side without)
!screenshot-3.png!
> Potential Memory Leak
> ----------------------
>
> Key: LOG4J2-2589
> URL: https://issues.apache.org/jira/browse/LOG4J2-2589
> Project: Log4j 2
> Issue Type: Bug
> Components: API, Appenders, Configurators, Core
> Affects Versions: 2.11.2
> Environment: Windows 10
> openjdk version "1.8.0_202"
> OpenJDK Runtime Environment
> (AdoptOpenJDK)(build 1.8.0_202-b08)
> OpenJDK 64-Bit Server VM (AdoptOpenJDK)(build 25.202-b08, mixed mode)
> Reporter: Stefan Höltker
> Priority: Major
> Attachments: 2019-04-12 13_20_45-eclipse-workspace -
> C__Daten_analyse_ems_prd_20190409_java_pid11448.hprof - Ecli.png,
> screenshot-1.png, screenshot-2.png, screenshot-3.png
>
>
> 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.
> We write our own Appender wich writes wit Hibernate to our DB (see
> InnovaIntegrationsportalHibernateAppender).
> After a runtime of ~36h the JVM crashed with OOME, analysing the hprof i saw
> that there is a amount of 763,5MB of the class
> org.apache.logging.log4j.core.appender.AbstractManager
> see screenshot of the Analyse attached (2019-04-12 13_20_45-eclips...)
>
> 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
> {code:java}
> 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;
> }
> }
> }
> {code}
>
> Test Class for Profiling
> {code:java}
> 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.getRootLogger().removeAppender(laufid);
> config.getRootLogger().remove(laufid+"FULL");
> ctx.updateLoggers();
> }
> logg.trace("Fertig");
> }
> }
> {code}
>
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
