[PROPOSAL] Change core logging from Java Utils Logging

[Stephen Connolly]

I come with evidence, namely my comparison of the performance of JUL, Log4J2 and Logback:

https://www.sitepoint.com/which-java-logging-framework-has-the-best-performance/

Java Utils Logging is horrible in terms of performance. About the only good thing I can say about it is that it give a consistent throughput no matter how many threads you throw at it... consistently crappy throughput ;-)

Given how much logging some Jenkins instances do, switching Core to either Log4J2 or Logback should have the potential to make a significant difference to the performance of some instances.

So before we all jump into a fight over whether to pick Log4J 2 or Logback, there are a number of questions that we need to resolve:

1. Is Kohsuke on-board. In the past this has been a blocker.

2. We should not change the logging format for existing installations. New installations might get a nicer single-line log message by default, but existing instances would have to configure the switch-over

3. For compatibility issues, users may need to switch back to JUL if they have issues. This likely means that we pick SLF4J as the API that we log with and just configure the back-end on start-up so that you can jump back to JUL if you really need to

4. Support Core plugin will need some rework, are there any other plugins that hard-code assumptions that Jenkins Core uses JUL

5. Remoting may need to bundle the logging framework somehow, or at least "just enough logging framework to bootstrap the real one"

What else do we need to line up before we can bite this one off?

-Stephen

[Jesse Glick]

On Tue, Apr 11, 2017 at 9:14 AM, Stephen Connolly
<stephen.al...@gmail.com> wrote:
> Java Utils Logging is horrible in terms of performance.

All I see from a quick read is that unbuffered handlers are a problem
if you are in fact logging tons of messages. In normal operation
Jenkins does _not_ logs tons of messages—unless you have set up a
`FINE` logger in `support-core`, but that has its own handlers, which
we can trivially buffer if they are not already.

So why would we waste precious developer time, and risk
incompatibilities? Is there some actual significant performance issue
*in Jenkins* (not a microbenchmark) that you are trying to fix?

[Stephen Connolly]

Even if you buffer the loggers you still are 50% slower due to poor message formatting and always capturing the stack trace for every log message to be able to report the call site

--
You received this message because you are subscribed to the Google Groups "Jenkins Developers" group.
To unsubscribe from this group and stop receiving emails from it, send an email to jenkinsci-dev+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/jenkinsci-dev/CANfRfr2GsqAt3Xme5vutbUC%3D3PmoHCjuatRMwPJUGB-4R__Npg%40mail.gmail.com.
For more options, visit https://groups.google.com/d/optout.

[Jesse Glick]

On Tue, Apr 11, 2017 at 11:35 AM, Stephen Connolly
<stephen.al...@gmail.com> wrote:
> you still are 50% slower due to poor message
> formatting and always capturing the stack trace

But again what is the actual impact on a typical instance producing on
the order of one log message per minute? A millisecond here or there?
If you are looking for performance optimizations I am guessing there
are much lower-hanging fruit.

[Jimilian]

Hi

Our Jenkins instance* produces ~10 messages per second maximum (INFO mainly), but I didn't see anything suspicious in any profiler report related to logging system. 

Maybe I looked for something wrong in profiler reports, but I checked:

1) Locked threads

2) CPU

3) IO

4) Memory

But in general I think it's good idea to move to Log4j2:

1) User can configure https://logging.apache.org/log4j/2.x/manual/layouts.html#JSONLayout - it will simplify parsing the logs (backward compatibility is not needed anymore, I suppose)

2) Log4j2 is more garbage friendly

3) Log4j2 is asynchronous

* Numbers: https://www.slideshare.net/profyclub_ru/continuous-integration-here/8

Br, Alex

[Cyrille Le Clerc]

I prefer the SLF4J syntax to the java.util.logging syntax, I don't like at all the java.util.logging syntax.

I think that using a friendly logging API is a good reason to move away from java.util.logging.

Cyrille

[Baptiste Mathus]

I'm somehow +0.9 for moving away from JUL, and -0.5 to move to anything else than the SLF4J facade (pleonasm). The API is easy to use and we can delay or switch to another impl without touching the code.

