Re: Cek's new log4j vs logback benchmark

Thanks :-) That works for me. -ck > On Oct 15, 2021, at 7:07 AM, Volkan Yazıcı wrote: > > Welcome back and great work Carter! I am inclined to merge the > `release-2.x` changes to clear out the way for the 2.15.0 release. (I guess > Ralph's changes will be the only blocker after that.) Porting

Re: Cek's new log4j vs logback benchmark

Welcome back and great work Carter! I am inclined to merge the `release-2.x` changes to clear out the way for the 2.15.0 release. (I guess Ralph's changes will be the only blocker after that.) Porting those to `master` can be tackled in parallel. On Fri, Oct 15, 2021 at 1:03 PM Carter Kozak wrote

Re: Cek's new log4j vs logback benchmark

I’ve been on vacation with limited network access since Saturday, but I’ll be back on Sunday. My PR is ready to merge into release-2.x, I haven’t done so yet because I began the cherry-pick to master but was unable to complete the relatively painful conflict resolution before my flight out. Hopi

Re: Cek's new log4j vs logback benchmark

I don't have access to those boxes any more. I will be going on holiday from tomorrow without access to work email so it will be difficult for me to find out. One way is to assume they were new and look at what was the fastest reported speed for 2015 SSDs. I found this: https://www.alphr.com/ssds/

Re: Cek's new log4j vs logback benchmark

Ralph, could you point me toward the test that was failing for you? I'd fixed up a few and thought everything was passing. The branch should be ready to merge unless there are test flakes, then I'll fix them up. I'm also planning to turn off direct encoders by default on Java 9 and newer in a se

Re: Cek's new log4j vs logback benchmark

I don’t believe Carter’s latest changes have been merged. But when I tried to build Carter’s branch one unit test kept failing. I believe the problem is in the test - some sort of timing issue. I have some documentation updates I need to make as well as my usual pass through open issues and

Re: Cek's new log4j vs logback benchmark

Gentlemen, what is the status of the progress on this front? Is it in a "good enough" state for the 2.15.0 release? On Thu, Sep 23, 2021 at 6:29 PM Carter Kozak wrote: > Thanks, Ralph! > > You're correct that the direct encoderes are required for GC-free logging, > some of our consumers rely on

Re: Cek's new log4j vs logback benchmark

I don't think we should get rid of the Java 8 specific performance options in the 2.x branch. In 3.x, we can simplify things to default to appropriate options for Java 11+ and also removing the less useful variants. On Thu, Sep 23, 2021 at 11:29 AM Carter Kozak wrote: > > Thanks, Ralph! > > You'r

Re: Cek's new log4j vs logback benchmark

Thanks, Ralph! You're correct that the direct encoderes are required for GC-free logging, some of our consumers rely on that for niche (low latency) workloads where it's important to understand precisely where a pause may occur. GC performance has become much better over the last several years,

Re: Cek's new log4j vs logback benchmark

I ran Ceki’s benchmarks against 2.14.1, 2.15.0-SNAPSHOT and Carter’s branch. I ran them with 16 threads on my MacBook Pro and ran each test twice since the tests show some variability from time to time. I can draw 2 conclusions from this. 1. The improvements Carter has made to 2.15.0 have alrea

Re: Cek's new log4j vs logback benchmark

That's great news! Then I will be looking forward to your signal for putting a ribbon onto 2.15.0. I have followed the conversation with Claes Redestad from Oracle on Twitter . My conclusion was also that there apparently is no way to ma

Re: Cek's new log4j vs logback benchmark

Thanks, Volkan! Rerunning the benchmarks on my branch (specifically the PatternLayout benchmarks in log4j-perf) produced much better improvements than I had anticipated. Beyond that, the date format cache invalidation problem resulted in a substantial speedup. I agree that it would be helpful t

Re: Cek's new log4j vs logback benchmark

First and foremost, fantastic job Carter! For #573, I see that Gary and Ralph have already shared some remarks. I would appreciate it if we can get this merged and cut the ribbon for 2.15.0 release. Regarding `StringBuilder#toString().getBytes()`-vs-`CharsetEncoder`... That is a tough one. In you

Re: Cek's new log4j vs logback benchmark

https://github.com/apache/logging-log4j2/pull/573 improves performance by double digits in my testing, unfortunately it's difficult and time-consuming to individually compare performance implications of each part of the change. I'd appreciate review/feedback on the change. When I apply this PR a

Re: Cek's new log4j vs logback benchmark

Carter, I am really curious about your ongoing crusade. Mind updating us on it a bit, please? Where are we? What is your plan? How can we help you? On Wed, Sep 1, 2021 at 2:57 PM Carter Kozak wrote: > Thanks, Volkan! > > I had not seen InstantFormatter, it does look helpful, however I think it >

Re: Cek's new log4j vs logback benchmark

Thanks, Volkan! I had not seen InstantFormatter, it does look helpful, however I think it may have a bug. It appears to only compare milliseconds of Instant values while FixedDateFormat has some patterns which support microsecond and nanosecond precision. Currently I think this will batch together

Re: Cek's new log4j vs logback benchmark

Great work Carter! Have you seen `o.a.l.l.layout.template.json.util.InstantFormatter`, particularly its `Formatter#isInstantMatching` methods used for invalidating the cache? I was thinking of making it even smarter, e.g., if the pattern only has seconds, compare `Instant`s by their seconds. I asp

Re: Cek's new log4j vs logback benchmark

I've merged the fix for our FixedDateFormat caching bug which caused us to recompute the same millisecond-precision formatted timestamp unnecessarily each time our microsecond-precision clock incremented. https://issues.apache.org/jira/browse/LOG4J2-3153 I've also been unwrapping a few layers o

Re: Cek's new log4j vs logback benchmark

I've pushed some changes I've been using to validate performance here: https://github.com/carterkozak/logback-perf/pull/new/ckozak/sandbox Using the linux perf-norm profiler, the direct (garbage free) encoders on my machine use about 5000 instructions per operation while the byte-array method u

Re: Cek's new log4j vs logback benchmark

On Sat, Aug 28, 2021 at 3:16 PM Ron Grabowski wrote: > Follow-up to "Formatting the date is expensive. The process of actually > formatting a value is reasonable". Is this still an issue from LOG4J2-930: > %m %ex%n: 1,755,573 msg/sec%d %m %ex%n: 1,194,184 msg/sec > No, I believe that formatting

Re: Cek's new log4j vs logback benchmark

Have you pushed that up somewhere? I would like to test it. Is it possible to have direct encoders disabled by default unless something else that indicates GC Free logging is desired is enabled? From what I can tell the CPU overhead of GC Free logging makes it not worth it for most Java apps.

Re: Cek's new log4j vs logback benchmark

I don’t particularly want to optimize for the benchmarks, in most cases by pre-generating the formatted dates we’d end up doing substantially more work because we don’t log an event every millisecond/microsecond in practice. I’ve pushed a relatively naive optimization which takes into account whe

Re: Cek's new log4j vs logback benchmark

May a ringbuffer cache be a viable solution? Knowing the resolution (ticks, microseconds, milliseconds, seconds,..), a key could be generated to lookup and return a previously created formatted string from a ringbuffer or create it on the fly and store it for later. During bursts of log events, th

Re: Cek's new log4j vs logback benchmark

If you look at log4j-perf you will see both a TimeFormatBenchmark and a ClocksBenchmark. The time benchmark doesn’t include java.time’s formatter but I am pretty sure I added it to find that it was still slower than our formatters. However, the TimeFormat benchmark tests using System.currentTi

Re: Cek's new log4j vs logback benchmark

Follow-up to "Formatting the date is expensive. The process of actually formatting a value is reasonable". Is this still an issue from LOG4J2-930: %m %ex%n: 1,755,573 msg/sec%d %m %ex%n: 1,194,184 msg/sec If so, isn't date rendering essentially a sequence we can generate ahead of time similar to

Re: Cek's new log4j vs logback benchmark

Thanks, Remko. The default '%d' uses FixedDateFormat with FixedFormat.DEFAULT. The FastDateFormat alternative does not support microseconds, so it doesn't suffer from the same problem. I think I can substantially reduce the frequency we re-format dates by checking FixedFormat.secondFractionDigit

Re: Cek's new log4j vs logback benchmark

I remember looking at PatternLayout performance, I reported my findings here, hopefully they’re still useful: https://issues.apache.org/jira/browse/LOG4J2-930 If %d is used in the pattern, does the FixedDateFormat get used? > On Aug 28, 2021, at 4:33, Ralph Goers wrote: > > All of that agr

Re: Cek's new log4j vs logback benchmark

All of that agrees with my observations as well. Ralph > On Aug 27, 2021, at 12:23 PM, Carter Kozak wrote: > > I've identified a few things that seem impactful, but bear in mind that I > haven't begun to drill down into them yet. I plan to file individual tickets > and investigate in greater

Re: Cek's new log4j vs logback benchmark

I've identified a few things that seem impactful, but bear in mind that I haven't begun to drill down into them yet. I plan to file individual tickets and investigate in greater depth later on: 1. Formatting the date is expensive. The process of actually formatting a value is reasonable, howeve

Re: Cek's new log4j vs logback benchmark

My pleasure, I enjoy digging into this sort of performance comparison, the toughest piece right now is balancing investigation with active projects at work. I completely agree about the importance of getting this resolved quickly and I intend to continue investigating. Re loom: Currently we have a

Re: Cek's new log4j vs logback benchmark

Carter, thanks so much for your great effort and attention on this issue. *I personally find this the uttermost important thing the project needs to address with urgency right now.* Ceki is warming up for a new Logback (and SLF4J?) release. I am pretty sure he will do his part in PR, particularly i

Re: Cek's new log4j vs logback benchmark

Yes, I'm still looking into this. I agree that the zero-garbage code is difficult to follow, and Loom virtual threads will have less reuse so our thread-locals will create more overhead than they're worth in many cases. Fingers crossed for Valhalla to land before Loom, but I haven't been follow

Re: Cek's new log4j vs logback benchmark

I see your point. On Thu, Aug 26, 2021 at 11:21 AM Ralph Goers wrote: > While that is true it does mean that we are locking higher up in the call > stack than we need to be. > > Ralph > > > On Aug 26, 2021, at 11:13 AM, Tim Perry wrote: > > > > I’m fairly certain the JIT will optimize out the l

Re: Cek's new log4j vs logback benchmark

While that is true it does mean that we are locking higher up in the call stack than we need to be. Ralph > On Aug 26, 2021, at 11:13 AM, Tim Perry wrote: > > I’m fairly certain the JIT will optimize out the locking operations on the > nested synchronized calls after a while. I’m not sure how

Re: Cek's new log4j vs logback benchmark

I’m fairly certain the JIT will optimize out the locking operations on the nested synchronized calls after a while. I’m not sure how soon into the performance tests that would happen. Tim > On Aug 26, 2021, at 10:55 AM, Ralph Goers wrote: > > So are you continuing to look at this? Frankly

Re: Cek's new log4j vs logback benchmark

So are you continuing to look at this? Frankly, the work on zero-gc stuff made this very complicated. I am not sure I can even follow the logic anymore. I also noticed that many of the methods dealing with byte buffers are synchronized. I am not sure why as only the method that moves data re

Re: Cek's new log4j vs logback benchmark

Sorry I missed replying to your question, Ralph! > Did you add the no-op appender to Ceki’s project? Or are you using our > NullAppender? I have > my doubts about using that NullAppender as it does nothing - not even render > the Layout, so > it may get completely optimized away. I added a no

Re: Cek's new log4j vs logback benchmark

I also tried that with similar results, which leads me to believe we're spending too much time copying between buffers. We've proven that log4j can get LogEvents to the appender very quickly and efficiently. Once we hit PatternLayout we write data to a StringBuilder. AbstractStringBuilder used t

Re: Cek's new log4j vs logback benchmark

Ralph, maybe a dumb idea but... Can't we simply write to /dev/null to avoid hardware's influence in the test results? On Wed, Aug 25, 2021 at 8:05 PM Ralph Goers wrote: > Did you add the no-op appender to Ceki’s project? Or are you using our > NullAppender? I have > my doubts about using that Nu

Re: Cek's new log4j vs logback benchmark

Did you add the no-op appender to Ceki’s project? Or are you using our NullAppender? I have my doubts about using that NullAppender as it does nothing - not even render the Layout, so it may get completely optimized away. I’d still like to know what kind of disks Remko did his original testing

Re: Cek's new log4j vs logback benchmark

> If we would move the appender performance aside, am I right to conclude > that the entire complex async. framework built atop Disruptor with all its > whistles and bells is yielding a diminishing performance gain compared to a > simple off the shelf blocking queue? I haven't seen any data that w

Re: Cek's new log4j vs logback benchmark

Carter, Thanks for following up. I knew I had to be missing something. I don’t know why I didn’t see the system property being set. Ralph > On Aug 20, 2021, at 5:19 PM, Carter Kozak wrote: > > The benchmark itself sets the system property to opt into > AsyncLoggerContextSelector: > https://g

Re: Cek's new log4j vs logback benchmark

Does it help that we have five different ways to do async logging? Matt Sicker > On Aug 20, 2021, at 19:19, Carter Kozak wrote: > > The benchmark itself sets the system property to opt into > AsyncLoggerContextSelector: > https://github.com/ceki/logback-perf/blob/5f6b10693959b6ecf1b82abddb052

Re: Cek's new log4j vs logback benchmark

The benchmark itself sets the system property to opt into AsyncLoggerContextSelector: https://github.com/ceki/logback-perf/blob/5f6b10693959b6ecf1b82abddb052e89fe063e89/src/main/java/ch/qos/logback/perf/AsyncWithFileAppenderBenchmark.java#L61

Re: Cek's new log4j vs logback benchmark

I don’t understand. His async configuration for Log4j 2 isn’t async. I didn’t see him set the system property. The log4j2 config file says But he didn’t configure an AsyncLogger or AsyncRoot and there is no Async Appender configured. Ralph > On Aug 20, 2021, at 9:14 AM, Carter Kozak wrote: >

Re: Cek's new log4j vs logback benchmark

Benchmarks were using an unpublished version of logback that works differently than the release version I tested against -- continuing the conversation there, but I'll report back here once dust settles. Rerunning the benchmarks with a logback snapshot from source shows that async logback with o

Re: Cek's new log4j vs logback benchmark

Feel free to respond to his tweet. Ralph > On Aug 20, 2021, at 7:15 AM, Carter Kozak wrote: > > Thanks for flagging this! I've responded to the tweet, copying it here as > well for posterity: > > Looking at the logback benchmark it appears that no bytes are being written > to target/test-ou

Re: Cek's new log4j vs logback benchmark

Thanks for flagging this! I've responded to the tweet, copying it here as well for posterity: Looking at the logback benchmark it appears that no bytes are being written to target/test-output/logback-async-perf.log. Upon closer inspection the logback asyncappender is in an started=false state,

Cek's new log4j vs logback benchmark

Hello, Ceki has recently posted a Tweet stating that both log4j 1 and logback performs better than log4j 2 in async mode: https://twitter.com/ceki/status/1428461637917360131?s=19 https://github.com/ceki/logback-perf I don't know much about how async wiring is done under the hood, yet, if his cla