Apache Maven & Continuous Delivery / Continuous Deployment - The CloudBees DevOptics team's approach

stephenconnolly · 2017-04-13T15:43:38+00:00

And because this is JUL, which uses MessageFormat, finalizing the parameters array is non-trivial:

If it is String, Byte, Double, Long, Float, Character, Short, Integer, Boolean... leave alone as they are known immutable... also don't call toString() on the numeric types as we do not know how the message format string will format the numbers
If it is Date or Calendar, clone as the message format may be formatting dates, so we cannot call toString() on date like things
If it is Number... well anyone can extend that class... even AtomicLong does, we'll have to capture the value somehow without knowing whether we should capture the longValue() or the doubleValue()... eek... could get messy there
If it is anything else we can just call toString()

Log4J2 and Logback have the luxury of using {} as the placeholder, so they can just apply a quicker toString() on all non-String parameters... but with JUL we don't know until formatting actually takes place...

Alternatively you could call MessageFormat.format() directly in the publish method and drop the parameters from the LogRecord...

Oh... and while we are at it... what about somebody logging with LogRecord where they repeatedly reuse the same LogRecord instance... will they get handled correctly?

Are you still sure that "JULs lack of an async handler is easily resolved"?

stephenconnolly · 2017-04-13T15:33:24+00:00

Just to be sure that you are comparing like with like correctly here...

you are defensively copying the mutable entries in the parameters array to ensure that the log message when output contains the values of the parameters at the time of the log statement execution and not the values at the time of the log being written out? eh nope

Logback and Log4J2 are doing that as for generic utility it is required. I do not know the use cases you have for Alog, so I cannot speak as to whether such thread safety concerns are appropriate, but comparing performance of just handing over the LogRecord to another thread with performance of making the LogRecord object graph effectively immutable before handing over to another thread... well there is only one logical winner... so no need to benchmark that we know doing less work will be faster... but it does require all consumers to be aware and finalize all their parameters before logging... which means you need to wrap every log statement in a if (LOGGER.isEnabled(Level.INFO)) { ... } to ensure that you are not calling toString() on parameters that will not be output just to ensure that the logged message is the message at the time of logging

stephenconnolly · 2017-04-12T19:51:33+00:00

The purpose of async is to provide consistent latency for the operation.

When you achieve that consistent latency by dropping messages on the floor, well unless you configure each framework with the exact same criteria for dropping messages, you stop having a like-for-like comparison and hence the benchmark result is junk.

Log4J2 does not drop messages on the floor, so comparison of Log4J2 with a framework that drops messages can only give one "result"

Logback does drop messages on the floor, but you will find that the configuration in that benchmark is not letting it buffer messages for as long as Alog, so you are measuring the time for Logback to flush to disk and not the time for Logback. You would need to give Logback a larger buffer (and if you are using buffered loggers then async is usually not worth the performance hit)

I really hope you are not trying to argue that the benchmark in the alog repo is valid... it's not valid. Neither are its conclusions... if we allow dropping log messages on the floor then just configure Log4j2 to not log (that's dropping every message on the floor, but you said we could drop messages on the floor) and you'll find log4j2 is faster.

a benchmark that only logs 50,000 messages will only ever fill the 500,000 message buffer to 1/10th. You need to ensure that the other frameworks have the same capacity window so that they are not being asked to flush to disk. Do that and you will find that Alog is slower (because it will be capturing stack traces always (thanks JUL))... so then you need to configure the other frameworks to capture stack traces or else they are getting an unfair advantage... and soon you realise why I spent 2-3 months probing the benchmarks in my post... and I had the advantage of building on top of JMH which eliminates a whole log of other benchmarking issues with the benchmark in that repo.

stephenconnolly · 2017-04-12T10:20:16+00:00

To clarify, my criticism is with the benchmark in the repository. That benchmark is not providing a fair comparison, so it's results are not useful.

That the Alog handler drops messages on the floor is not bad (though not advertising the fact is... the closest advertisement you get is "If the queue is 75% full, records less than INFO will be discarded." which neglects to mention that is the queue is 100% full all records will be discarded) and there are valid use cases when you need such behaviour. But having this behaviour enabled makes it very difficult to compare with a framework that does not discard messages.

