logging-log4j-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Shawn Heisey <apa...@elyograg.org>
Subject Questions about switching to async and other performance-related config
Date Mon, 06 Aug 2018 16:00:24 GMT
I'm a committer on the Solr project.  Recently we completed an upgrade
to log4j2, a change that we're very happy with.  The "rotate on startup"
option has greatly simplified our start scripts, and we're running a
version with full community support.


Now we're contemplating switching to async, which is apparently how
log4j2 achieves "insane performance."


I've been reading what I can find about how to switch, but the docs seem
to indicate at least two ways to do it, and I can't tell by looking at
those which approach is better.  At the end of this message is a paste
URL with the log4j2 config that Solr ships.  Any suggestions for
improving the config are appreciated.

What are the potential problems of async logging?  I'm guessing that
there's a possibility that messages will get logged out of order if it
takes longer to process one message than it does to process another one
that happens immediately afterwards.  If this can happen, would the
timestamps still be accurate even if logged out of order?  Although even
with millisecond precision, it's likely that they would have the same
visible timestamp, so most of the time that might not actually be useful.

I was reading about mixing async and sync loggers, and wondering whether
that would solve any out-of-order problems for critical log messages.
Thinking mainly about having WARN and ERROR use sync.  A properly
functioning Solr server with a modern config logs almost nothing at WARN
or ERROR.  Typically even if the config isn't modern, a well-functioning
server usually only logs such messages at startup or index reload.  The
vast majority of what Solr usually logs is at INFO.  There's a fair
amount of DEBUG in the code, and possibly even some at a lower level,
but the logging threshold defaults to INFO.  Solr can be a little noisy
in its logs, but we are taking steps to reduce the verbosity.  If the
server is particularly busy, it can generate a lot of logs quickly.

Beyond that, I have a question about other ways that we can improve
performance.  I've been reading that the use of %C or %c (we use %c{.1}
in the config) causes performance to drag, because the class must be
looked up.  But from what I can tell, it is not actually using the class
name in the log output ... it's using the *Logger* name.  The first line
of the below is at the top of most of the classes in Solr.  All three of
these lines are in one particular class -- SolrCore:

  private static final Logger log =
  private static final Logger requestLog =
LoggerFactory.getLogger(MethodHandles.lookup().lookupClass().getName() +
  private static final Logger slowLog =
LoggerFactory.getLogger(MethodHandles.lookup().lookupClass().getName() +

The parameter in the first "getLogger" call is a Class, but the
parameter in the other two is a String.  Does the performance impact for
%c apply to String-based loggers or just Class-based loggers?  If the
performance impact doesn't apply to a String-based logger, maybe we
could just add .getName() to the first line.  If necessary, we could
switch to including the class name in each log message from a static
string in the class... would the performance impact of doing that be
worth the time and the massive patch?  I do like the flexibility of
having log4j shorten the class name with the suffix on our "%c{.1}"
pattern, which would be challenging to make configurable inside Solr itself.

Keep in mind that Solr is using slf4j API calls, not log4j directly. 
Our slf4j binding is log4j2.

At the following pastes are an example of the logging output and the
log4j2 config that produced it:



To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org

View raw message