Unfortunately I don't think there's much we can do... http://logging.apache.org/log4j/2.x/manual/usage.html#StaticVsNonStatic says:
*Once a Logger is created it will not be deleted until the LoggerContext it > is associated with is deleted. Typically, this will only happen when the > application is shut down or un-deployed. Each call to getLogger with the > same logger name will return the same Logger instance.* I even changed LoggerContext to use LoggerRegistry (log4j2) with org.apache.logging.log4j.spi.LoggerRegistry.WeakMapFactory), but this doesn't change anything - the created map uses weak key (strings - logger names), but the same key (string) is kept in a Logger instance - the value of WeakHashMap - this breaks WeakHashMap contract: *Thus care should be taken to ensure that value objects do not strongly > refer to their own keys* > Monica - which pax-logging backed are you using - Log4j2? Did you check a heapdump? How many actual different loggers do you create? In my test, I tried creating 1,000,000 loggers with unique names and used -Xmx128M. OOME (heap) happened after ~300K loggers created. The only change I needed in Pax Logging 1.11+ was change of org.ops4j.pax.logging.OSGIPaxLoggingManager#m_loggers to WeakHashMap. I don't think there's a need to reverse back the key-value order - especially in 1.11+. Is there a chance to analyze a heapdump of your application? regards Grzegorz Grzybek regards Grzegorz Grzybek pt., 13 mar 2020 o 15:22 Grzegorz Grzybek <[email protected]> napisał(a): > I've created https://ops4j1.jira.com/browse/PAXLOGGING-311 and I'm > checking it. > > But simple switching org.ops4j.pax.logging.OSGIPaxLoggingManager#m_loggers > to WeakHashMap gave me OOME where the problem was not the order of > key-value in the map (TrackingLoggers were correctly disposed, as well as > those Pax Web crafted String keys). The problem is: > [image: image.png] > > So Log4j2 itself holds huge number of non-GCed loggers. > > I'm checking what can be done with it. > > regards > Grzegorz Grzybek > > > pt., 13 mar 2020 o 13:50 Monica Ron <[email protected]> napisał(a): > >> I'm glad you can see what I saw. :) >> >> I attached my patch to this post. I first downloaded the 1.10.x branch, >> and made changes. The patch is the output from 'git diff'. To build what I >> have using this patch, you can do the following: >> >> git init >> git remote add origin https://github.com/ops4j/org.ops4j.pax.logging.git >> git fetch origin >> git merge 398a8234c6c6ef831e64bd458263c637795a4087 >> git apply PaxLoggingWeakHashMapChange.patch >> >> And then build with Maven. I only replaced the pax-logging-api.jar, not >> any of the other ones. We are using the pax-logging-log4j2-1.10.5.jar and >> my custom jar made with this patch. >> >> I don't know if there are any other memory issues, but this helped with >> some of them. >> >> Monica >> >> On Friday, March 13, 2020 at 7:53:41 AM UTC-4, Grzegorz Grzybek wrote: >>> >>> Hello >>> >>> I did simple test: >>> >>> @Test >>> public void memoryIssues() throws IOException { >>> for (int i = 0; i < 1_000_000; i++) { >>> new MyClass().run(); >>> } >>> LOG.info("Done"); >>> } >>> private static class MyClass { >>> private Logger nonStaticLogger = LoggerFactory.getLogger( >>> *UUID.randomUUID().toString()*); >>> public void run() { >>> // running a method >>> nonStaticLogger.trace("Hello!"); >>> } >>> } >>> >>> And I got: >>> >>> OSGIPaxLoggingManager@4270 >>> tracker: org.osgi.util.tracker.ServiceTracker = >>> {org.osgi.util.tracker.ServiceTracker@4271} >>> m_logService: org.ops4j.pax.logging.PaxLoggingService = >>> {org.ops4j.pax.logging.log4j2.internal.PaxLoggingServiceImpl$1ManagedPaxLoggingService@4249} >>> >>> m_logServiceRef: org.osgi.framework.ServiceReference = >>> {org.apache.felix.framework.ServiceRegistrationImpl$ServiceReferenceImpl@4272} >>> "[org.osgi.service.log.LogService, org.osgi.service.log.LoggerFactory, >>> org.ops4j.pax.logging.PaxLoggingService]" >>> m_loggers: java.util.Map = {java.util.HashMap@4273} size = *1000014* >>> >>> "org.ops4j.pax.logging.slf4j.Slf4jLogger#516419e9-4bbc-4e5c-9518-204751cb669c#18" >>> -> {org.ops4j.pax.logging.internal.TrackingLogger@4379} >>> >>> "org.ops4j.pax.logging.slf4j.Slf4jLogger#8536c55c-631a-4fd1-8118-78b1eeda329a#18" >>> -> {org.ops4j.pax.logging.internal.TrackingLogger@4381} >>> >>> "org.ops4j.pax.logging.slf4j.Slf4jLogger#e4da2934-f756-41dc-ac02-b9a9d4290de5#18" >>> -> {org.ops4j.pax.logging.internal.TrackingLogger@4383} >>> >>> "org.ops4j.pax.logging.slf4j.Slf4jLogger#1c40dbe4-2475-4634-ba95-54c5bf2a2a5b#18" >>> -> {org.ops4j.pax.logging.internal.TrackingLogger@4385} >>> >>> "org.ops4j.pax.logging.slf4j.Slf4jLogger#0d80d39b-63aa-4719-b5ce-0265449cc924#18" >>> -> {org.ops4j.pax.logging.internal.TrackingLogger@4387} >>> >>> "org.ops4j.pax.logging.slf4j.Slf4jLogger#919916db-6aef-4b77-a48e-7fccce2f8740#18" >>> -> {org.ops4j.pax.logging.internal.TrackingLogger@4389} >>> ... >>> >>> m_loggers had million+ entries - definitely not good ;) I'm working on >>> definitive solution. >>> >>> regards >>> Grzegorz Grzybek >>> >>> śr., 11 mar 2020 o 18:44 Monica Ron <[email protected]> napisał(a): >>> >>>> Thanks. I can send my patch, if it would help. >>>> >>>> Monica >>>> >>>> >>>> On Wednesday, March 11, 2020 at 1:08:48 PM UTC-4, Grzegorz Grzybek >>>> wrote: >>>>> >>>>> Hello >>>>> >>>>> Great analysis - as always. I'll have a look very soon! >>>>> >>>>> regards >>>>> Grzegorz Grzybek >>>>> >>>>> śr., 11 mar 2020 o 16:39 Monica Ron <[email protected]> napisał(a): >>>>> >>>>>> Hi. I know it's been a while since this was last sent. The change in >>>>>> order of the generic parameters of the WeakHashMap definitely caused a >>>>>> change in memory behavior, and thus a memory leak in our application. >>>>>> >>>>>> In some of our code, we have: >>>>>> public abstract class AbstractBase { >>>>>> protected Logger logger = LogManager.getLogger(getClass()); >>>>>> >>>>>> public void doSomething() { >>>>>> logger.debug("Base method."); >>>>>> } >>>>>> } >>>>>> >>>>>> And then we create instances of subclasses: >>>>>> public class MyClassAAA extends AbstractBase { >>>>>> public void someMethodA() { >>>>>> logger.debug("Something."); >>>>>> } >>>>>> } >>>>>> >>>>>> public class MyClassBBB extends AbstractBase { >>>>>> public void someMethodB() { >>>>>> logger.debug("Something."); >>>>>> } >>>>>> } >>>>>> >>>>>> The inherited logger gets the name of the subclass, so you can see in >>>>>> the log whether an instance of MyClassAAA did the logging or MyClassBBB >>>>>> did >>>>>> the logging. This is a common usage of loggers from what I can tell. Not >>>>>> all loggers are static. We also create some names dynamically (so we get >>>>>> "MyClassAAA-1" and "MyClassAAA-2"), so that we can distinguish multiple >>>>>> instances of it, so we can track data through a single thread (where we >>>>>> might have 5 threads, each running a separate instance of the MyClassAAA >>>>>> class), for example. >>>>>> >>>>>> With the nature of our program, instances of some of these classes >>>>>> with inherited loggers come and go frequently. Some are very short lived >>>>>> (an object is created, some processing is performed on it, and the >>>>>> instance >>>>>> is then dropped and garbage-collected). Some may live for days or for a >>>>>> few >>>>>> weeks (to consume data from an ActiveMQ queue), but then are removed, >>>>>> never >>>>>> to be used again. With the old Pax 1.6.1, because the WeakHashMap was >>>>>> effectively "WeakHashMap<Logger, String>" (even though generic >>>>>> parameters weren't specified, this was how it was used), the logger would >>>>>> be garbage-collected when the instance of our class was >>>>>> garbage-collected. >>>>>> >>>>>> With the current behavior of Pax Logging 1.10.5 with the generic >>>>>> parameters switched to "WeakHashMap<String, Logger>" (and similar >>>>>> for other logging types), each instance of a class with an inherited >>>>>> logger >>>>>> may get a new instance of the logger, and those loggers are never >>>>>> garbage-collected. I don't know the behavior of the real Log4J, Log4J2, >>>>>> SLF4J, JCL, etc. in terms of memory management in our use case, but since >>>>>> our application has always used Pax Logging, the new behavior is >>>>>> definitely >>>>>> a change, and creates a memory leak. >>>>>> >>>>>> I downloaded the 1.10.x branch (commit >>>>>> 398a8234c6c6ef831e64bd458263c637795a4087) and changed the following >>>>>> classes >>>>>> to switch the WeakHashMap parameters back to the original <Logger, >>>>>> String>: >>>>>> >>>>>> pax-logging-api/src/main/java/org/apache/commons/logging/LogFactory.java >>>>>> pax-logging-api/src/main/java/org/apache/juli/logging/LogFactory.java >>>>>> pax-logging-api/src/main/java/org/apache/log4j/Logger.java >>>>>> >>>>>> pax-logging-api/src/main/java/org/ops4j/pax/logging/avalon/AvalonLogFactory.java >>>>>> >>>>>> pax-logging-api/src/main/java/org/ops4j/pax/logging/slf4j/Slf4jLoggerFactory.java >>>>>> >>>>>> I also changed this: >>>>>> >>>>>> pax-logging-api/src/main/java/org/ops4j/pax/logging/log4jv2/Log4jv2LoggerContext.java >>>>>> >>>>>> to use a WeakHashMap<Log4jv2Logger, String> instead of a >>>>>> ConcurrentHashMap<String, Log4jv2Logger>. That one hadn't ever been >>>>>> ConcurrentHashMap<Log4jv2Logger, String>, but changing it to a >>>>>> WeakHashMap<Log4jv2Logger, String> improved the memory cleanup when our >>>>>> instances were garbage-collected (since our upgraded code uses Log4jv2 as >>>>>> an API instead of Log4J, but we are still using the PAX Logging API and >>>>>> Service at runtime). I synchronized the loggers access in >>>>>> Log4jv2LoggerContext, since I no longer had a ConcurrentHashMap. >>>>>> >>>>>> For now, I have built a local copy of pax-logging-api with changes to >>>>>> the above files, and it has helped our memory management compared to the >>>>>> 1.10.5 release. >>>>>> >>>>>> Regards, >>>>>> Monica >>>>>> >>>>>> On Tuesday, January 7, 2020 at 4:55:57 AM UTC-5, Grzegorz Grzybek >>>>>> wrote: >>>>>>> >>>>>>> Hello >>>>>>> >>>>>>> sob., 4 sty 2020 o 02:58 Monica Ron <[email protected]> napisał(a): >>>>>>> >>>>>>>> The new code works for me. Once we deploy our wars, we don't >>>>>>>> generally re-deploy until we have a new release, and we usually >>>>>>>> shutdown >>>>>>>> the Glassfish/Payara domain to do that deployment. So, shutting down >>>>>>>> the >>>>>>>> JVM obviously clears all memory. >>>>>>>> >>>>>>>> I'm not really worried (I think our code should be fine, based on >>>>>>>> how we use it), but I do have one question: >>>>>>>> Hasn't the garbage-collection behavior changed by changing the >>>>>>>> original WeakHashMap<Logger, String> (if generics had been added >>>>>>>> to the code as it is in 1.10.x [with separate m_loggers for each >>>>>>>> logging >>>>>>>> API] without otherwise changing underlying code) to WeakHashMap<String, >>>>>>>> List<Logger>>? >>>>>>>> >>>>>>> >>>>>>> Actually both cases are a bit incorrect IMO... My new case (weak map >>>>>>> of string → list<Logger>) only ensures that we don't loose loggers, but >>>>>>> doesn't do any weak-functionality (because the logger strongly >>>>>>> references >>>>>>> key anyway). Previous case (weak map of logger → string) was better, but >>>>>>> keys (loggers) were mostly used by strong references anyway throughout >>>>>>> the >>>>>>> code - because most libraries use "logger log = >>>>>>> loggerFactory.getLogger()" >>>>>>> idiom all the time - and mostly using static references, so the weak >>>>>>> keys >>>>>>> of old WeakHashMap<Logger, String> were not released anyway. >>>>>>> >>>>>>> In pax-logging 1.11.x+, the List<Logger> is definitely not weak, but >>>>>>> activator of pax-logging-api explicitly clears this list when >>>>>>> everything is >>>>>>> done, so it's even better (IMO). >>>>>>> >>>>>>> >>>>>>>> >>>>>>>> For 1.11.x, the change made for PAXLOGGING-307 was: >>>>>>>> public static final Map<String, PaxLoggingManagerAwareLogger> >>>>>>>> m_loggers = new WeakHashMap<String, PaxLoggingManagerAwareLogger> >>>>>>>> (); >>>>>>>> became: >>>>>>>> public static final List<PaxLoggingManagerAwareLogger> m_loggers = >>>>>>>> new LinkedList<>(); >>>>>>>> >>>>>>>> Based on the pre-generics code, the 1.11.x map should have had the >>>>>>>> logger as the key: >>>>>>>> public static final Map<PaxLoggingManagerAwareLogger, String> >>>>>>>> m_loggers = new WeakHashMap<PaxLoggingManagerAwareLogger, String> >>>>>>>> (); >>>>>>>> >>>>>>>> >>>>>>>> For a WeakHashMap, if all of the other references to the key got >>>>>>>> discarded elsewhere, the key-value pair automatically gets discarded >>>>>>>> from >>>>>>>> the WeakHashMap, correct? So, if an instance of a class with a >>>>>>>> reference to >>>>>>>> a PaxLoggingManagerAwareLogger (or Logger [of whatever logging API you >>>>>>>> used] for 1.10.x) got garbage-collected, the logger would also have >>>>>>>> been >>>>>>>> removed from m_loggers, correct? This automatic removal from m_loggers >>>>>>>> will >>>>>>>> not occur with a List<PaxLoggingManagerAwareLogger> (for 1.11.x), >>>>>>>> or with a WeakHashMap<String, List<Logger>> (for 1.10.x). >>>>>>>> >>>>>>> >>>>>>> For 1.11.x it's removed explicitly here: >>>>>>> https://github.com/ops4j/org.ops4j.pax.logging/blob/logging-1.11.4/pax-logging-api/src/main/java/org/ops4j/pax/logging/internal/Activator.java#L143-L155 >>>>>>> >>>>>>> For 1.10.x, taking into account the fact that loggers are created >>>>>>> once and mostly held statictly, it's not a big issue IMO. >>>>>>> >>>>>>> >>>>>>>> >>>>>>>> As I said, I don't think this will be a problem for us, but it may >>>>>>>> be something to consider, if the original WeakHashMap was by intention >>>>>>>> to >>>>>>>> help with garbage collection. By this time, no one may know what the >>>>>>>> original intention is... >>>>>>>> >>>>>>> >>>>>>> :) >>>>>>> >>>>>>> regards >>>>>>> Grzegorz Grzybek >>>>>>> >>>>>>> >>>>>>>> Thanks again, >>>>>>>> Monica >>>>>>>> >>>>>>>> >>>>>>>> -- >>>>>>>> -- >>>>>>>> ------------------ >>>>>>>> OPS4J - http://www.ops4j.org - [email protected] >>>>>>>> >>>>>>>> --- >>>>>>>> You received this message because you are subscribed to the Google >>>>>>>> Groups "OPS4J" group. >>>>>>>> To unsubscribe from this group and stop receiving emails from it, >>>>>>>> send an email to [email protected]. >>>>>>>> To view this discussion on the web visit >>>>>>>> https://groups.google.com/d/msgid/ops4j/d4a9fb64-9389-4d08-9b3e-8a735b57d6ef%40googlegroups.com >>>>>>>> <https://groups.google.com/d/msgid/ops4j/d4a9fb64-9389-4d08-9b3e-8a735b57d6ef%40googlegroups.com?utm_medium=email&utm_source=footer> >>>>>>>> . >>>>>>>> >>>>>>> -- >>>>>> -- >>>>>> ------------------ >>>>>> OPS4J - http://www.ops4j.org - [email protected] >>>>>> >>>>>> --- >>>>>> You received this message because you are subscribed to the Google >>>>>> Groups "OPS4J" group. >>>>>> To unsubscribe from this group and stop receiving emails from it, >>>>>> send an email to [email protected]. >>>>>> To view this discussion on the web visit >>>>>> https://groups.google.com/d/msgid/ops4j/fdd62aeb-e3ae-4d33-879f-6c54d4ddce43%40googlegroups.com >>>>>> <https://groups.google.com/d/msgid/ops4j/fdd62aeb-e3ae-4d33-879f-6c54d4ddce43%40googlegroups.com?utm_medium=email&utm_source=footer> >>>>>> . >>>>>> >>>>> -- >>>> -- >>>> ------------------ >>>> OPS4J - http://www.ops4j.org - [email protected] >>>> >>>> --- >>>> You received this message because you are subscribed to the Google >>>> Groups "OPS4J" group. >>>> To unsubscribe from this group and stop receiving emails from it, send >>>> an email to [email protected]. >>>> To view this discussion on the web visit >>>> https://groups.google.com/d/msgid/ops4j/abc30993-9caf-461a-a675-50cfa95ddf03%40googlegroups.com >>>> <https://groups.google.com/d/msgid/ops4j/abc30993-9caf-461a-a675-50cfa95ddf03%40googlegroups.com?utm_medium=email&utm_source=footer> >>>> . >>>> >>> -- >> -- >> ------------------ >> OPS4J - http://www.ops4j.org - [email protected] >> >> --- >> You received this message because you are subscribed to the Google Groups >> "OPS4J" group. >> To unsubscribe from this group and stop receiving emails from it, send an >> email to [email protected]. >> To view this discussion on the web visit >> https://groups.google.com/d/msgid/ops4j/27968583-d090-43a0-b963-12a923c31fd4%40googlegroups.com >> <https://groups.google.com/d/msgid/ops4j/27968583-d090-43a0-b963-12a923c31fd4%40googlegroups.com?utm_medium=email&utm_source=footer> >> . >> > -- -- ------------------ OPS4J - http://www.ops4j.org - [email protected] --- You received this message because you are subscribed to the Google Groups "OPS4J" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. To view this discussion on the web visit https://groups.google.com/d/msgid/ops4j/CAAdXmhpQq0b0q8Z_vAXncZj2v5qBVKcEyn_p3hquQVOENoo3GQ%40mail.gmail.com.