I am not that convinced that apart from rare cases where people enabled more logging for debugging purpose, logging would really be the bottleneck for perf in 99%, but like Cyrille I think it's more the clunkiness of the JUL API that would justify the work, for more developer-pleasure for the codebase. And more attractivity for contributors globally.

Because, well:

if (LOGGER.isLoggable(Level.FINE)) {

LogRecord lr = new LogRecord(Level.FINE, "{0} WUT");
lr.setThrown(e);
lr.setParameters(new Object[]{name});
logger.log(lr);

}

could then be replaced by:

LOGGER.trace( "{0} WUT", name, e);

Also, SLF4J offers many *-over-slf4j shims to redirect existing API usages to the same pipe, which is likely to be very useful for our purpose. (maybe others do so too, though, didn't check)

--

You received this message because you are subscribed to the Google Groups "Jenkins Developers" group.
To unsubscribe from this group and stop receiving emails from it, send an email to jenkinsci-dev+unsubscribe@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/jenkinsci-dev/f35899a9-a74b-4442-9b0b-06cb5646a99a%40googlegroups.com.

[Robert Sandell]

Stephen has shot down my previous proposals to switch to using SLF4J before because of the SLF4J -> JUL bridge has terrible overhead in performance. So if we were to switch to SLF4J we also need to switch the default logging backend because otherwise we would really have a performance issue even if we didn't have one before.

But I'm finding it hard to grasp how we would do this. configuring JUL is hard as it is, and if core and only a few plugins swtches admins would have an even bigger headache in having to maintain two logging configs, one for what we switch to and one for JUL for the plugins that haven't updated yet.

/B

To view this discussion on the web visit https://groups.google.com/d/msgid/jenkinsci-dev/CANWgJS5taen55KuwSJhcEKLBbmqDq4-zoqgTOKGvji%3Dm0errXw%40mail.gmail.com.

For more options, visit https://groups.google.com/d/optout.

--

Robert Sandell

Software Engineer

CloudBees Inc.

[James Nord]

Bringing this up again because I just found myself having to write a LogRecord to log a paramaterized log with an exception...

What is the actual overhead of using the bridge? Stephen has some winderful benchmarks of not logging or logging various paramters but I didn't see anything about SLF4j -> JUL...

At the same time I'm not sure why we would use SLF4j -> JUL rather than just use logback, and add JUL -> slf4j binding adapters for plugins.

> But I'm finding it hard to grasp how we would do this. configuring JUL is hard as it is, and if core and only a few plugins swtches admins would have an even bigger headache in having to maintain two logging configs, one for what we switch to and one for JUL for the plugins that haven't updated yet.

regardless of any approach there MUST only be one logging backend and that is the one you configure, be it logback or JUL.

Is it time for a JEP?  or are there issues with other things (like those pesky web containers (tomcat et al)? that would kill this?

To unsubscribe from this group and stop receiving emails from it, send an email to jenkinsci-de...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/jenkinsci-dev/f35899a9-a74b-4442-9b0b-06cb5646a99a%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups "Jenkins Developers" group.

To unsubscribe from this group and stop receiving emails from it, send an email to jenkinsci-de...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/jenkinsci-dev/CANWgJS5taen55KuwSJhcEKLBbmqDq4-zoqgTOKGvji%3Dm0errXw%40mail.gmail.com.

For more options, visit https://groups.google.com/d/optout.

[Jesse Glick]

On Fri, Nov 17, 2017 at 8:47 AM, James Nord <jn...@cloudbees.com> wrote:
> I just found myself having to write a
> LogRecord to log a paramaterized log with an exception...

LOGGER.log(Level.FINE, ex, () -> "so why did you bother making a
LogRecord for " + this + " common task?");

[Stephen Connolly]

JMH says Indy is slower

--
You received this message because you are subscribed to the Google Groups "Jenkins Developers" group.
To unsubscribe from this group and stop receiving emails from it, send an email to jenkinsci-de...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/jenkinsci-dev/CANfRfr3k89MiLV3dBsaAKLHgQJ2mR0_xb-UtUoQokRLJX%2BAP5A%40mail.gmail.com.

For more options, visit https://groups.google.com/d/optout.

--

Sent from my phone

[Oleg Nenashev]

JEP It, I'd guess.
I am +1 about considering the move, but it requires some design work and prototyping.

BR, Oleg

пятница, 17 ноября 2017 г., 16:41:51 UTC+1 пользователь Stephen Connolly написал:

[Jesse Glick]

On Fri, Nov 17, 2017 at 10:41 AM, Stephen Connolly
<stephen.al...@gmail.com> wrote:
> JMH says Indy is slower

Sorry, what are “JMH” and “Indy”?

Where is the evidence that there is any actual performance issue in
production Jenkins installations which is not trivially corrected by a
change of idiom in a few hot spots? That would justify spending
engineering time on implementing and testing a significant framework
change?

[Stephen Connolly]

JMH is the micro benchmarking tool.

INDY is invoke dynamic

I have blog posts already published showing that when capturing local variables, 

log(Level.FINE, ()-> "simple concat " + localVar) 

is worse when not logging than either of

log(Level.FINE, "simple concat {0}", localVar)

log(Level.FINE, "simple concat {0}", new Object[]{localVar})

If you are using field variables, then INDY does not need to capture state and the performance is better... *but* you don't want to do that as then you are logging the state at the point in time when the log message is being logged not the point in time when the log method was called.

I argue that the

    () -> expr 

pattern is exceedingly dangerous because of the ease with which you can end up logging mutable state. In addition it is slower. Please stop promoting it.

--
You received this message because you are subscribed to the Google Groups "Jenkins Developers" group.

To unsubscribe from this group and stop receiving emails from it, send an email to jenkinsci-dev+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/jenkinsci-dev/CANfRfr3RL6pU%3DNeNHKJHxWjVuv0aMhfv4tJ6XYVC50K6T-E1xg%40mail.gmail.com.

[Jesse Glick]

On Mon, Nov 20, 2017 at 10:32 AM, Stephen Connolly
<stephen.al...@gmail.com> wrote:
> log(Level.FINE, ()-> "simple concat " + localVar)
>
> is worse when not logging than either of
>
> log(Level.FINE, "simple concat {0}", localVar)
> log(Level.FINE, "simple concat {0}", new Object[]{localVar})

Worth comparing the more interesting case of two or more format
parameters (when the logger is at INFO+):

fine(() -> local1 + " and " + local2);

vs.

log(Level.FINE, "{0} and {1}", new Object[] {local1, local2});

I.e., the case where the `Object[]` constructor is required if you are
avoiding lambdas. The last time I checked (very informally!), the
lambda variant was slower for initial calls, and then became faster
after a large number of repetitions, presumably due to JIT effects.

At any rate, my broader question stands. Is there actual evidence for
a pervasive performance drain in typical Jenkins workloads across a
large number of call sites caused by suboptimal logging calls? If the
number of performance-sensitive call sites is moderately small, it is
far less intrusive to just optimize those (for example, gating with
`isLoggable`) and move on to some more important work.

[Stephen Connolly]

On Wed 22 Nov 2017 at 17:26, Jesse Glick <jgl...@cloudbees.com> wrote:

On Mon, Nov 20, 2017 at 10:32 AM, Stephen Connolly
<stephen.al...@gmail.com> wrote:
> log(Level.FINE, ()-> "simple concat " + localVar)
>
> is worse when not logging than either of
>
> log(Level.FINE, "simple concat {0}", localVar)
> log(Level.FINE, "simple concat {0}", new Object[]{localVar})

Worth comparing the more interesting case of two or more format
parameters (when the logger is at INFO+):

fine(() -> local1 + " and " + local2);

vs.

log(Level.FINE, "{0} and {1}", new Object[] {local1, local2});

I.e., the case where the `Object[]` constructor is required if you are
avoiding lambdas. The last time I checked (very informally!), the
lambda variant was slower for initial calls, and then became faster
after a large number of repetitions, presumably due to JIT effects.

Well JMH does many iterations to allow for inclining...

But irrespective of perf there is the logging of incorrect values that a lambda makes trivial given the action at a distance.

At any rate, my broader question stands. Is there actual evidence for
a pervasive performance drain in typical Jenkins workloads across a
large number of call sites caused by suboptimal logging calls? If the
number of performance-sensitive call sites is moderately small, it is
far less intrusive to just optimize those (for example, gating with
`isLoggable`) and move on to some more important work.

--
You received this message because you are subscribed to the Google Groups "Jenkins Developers" group.

To unsubscribe from this group and stop receiving emails from it, send an email to jenkinsci-de...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/jenkinsci-dev/CANfRfr14-fLB-W_iujqR69dWqJWRT3vq_0aSkAPOC7Q-RwjKyQ%40mail.gmail.com.

For more options, visit https://groups.google.com/d/optout.

[Jesse Glick]

On Wed, Nov 22, 2017 at 2:07 PM, Stephen Connolly
<stephen.al...@gmail.com> wrote:
> there is the logging of incorrect values

I guess this is a concern according to the handler.
`Logger.log(LogRecord)` calls `Handler.publish` synchronously. And
typical handlers would then format the message synchronously if they
log it at all. In Jenkins, the problematic handler is
`RingBufferLogHandler`, which formats messages asynchronously, or
rather allows callers such as `Functions.printLogRecordHtml` to do so.
It could instead call `setMessage` synchronously with the result of
`SimpleFormatter.formatMessage` (and then call `setParameters(null)`
to clean up). This would actually have another benefit, even if no one
ever abused the lambda form: avoiding nasty memory leaks, which I have
personally encountered.

[Stephen Connolly]

Or any other user provided handler could have the same issue.

Much better if we just switch to a decent logging framework and be done

--
You received this message because you are subscribed to the Google Groups "Jenkins Developers" group.
To unsubscribe from this group and stop receiving emails from it, send an email to jenkinsci-de...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/jenkinsci-dev/CANfRfr2Wxxy5RUatk4E8b80tvPydHUCGP2B-BraFH3ehR-V2Lg%40mail.gmail.com.

For more options, visit https://groups.google.com/d/optout.

[Jesse Glick]

On Mon, Nov 27, 2017 at 7:56 PM, Stephen Connolly
<stephen.al...@gmail.com> wrote:
> any other user provided handler could [also queue unformatted log records]

Theoretically. I cannot think of any such case. Handlers are known to
be registered by Jenkins core; the `support-core` plugin; and the
servlet container.

Am I the only one to think it strange that we are discussing using
very limited core developer resources to replace a library used
pervasively throughout the Jenkins code base with a functionally
identical library with no demonstrable benefit to users and rather
marginal impact on developers?

[Samuel Van Oort]

> Am I the only one to think it strange that we are discussing using 
very limited core developer resources to replace a library used 
pervasively throughout the Jenkins code base with a functionally 
identical library with no demonstrable benefit to users and rather 
marginal impact on developers

No, you're not -- I'd also like to see a case where profiling shows simple log formatting is a significant bottleneck.  If it wasn't an impactful change I'd say "sure, micro-optimize" but after seeing applications broken due to SLF4J API changes it seems like a risky change which is only beneficial in edge cases (high logging throughput). 

Now, I *have* seen bottlenecks around AnnotatedLargeText and console annotation -- particularly in pipeline, although the logging there is getting a rework anyway that will reduce the impact of that.  

If we want to optimize logging performance, I think it makes more sense to target the build logging APIs for optimization, specifically the I/O bits -- there's some room to optimize the way we use & interact with the streams, and use more modern NIO APIs.  Would also like to see reuse of buffers, because this is a key cause of high GC pressure from Jenkins if you're touching small log files, and one of the main reasons we see hundreds of MB/s of object garbage generated (continuously reallocating byte arrays that could be reused).  Remoting is another cause of GC pressure (depending on the protocol used).

[msi...@cloudbees.com]

Hey all, sorry to resurrect an old thread, but I'm also interested in migrating. I'm a developer of Log4j 2 and could probably spend hours geeking out about this, but for us developers, the best advantage of migrating to log4j-api or slf4j-api would be parameterized logging, markers, MDC/NDC/ThreadContext, and more. From an administrative standpoint, Jenkins remotes could be configured to send logs to master using native log4j functionality (e.g., logging over sockets, Kafka, ZeroMQ, Flume, etc.).

As for performance considerations, it may not be a large deal currently, though perhaps developers have been avoiding adding log messages because of that? If it were convenient and fast to add more logging messages, developers may be more inclined to do so. Also, if you want to see what I mean by performance, have a look at LogRecord itself and you'll start to see the problems right away.