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/CAAdXmhqN-VmvKrKbS%3D_-ozaWfNveE254ozwSULm1yFDzWM23Cw%40mail.gmail.com.
