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/CAAdXmhprH9jgWRsAbxgVLMzRqNhCP3Xh4%2B9r%2Ba7FXdXvZHoM4w%40mail.gmail.com.
