It took me some time to figure out how to run the tests. For one thing, it
didn't like the fact that I wasn't using the default repository (I wasn't
using .m2/repository in my home directory). Eventually, I got it working by
using that default repository.
Anyway, I'm still working on writing a test.
In the meantime, several observations (I noted #2 when originally writing
my patch, but did not change it):
1. Log4J1 in pax-logging-api behaves differently from SLF4J in
pax-logging-api in your Log4JMemoryTest.
If you take the Log4JMemoryTest and *use the Log4J1 API instead of
SLF4J API* in the MyClass to get the nonStaticLogger, then *you end up with
1,000,000 Loggers within m_loggers in org.apache.log4j.Logger in
pax-logging-api*. To make this change, I changed only the MyClass
constructor, to be:
public MyClass(String name) {
this.nonStaticLogger = Logger.getLogger(name);
}
and changed the imports from
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
to
import org.apache.log4j.Logger;
*This behavior is what my patch addresses. With my patch, there were at
maximum 1,535 entries in m_loggers. (The 1,535 varies as garbage collection
is not deterministic, but 1,535 is still better than 1,000,000.)*
===================
===================
2. Explanation of #1 (difference in whether or not the new logger instance
is stored in m_loggers when m_paxLogging is not null):
- SLF4J in pax-logging-api:
In org.ops4j.pax.logging.slf4j.Slf4jLoggerFactory getLogger, *if
m_paxLogging is not null* (Line 95), then a new Slf4jLogger is created, *but
the Slf4jLogger is not stored in m_loggers.*
- Log4J1 in pax-logging-api*: *In org.apache.log4j.Logger getLogger, the
new Logger created on line 140 is *stored in m_loggers regardless of
whether m_paxLogging is null or not null.*
- Others in pax-logging-api: The other log implementations (Apache
Commons Logging in org.apache.commons.logging.LogFactory, JULI Logging in
org.apache.juli.logging.LogFactory, Avalon Logging in
org.ops4j.pax.logging.avalon.AvalonLogFactory) *behave like
org.apache.log4j.Logger*, and *store new logger instance in m_loggers
regardless of whether m_paxLogging is null or not null.*
-
*Only org.ops4j.pax.logging.log4jv2.Log4jv2LoggerContext checks for
existence of a logger with the same name before creating a new logger to
put in the loggers map. *
===================
===================
I'll look at writing a test to match my usage with what I called "groups".
Markers as the Ralph from Log4J2 suggested may help (I haven't tried how
that works yet---I've just been using the existing logging we've had for
years). However, without changing our own logging, the change in behavior
of pax-logging-api between the very old 1.6.1 and the new 1.10.5 because of
the change in the order of WeakHashMap parameters definitely had a negative
effect on the memory behavior of pax-logging-api. Even if the
TrackingLogger using the same name sticks around after we're done with that
(I can deal with that), the fact that the pax-logging-api holds on to
things longer doesn't seem too good. I guess since I now use
pax-logging-api Log4J2 instead of pax-logging-api Log4J1, that does help,
because Log4J2 in pax-logging-api only creates new instances for new names.
Log4J1, as stated in #1 above, creates and holds onto new instances
forever, even if the name is re-used.
Thanks again,
Monica
On Saturday, March 14, 2020 at 6:13:14 AM UTC-4, Grzegorz Grzybek wrote:
>
> Hello again
>
> I've backported 3 "memory" tests from Pax Logging 1.11.x to
> https://github.com/ops4j/org.ops4j.pax.logging/commits/pax-logging-1.10.x
>
> The test (e.g., org.ops4j.pax.logging.it.Log4J2MemoryTest) does this:
>
> @Test
> public void memoryIssues() throws IOException {
> LOG.info("Starting");
> String[] loggerNames = new String[10000];
> for (int i = 0; i < 10000; i++) {
> loggerNames[i] = UUID.randomUUID().toString();
> }
> for (int i = 0; i < 1000000; i++) {
> if (i % 10000 == 0) {
> LOG.info("iteration {}", i);
> System.gc();
> }
> new Log4J2MemoryTest.MyClass(loggerNames[i % 10000]).run();
> }
> LOG.info("Done");
> }
>
> private static class MyClass {
> private Logger nonStaticLogger;
>
> public MyClass(String name) {
> this.nonStaticLogger = LoggerFactory.getLogger(name);
> }
>
> public void run() {
> // running a method
> nonStaticLogger.trace("Hello!");
> }
> }
>
> You see - million logger instances using 10000 different unique names.
> What I'm not sure about is the "group" you've mentioned - are the new
> groups reusing logger names? or each "group" introduces completely new set
> of loggers?
>
> I checked the result in heap dump and I got:
>
> [image: image.png]
>
> which means that in pax-logging 1.10.6-SNAPSHOT (not changed comparing to
> 1.10.5) there's exactly 10000 TrackingLoggers (+11 for non-test related
> ones).
>
> The test uses SLF4J facade to get pax logging loggers.
>
> May I ask you to change the tests, so I can try reproducing your problem?
> I agree that using WeakHashMap helps, but if the number of unique logger
> names doesn't increase endlessly, I think it's not necessary to use
> WeakHashMaps.
>
> BTW, I've closed https://issues.apache.org/jira/browse/LOG4J2-2806 even
> if I was able to ensure proper weak-reference behavior inside Log4J2.
>
> Thanks for great cooperation!
>
> regards
> Grzegorz Grzybek
>
--
--
------------------
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/e2090a5d-ad39-49d6-8a6d-c9dd8869a1b1%40googlegroups.com.
