[
https://issues.apache.org/jira/browse/LOG4J2-2589?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17078083#comment-17078083
]
Stefan Höltker commented on LOG4J2-2589:
----------------------------------------
Ok i will have a look on the AbstractConfiguration,
i maintain our legacy tool wich is a scheduler for jobs written in java.
The jobs and the scheduler are running inside one jvm.
All jobs have an running id (german laufid).
All jobs have a config stored in db.
All job runs create a log inside the db.
We have a own JPAUtil on top of Hibernate where we get the configs for DB
Connection from.
InnovaIntegrationsportalHibernateAppender as seen above uses this JPAUtil and
writes the log from log4j to the DB.
The primary key to the existing table is SCHNITTSTELLE (Interface / Job Class),
VERSION (Job definition), Laufid (Running id).
We added the LOGLEVEL to the Table.
I use the Custom Appender to inject the primary key for the logging table in
the db.
The Log Config is inside the the job config inside the db, there we config the
loglevel for the loggingappender to the db and loglevel for the fileappender.
Our biggest installation is running ~80.000 Jobs per day.
All around we run about 2.500.000 jobs per week.
> 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
>
>
> 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)