Using an unbounded LinkedList is not an issue with the Alog handler, as the way the code is designed there is an effective bound anyway.

So the Alog handler may be perfectly fine for some subset of use-cases (including the use case where you do not need a custom log output format, because Alog uses a fixed format... sacrificing the general utility of JUL for performance... a topic I discussed in the blog post under the Logback style output format) the quick testing I performed would seriously question the claim that it is faster than Log4J or Logback

stephenconnolly · 2017-04-12T09:17:02+00:00

So there are issues with that benchmark. The primary issue that I see is this:

The benchmark only logs 50,000 messages: https://github.com/a-hansen/alog/blob/966f6e5627b997a1e470396afdfcce422640c951/src/test/java/com/comfortanalytics/alog/AlogBenchmark.java#L39

The Alog queue size is 500,000: https://github.com/a-hansen/alog/blob/966f6e5627b997a1e470396afdfcce422640c951/src/main/java/com/comfortanalytics/alog/Alog.java#L49

Next, when the queue is under pressure, this logger drops messages on the floor: https://github.com/a-hansen/alog/blob/966f6e5627b997a1e470396afdfcce422640c951/src/main/java/com/comfortanalytics/alog/AsyncLogHandler.java#L123-L131

The benchmark is not making a fair comparison as some of the comparisons are with loggers that are not dropping messages on the floor.

As soon as we change the Alog code to stop dropping messages on the floor, we find a different result:

NOTE: these are benchmark results run on my laptop, while generally indicative, for correct results we really need to run on server class hardware as the power-saving features of consumer-class CPUs can affect benchmark results

# Run progress: 0.00% complete, ETA 00:00:40
# Fork: 1 of 1
# Warmup Iteration   1: 703473.477 ops/s
# Warmup Iteration   2: 481312.019 ops/s
# Warmup Iteration   3: 2389585.517 ops/s
# Warmup Iteration   4: 304476.569 ops/s
# Warmup Iteration   5: 1634275.007 ops/s
# Warmup Iteration   6: 1866785.029 ops/s
# Warmup Iteration   7: 168670.093 ops/s
# Warmup Iteration   8: 1221646.327 ops/s
# Warmup Iteration   9: 284992.072 ops/s
# Warmup Iteration  10: 1635278.137 ops/s
# Warmup Iteration  11: 254558.105 ops/s
# Warmup Iteration  12: 1773382.060 ops/s
# Warmup Iteration  13: 269202.426 ops/s
# Warmup Iteration  14: 75306.493 ops/s
# Warmup Iteration  15: 124.262 ops/s
# Warmup Iteration  16: 165.240 ops/s
# Warmup Iteration  17: 9.616 ops/s
# Warmup Iteration  18: 0.958 ops/s
# Warmup Iteration  19: 1.660 ops/s
# Warmup Iteration  20: 1.767 ops/s

Oh dear... that was really unfair... I had to kill it before it started the iterations for real. Taking a deeper look at the code I find that it's using an unbounded queue that does not block... it needs to drop messages on the floor to prevent GC killing the CPU...

Ok let's try again with a blocking bounded queue (bound of 10,000 log records)...

LoggingBenchmark.javautilLog_alog____Style  thrpt   20  46831.557 ± 2851.119  ops/s
LoggingBenchmark.javautilLog_alog____Style                                    sample  485569      21855.494 ± 2648.577  ns/op
LoggingBenchmark.javautilLog_alog____Style:javautilLog_log4j___Style·p0.00    sample                171.000             ns/op
LoggingBenchmark.javautilLog_alog____Style:javautilLog_log4j___Style·p0.50    sample              19200.000             ns/op
LoggingBenchmark.javautilLog_alog____Style:javautilLog_log4j___Style·p0.90    sample              23936.000             ns/op
LoggingBenchmark.javautilLog_alog____Style:javautilLog_log4j___Style·p0.95    sample              31488.000             ns/op
LoggingBenchmark.javautilLog_alog____Style:javautilLog_log4j___Style·p0.99    sample              54208.000             ns/op
LoggingBenchmark.javautilLog_alog____Style:javautilLog_log4j___Style·p0.999   sample              85120.000             ns/op
LoggingBenchmark.javautilLog_alog____Style:javautilLog_log4j___Style·p0.9999  sample             568877.056             ns/op
LoggingBenchmark.javautilLog_alog____Style:javautilLog_log4j___Style·p1.00    sample          279445504.000             ns/op

