You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-user@logging.apache.org by Shawn Heisey <ap...@elyograg.org> on 2018/08/06 16:00:24 UTC
Questions about switching to async and other performance-related
config
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.
https://issues.apache.org/jira/browse/SOLR-7887
Now we're contemplating switching to async, which is apparently how
log4j2 achieves "insane performance."
http://www.grobmeier.de/log4j-2-performance-close-to-insane-20072013.html
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 =
LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
private static final Logger requestLog =
LoggerFactory.getLogger(MethodHandles.lookup().lookupClass().getName() +
".Request");
private static final Logger slowLog =
LoggerFactory.getLogger(MethodHandles.lookup().lookupClass().getName() +
".SlowRequest");
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:
https://apaste.info/MqMq
https://apaste.info/tTcc
Thanks,
Shawn
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Questions about switching to async and other performance-related
config
Posted by Shawn Heisey <ap...@elyograg.org>.
On 8/7/2018 11:13 AM, Remko Popma wrote:
> Async logging will not cause messages to appear out of order in the log file.
That's good to know. I figured it would be at least theoretically
possible. If for some reason processing one log message took slightly
longer than processing the next log message, the later log message might
end up getting logged first. There might not be much danger of
radically different processing times for different log messages,
though. Sounds like I really don't need to be worried about it.
> Please take a look at the performance page (https://logging.apache.org/log4j/2.x/performance.html). Async logging is fast because of reduced lock contention. Lock contention happens when you have many threads logging simultaneously. If your application doesn’t do that, benefits will be limited.
As already discussed, Solr *can* do a lot of logging simultaneously.
What I would think of as a "typical" install probably won't have
sustained periods of heavy logging. It all depends on what kind of
traffic patterns the Solr install will be handling.
> The 10% speedup you mentioned indicates to me that logging is not the main performance bottleneck (at least during the tests).
I would agree with that assessment. Although 10 percent isn't
earth-shattering, it's *something*. If there are any massive
performance improvements to be made, the problems will be found
elsewhere. There have been a number of impressive performance gains
achieved by Lucene and Solr over the years, maybe there are a few more
still left to be found.
> It’s a nice gain for little effort, but if your aim is to dramatically improve the performance of your application, it’s best to first approach this systematically: identify the biggest bottleneck, optimize that, measure again, etc.
I see it as an easy win - a tiny change with little danger that has the
potential to improve performance for all users. Some users might see
big gains, but a lot of them probably won't even be able to measure the
difference. I think it's an enhancement that can help Solr scale for
heavy loads, not something that will massively improve life for everyone.
Thank you for taking the time to discuss this. It's been helpful.
Shawn
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Questions about switching to async and other performance-related config
Posted by Remko Popma <re...@gmail.com>.
Async logging will not cause messages to appear out of order in the log file.
Please take a look at the performance page (https://logging.apache.org/log4j/2.x/performance.html). Async logging is fast because of reduced lock contention. Lock contention happens when you have many threads logging simultaneously. If your application doesn’t do that, benefits will be limited.
The 10% speedup you mentioned indicates to me that logging is not the main performance bottleneck (at least during the tests).
It’s a nice gain for little effort, but if your aim is to dramatically improve the performance of your application, it’s best to first approach this systematically: identify the biggest bottleneck, optimize that, measure again, etc.
Remko
(Shameless plug) Every java main() method deserves http://picocli.info
> On Aug 8, 2018, at 0:47, Shawn Heisey <ap...@elyograg.org> wrote:
>
>> On 8/6/2018 4:35 PM, Remko Popma wrote:
>> If you have multiple threads that log quite a lot, async logging can make a
>> big difference.
>> If you don't log much, or if the logging is mostly happening on a single
>> thread, I'd suggest sticking with synchronous logging for its simplicity.
>
> Solr is a fully threaded application that runs in a servlet container. In busy environments, there will be many things happening simultaneously that will all generate logs. I would call what Solr generates a sort of "medium" level of logging. There's a fair amount of detail when request happen, but when there are no requests, most Solr installs will not be logging anything unless Jetty has something to say.
>
> Did you see my question early in the thread about whether async logging can place entries in the log that are out of sequence, and whether that could be helped by using sync logging for WARN and above, with lower levels using async? One thing I'm going to keep in my tech support hat after we complete the switch to async is having users change the logging back to sync if there's any concern about timing of log entries. That should probably end up in Solr documentation as well.
>
>> Have you thought of any way to measure the performance difference between
>> synchronous and async logging for your application? (If you cannot tell the
>> difference, then what's the point?) :-)
>
> In SOLR-12055, one of my fellow committers did a Solr test run (running "ant test") that took 42 minutes. Then Root was changed to AsyncRoot, and the next test run only took 38 minutes. The Lucene project has some automated benchmarks, work is underway to bring something similar to Solr. The idea will be to put Solr through a workload that's similar to something that might happen in a real install.
>
> My personal goal in switching to async is achieving the "insane performance" I've heard about that upgrading from log4j1 to log4j2 makes possible. Definitely hoping we won't see any downsides.
>
>> If you decide it is worth it, you can switch by changing Root to AsyncRoot
>> and Logger to AsyncLogger in your configuration.
>
> Thank you for that information. I think the async page in the log4j documentation should have a paragraph near the beginning about switching existing configs to async, with that simple statement in it.
>
> Thanks,
> Shawn
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
Re: Questions about switching to async and other performance-related
config
Posted by Shawn Heisey <ap...@elyograg.org>.
On 8/6/2018 4:35 PM, Remko Popma wrote:
> If you have multiple threads that log quite a lot, async logging can make a
> big difference.
> If you don't log much, or if the logging is mostly happening on a single
> thread, I'd suggest sticking with synchronous logging for its simplicity.
Solr is a fully threaded application that runs in a servlet container.
In busy environments, there will be many things happening simultaneously
that will all generate logs. I would call what Solr generates a sort of
"medium" level of logging. There's a fair amount of detail when request
happen, but when there are no requests, most Solr installs will not be
logging anything unless Jetty has something to say.
Did you see my question early in the thread about whether async logging
can place entries in the log that are out of sequence, and whether that
could be helped by using sync logging for WARN and above, with lower
levels using async? One thing I'm going to keep in my tech support hat
after we complete the switch to async is having users change the logging
back to sync if there's any concern about timing of log entries. That
should probably end up in Solr documentation as well.
> Have you thought of any way to measure the performance difference between
> synchronous and async logging for your application? (If you cannot tell the
> difference, then what's the point?) :-)
In SOLR-12055, one of my fellow committers did a Solr test run (running
"ant test") that took 42 minutes. Then Root was changed to AsyncRoot,
and the next test run only took 38 minutes. The Lucene project has some
automated benchmarks, work is underway to bring something similar to
Solr. The idea will be to put Solr through a workload that's similar to
something that might happen in a real install.
My personal goal in switching to async is achieving the "insane
performance" I've heard about that upgrading from log4j1 to log4j2 makes
possible. Definitely hoping we won't see any downsides.
> If you decide it is worth it, you can switch by changing Root to AsyncRoot
> and Logger to AsyncLogger in your configuration.
Thank you for that information. I think the async page in the log4j
documentation should have a paragraph near the beginning about switching
existing configs to async, with that simple statement in it.
Thanks,
Shawn
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Questions about switching to async and other performance-related config
Posted by Remko Popma <re...@gmail.com>.
If you have multiple threads that log quite a lot, async logging can make a
big difference.
If you don't log much, or if the logging is mostly happening on a single
thread, I'd suggest sticking with synchronous logging for its simplicity.
Have you thought of any way to measure the performance difference between
synchronous and async logging for your application? (If you cannot tell the
difference, then what's the point?) :-)
If you decide it is worth it, you can switch by changing Root to AsyncRoot
and Logger to AsyncLogger in your configuration.
On Tue, Aug 7, 2018 at 5:38 AM, Shawn Heisey <ap...@elyograg.org> wrote:
> On 8/6/2018 10:10 AM, Matt Sicker wrote:
> > The %c (aka %logger) pattern uses the logger name. The %C (aka %class)
> > pattern does the runtime lookup which kills performance.
>
> Thank you for that information. I was worried that we had a performance
> killing config. What a difference the case of a letter can make!
>
> I still need information about the best way to switch our config to
> Async logging and any other recommendations that come to mind when
> reading the config.
>
> https://apaste.info/MqMq
> https://apaste.info/tTcc
>
> We have a project issue to switch to async:
>
> https://issues.apache.org/jira/browse/SOLR-12055
>
> Is changing the Root tag in the xml to AsyncRoot all we have to do?
>
> Thanks,
> Shawn
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
Re: Questions about switching to async and other performance-related
config
Posted by Shawn Heisey <ap...@elyograg.org>.
On 8/6/2018 10:10 AM, Matt Sicker wrote:
> The %c (aka %logger) pattern uses the logger name. The %C (aka %class)
> pattern does the runtime lookup which kills performance.
Thank you for that information. I was worried that we had a performance
killing config. What a difference the case of a letter can make!
I still need information about the best way to switch our config to
Async logging and any other recommendations that come to mind when
reading the config.
https://apaste.info/MqMq
https://apaste.info/tTcc
We have a project issue to switch to async:
https://issues.apache.org/jira/browse/SOLR-12055
Is changing the Root tag in the xml to AsyncRoot all we have to do?
Thanks,
Shawn
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Questions about switching to async and other performance-related config
Posted by Matt Sicker <bo...@gmail.com>.
The %c (aka %logger) pattern uses the logger name. The %C (aka %class)
pattern does the runtime lookup which kills performance.
On Mon, 6 Aug 2018 at 11:00, Shawn Heisey <ap...@elyograg.org> wrote:
> 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.
>
> https://issues.apache.org/jira/browse/SOLR-7887
>
> Now we're contemplating switching to async, which is apparently how
> log4j2 achieves "insane performance."
>
> http://www.grobmeier.de/log4j-2-performance-close-to-insane-20072013.html
>
> 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 =
> LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
> private static final Logger requestLog =
> LoggerFactory.getLogger(MethodHandles.lookup().lookupClass().getName() +
> ".Request");
> private static final Logger slowLog =
> LoggerFactory.getLogger(MethodHandles.lookup().lookupClass().getName() +
> ".SlowRequest");
>
> 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:
>
> https://apaste.info/MqMq
> https://apaste.info/tTcc
>
> Thanks,
> Shawn
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
--
Matt Sicker <bo...@gmail.com>