Cache LoggerContext in log4j-slf4j-impl

[blaghed]

When integrating Slf4J with Log4J, I make use of the log4j-slf4j-impl library.

Then, typically, when logging something this will be the classical approach used:

public class MyApp {
  private static final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(MyApp.class);
  public void doSomething() {
    log.info("Hello World!");
  }
}

Following the change of heart on slf4j#declared_static, I expected that the following is just as valid of a use case (which works, but does not perform well):

public class MyApp {
  public void doSomething(String ctx) {
    final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(ctx);
    log.info("Hello World!");
  }
}

Checking the integration code on Log4J side, it seems like there are appropriate caches on all expected places to deal with this, except in Log4jLoggerFactory.java#L53-L59 (invocation coming from AbstractLoggerAdapter.java#L46 ):

    @Override
    protected LoggerContext getContext() {
        final Class<?> anchor = LogManager.getFactory().isClassLoaderDependent()
                ? StackLocatorUtil.getCallerClass(Log4jLoggerFactory.class, CALLER_PREDICATE)
                : null;
        LOGGER.trace("Log4jLoggerFactory.getContext() found anchor {}", anchor);
        return anchor == null ? LogManager.getContext(false) : getContext(anchor);
    }

In particular, the StackLocatorUtil.getCallerClass call is what causes the performance degradation.
Would it be feasible to add a cache here as well, so the anchor is remembered between calls?

[blaghed]

Is it alright if I create a suggested PR for this? I would really rather avoid the Apache "mailing list" stuff, though...
Worth noting that some of the other integrations on this project follow the same pattern, so would be nice to get a confirmation for this idea, or if Caching here is somehow against some other idea.

[vy]

@blaghed, good news is, you don't need to deal with the mailing list stuff. We would be more than happy to assist you here.

Can you explain what kind of a cache you see others implement (references please) and log4j-slf4j-impl is missing? That is, to create a Logger, we need a LoggerContext. To locate that, we need to know the enclosing class of the getLogger() call, and this is where StackLocatorUtil.getCallerClass() comes in.

Following the change of heart on slf4j#declared_static...

IMHO, you're misinterpreting the docs. It says instance variables. Your example is not an instance variable, but a method variable. This is an instance variable:

public class MyApp {
    // Note the missing `static` modifier
    private final String foo = "bar";
}

Generally speaking, Loggers are not cheap constructs, they should ideally be reused and kept in a sufficiently long-living scope.

[ppkarwasz]

The idea behind instance loggers is a nice one: if an application server shares your library between applications, instance loggers should allow you to log messages to the correct application's log file.

Unfortunately many (most?) libraries don't use instance loggers and the list also includes libraries, which are meant to be shared between applications.
For example Hibernate's EntityManagerImpl and SessionFactoryImpl, which are objects specific to each application, use static loggers and send the logs of all applications to server's global logger context.

Since Hibernate is the JPA implementation in many application servers, system administrators are used to the fact that logs specific to a given application are scattered among multiple log files.
Therefore they have no reason to configure per-application logger contexts and might as well use a single logger context.

Note also that SLF4J's standard implementation (Logback) only supports a single logger context (see LoggerContext).

Remark: I chose Hibernate as an example. Pick any implementation of a Jakarta specification and you'll find similar problems.

[blaghed]

Thanks for having a look.
After receiving your feedback and going again through the mentioned code, I can't really find a nice way to "cache" the LoggerContext in order to prevent the expensive StackWalker to always be called, at least not without some hacky approach.
Indeed, logback doesn't have this issue, so I should simply use that one instead.

Please feel free to close, and thank you for the explanation.

[ppkarwasz]

@blaghed,

After receiving your feedback and going again through the mentioned code, I can't really find a nice way to "cache" the LoggerContext in order to prevent the expensive StackWalker to always be called, at least not without some hacky approach. Indeed, logback doesn't have this issue, so I should simply use that one instead.

As @vy explained, the expensive StackWalker call is necessary to return a different Logger instance depending on the caller of LoggerFactory#getLogger(). If you eliminate the call (e.g. by switching to Logback) you lose all advantages that instance loggers have over static loggers.

The trick of using instance loggers is to manage the cost of Logger creation by assigning the logger to a field:

public class MyService {
  private final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(MyApp.class);
  public void doSomething() {
    log.info("Hello World!");
  }
}

This way if both application A and application B instantiate MyService, they could get different Logger instances, configured to log to different appenders.

The choice of using instance loggers implies however other limitations to your library. You can not use logging in classical "utility" classes:

public final class MyUtil {
    private static final Logger log = LoggerFactory.getLogger(MyUtil.class);

    public static String transform(String value) {
        log.debug("Transforming {}.", value);
    }

You need to either to pass Logger as parameter to the utility class:

public final class MyUtil {
    public static String transform(String value, Logger log) {
        log.debug("Transforming {}.", value);
    }

or replace static methods with instance methods:

public final class MyUtil {
    private final Logger log = LoggerFactory.getLogger(MyUtil.class);

    public String transform(String value) {
        log.debug("Transforming {}.", value);
    }

Remark: If you want to emulate Logback's behavior, you can also set the log4j2.contextSelector configuration property to org.apache.logging.log4j.core.selector.BasicContextSelector. There will be a single logger context for the entire application, so the caller lookup will not be necessary.

[blaghed]

While I appreciate what the Logger Context is trying to accomplish, I have to say that adding such a heavy initialization time to instances is not ok, at least not for me (fyi, we are getting 2.8s extra time per instance just from the StackWalker).

I could sort of justify this cost (to myself) if this logic was needed only on the very first instance being created for a particular logger class -- similar to what happens with the static approach.
But that this happens on every instance ... then this would only really work in limited situations, like Singletons or Pooled Objects.

It is nice that there is a setting to change the logic to a single context, but then (1) the abstraction I get from using Slf4J API is meaningless and (2) it becomes awkward for a library to suggest this setting on the application using it in case it is backed by Log4J.

Having said this, I unfortunately don't really have a solution to propose here that wouldn't potentially break the idea behind this, so I feel like I accidentally just came here to complain -- Sorry for that, my initial look at the code really made it seem like it was simple tweak.