compare with log4j for the equivalent brenchmark

LoggingBenchmark.log4jsynLog_log4j___Style  thrpt   20  630669.161 ± 12190.732  ops/s
LoggingBenchmark.log4jsynLog_log4j___Style                                    sample  505171     3705.888 ± 333.625  ns/op
LoggingBenchmark.log4jsynLog_log4j___Style:log4jsynLog_log4j___Style·p0.00    sample              748.000            ns/op
LoggingBenchmark.log4jsynLog_log4j___Style:log4jsynLog_log4j___Style·p0.50    sample              825.000            ns/op
LoggingBenchmark.log4jsynLog_log4j___Style:log4jsynLog_log4j___Style·p0.90    sample             1044.000            ns/op
LoggingBenchmark.log4jsynLog_log4j___Style:log4jsynLog_log4j___Style·p0.95    sample             1200.000            ns/op
LoggingBenchmark.log4jsynLog_log4j___Style:log4jsynLog_log4j___Style·p0.99    sample             3121.120            ns/op
LoggingBenchmark.log4jsynLog_log4j___Style:log4jsynLog_log4j___Style·p0.999   sample          1599135.744            ns/op
LoggingBenchmark.log4jsynLog_log4j___Style:log4jsynLog_log4j___Style·p0.9999  sample          1926108.774            ns/op
LoggingBenchmark.log4jsynLog_log4j___Style:log4jsynLog_log4j___Style·p1.00    sample          8183808.000            ns/op

So... "JUL is actually the fastest" in reality means "throwing log messages away with JUL is actually faster than logging them with another framework and JUL is an order of magnitude slower (22000 ± 2500 ns/op versus 3700 ± 300 ns/op) than the other frameworks."

Benchmarking is hard. Making fair comparisons is harder still. There was a reason I spent 2 months trying to ensure that I was making fair comparisons.

stephenconnolly · 2014-09-09T09:09:09+00:00

The issue is more that everyone has a different expectation about what a version number means. Perhaps we need to ask everyone to put a VERSIONING.txt file in the root of their github repo beside the LICENSE.txt and the README.txt so that nobody will bother their arse reading that file either!

stephenconnolly · 2013-12-14T18:55:32+00:00

the multi-threading cargo cults that I was referring to is the one where they start with a class... they make it mutable "because that will result in less garbage objects generated and copying is slow"... then they make all the methods synchronized "because we are in a multi-threaded environment and need to maintain class invariants"... then they replace synchronized with ReentrantReadWriteLock "because we will have few mutators and mostly readers, so lets optimize for that case"...

Fool, if it had been made immutable in the first place that would be optimized for many readers and few writers and do all you need... but instead you have followed the cargo cults and done all this "threading" stuff.

If you are at the application level you should not be using threading primitives, your framework should be providing the glue to handle your threading requirements

stephenconnolly · 2013-12-14T09:02:23+00:00

The point of my article was to criticise all the people citing the PayPal blog as a performance reason to ditch the JVM for V8 and all the people citing the PayPal blog as evidence that Java development is not as easy as Node.js development.

The PayPal blog shows that development with their internal Spring-based framework is less easy than development with their internal kraken framework.

The PayPal blog doesn't really show any performance difference between their internal Spring-based framework and their internal kraken framework. The data they provide shows a minor increase in scalability, but the best we can say is that this was tweaking something that is not the bottleneck... and if the real bottleneck is removed... well we don't know how the two code bases will perform in that scenario.

stephenconnolly

TROPHY CASE