Hello again After little more investigation and careful usage of WeakHashMaps and WeakReferences I managed to create 1M of unique loggers on -Xmx128M that were correctly garbage collected in:
- pax-logging-log4j1 - pax-logging-log4j2 (after fixing the problem described in https://issues.apache.org/jira/browse/LOG4J2-2806) However it CAN'T be done easily with Logback, because the child loggers (and UUID-named logger is child of root logger) are held on a list... there's ONE test faling were I check what happens with a reference to LogService after pax-logging-api and pax-logging-log4j2 are refreshed while the test method is running... All findings will be at https://ops4j1.jira.com/browse/PAXLOGGING-311. regards Grzegorz Grzybek pt., 13 mar 2020 o 16:11 Grzegorz Grzybek <[email protected]> napisał(a): > 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/CAAdXmhrr%3DgcivPCGeZB8OmaJR4QyAC%3DwiZo6zkCQ3AEu78cZHA%40mail.gmail.com.
