Re: Logback performance improvements

Let's think about what is the relevant metric for users. I guess that quite some users value minimal slowdown of the application over maximal rate of log events written out. On Sun, Feb 12, 2017 at 3:41 PM, Remko Popma wrote: > But I agree it is interesting to see that a

Re: Logback performance improvements

I found a comment somewhere (probably an old comment) that asked why Log4j 2 even exists when you could just use JUL. I feel like maybe we should make a JSR/JEP/whatever to deprecate JUL entirely. On 12 February 2017 at 08:54, Remko Popma wrote: >

Re: Logback performance improvements

#FriendsDontLetFriendsUseJavaUtilLogging On Sun, Feb 12, 2017 at 11:41 PM, Remko Popma wrote: > But I agree it is interesting to see that a simple (RAF)FileAppender will > outperform async logging if the sustained logging rate is faster than the > appender can handle for

Re: Logback performance improvements

But I agree it is interesting to see that a simple (RAF)FileAppender will outperform async logging if the sustained logging rate is faster than the appender can handle for long enough to fill up the queue. I've heard people in the high performance computing world mention this but I hadn't seen

Re: Logback performance improvements

The queue is bigger but still fills up quickly because all the benchmarks do is add events as quickly as possible and the FileAppender can't keep up with that rate. Sent from my iPhone > On Feb 12, 2017, at 16:19, Apache wrote: > > I added the tests so you guys

Re: Logback performance improvements

I added the tests so you guys could run them and take a look. I have no problem with the changes being reverted. As I think I said, I expected most of the async appenders to back up. I expected them to be a bit slower, but I didn’t expect them to be as slow as they are when the queue is full.

Re: Logback performance improvements

I don't think it is a good idea to mix async tests with sync tests. We already have separate benchmarks for the various ways to log asynchronously, if you want to compare them just run those also. JMH makes it super easy to build benchmarks but we have to be very careful that the test really

Re: Logback performance improvements

Whoa, I wonder how async MMF benchmarks compare. Also, I wonder if there's some sort of cloud service out there we can use for free to run benchmarks on a regular basis. Might even be doable with a dedicated VM on builds.apache.org. On 11 February 2017 at 13:37, Apache

Re: Logback performance improvements

Just for fun I decided to add some more tests to the file appender benchmark. I’ve checked them in. Please review them to see if everything is configured so the tests make sense. Note that I would expect the async appenders to reduce to the speed of the file appender, since once the queue

Re: Logback performance improvements

Also, there are some potential issues with logback-perf: * JMH is way out of date (1.11.3 versus 1.17.4) * Less warmup iterations than we do Anyways, results for 32 threads (8 core environment): Benchmark Mode Cnt ScoreError Units

Re: Logback performance improvements

That value does look messed up. I'll re-run the 32 thread tests. Also, I'm not on the logback lists yet, so I'll sign up this afternoon. On 9 February 2017 at 14:35, Apache wrote: > What is up with that score for 32 threads? That can’t possibly be correct. > > Ralph

Re: Logback performance improvements

What is up with that score for 32 threads? That can’t possibly be correct. Ralph > On Feb 9, 2017, at 12:45 PM, Matt Sicker wrote: > > I ran the logback-perf repo on the same AWS instance. Here's the CSV data. It > appears as soon as more than one thread comes into play,

Re: Logback performance improvements

At least Logback is now consistently performing better than Log4j 1. Ralph > On Feb 9, 2017, at 12:45 PM, Matt Sicker wrote: > > I ran the logback-perf repo on the same AWS instance. Here's the CSV data. It > appears as soon as more than one thread comes into play, log4j2

Re: Logback performance improvements

Feel free to post them on the Logback user list. There is a performance thread there where Ceki asked for that feedback. Ralph > On Feb 9, 2017, at 12:45 PM, Matt Sicker wrote: > > I ran the logback-perf repo on the same AWS instance. Here's the CSV data. It > appears as

Re: Logback performance improvements

I ran the logback-perf repo on the same AWS instance. Here's the CSV data. It appears as soon as more than one thread comes into play, log4j2 has better scores. "Benchmark","Mode","Threads","Samples","Score","Score Error (99.9%)","Unit"

Re: Logback performance improvements

You might try running Ceki’s benchmark project on AWS and publish those numbers here. He also asked people to publish numbers on the Logback user’s list so he can add them to his spreadsheet. From your numbers and the numbers I’ve been getting, it is clear to me that the SSDs in Apple’s

Re: Logback performance improvements

Ran on an AWS instance (CentOS 7.2), cpuinfo says 8-core Intel(R) Xeon(R) CPU E5-2666 v3 @ 2.90GHz, not super sure about all the params involved in making the instance, but here's some data (same strangeness with MMF): Benchmark Mode Samples Score

Re: Logback performance improvements

Run on a MacBook Pro (Retina, 15-inch, Mid 2015) 2.5 GHz Intel Core i7. Can find out more hardware specs if needed. I also noticed that the memory mapped file starts out fast and slows down over time (somewhat seen by the error value here). Benchmark Mode

Re: Logback performance improvements

My results on Windows 10 64-bit laptop (java 1.8.0_51 64bit), i5-3317u CPU @ 1.70GHz (dual core with hyperthreading for 4 virtual cores), SSD hard disk: java -jar log4j-perf/target/benchmarks.jar ".*FileAppenderBenchmark.*" -f 1 -wi 10 -i 20 -t 4 -tu ms # Run complete. Total time: 00:03:58

Re: Logback performance improvements

I guess that with a memory mapped file, you leave it to the OS to do the best it can, and you lose any direct control over how it is actually done. On Thu, Feb 9, 2017 at 4:52 PM, Apache wrote: > On my Mac Pro with the slower external SSD I now got: > > Benchmark

Re: Logback performance improvements

On my Mac Pro with the slower external SSD I now got: Benchmark Mode Samples Score Error Units o.a.l.l.p.j.FileAppenderBenchmark.julFilethrpt 1073.739 ± 0.740 ops/ms o.a.l.l.p.j.FileAppenderBenchmark.log4j1File thrpt

Re: Logback performance improvements

It is there now. Ralph > On Feb 9, 2017, at 7:46 AM, Remko Popma wrote: > > can you push the correct config? > > On Thu, Feb 9, 2017 at 11:03 PM, Apache > wrote: > After modifying the configuration the

Re: Logback performance improvements

can you push the correct config? On Thu, Feb 9, 2017 at 11:03 PM, Apache wrote: > After modifying the configuration the new results on my laptop are: > > Benchmark Mode Samples Score > Error Units >

Re: Logback performance improvements

After modifying the configuration the new results on my laptop are: Benchmark Mode Samples Score Error Units o.a.l.l.p.j.FileAppenderBenchmark.julFilethrpt 1092.580 ± 3.698 ops/ms

Re: Logback performance improvements

Ceki replied on twitter that the immediateFlush option is now a parameter of the appended, not the encoder, so it looks like the confit needs to be changed and the test rerun. Ralph > On Feb 9, 2017, at 3:08 AM, Remko Popma wrote: > > FYI, The write and flush methods

Re: Logback performance improvements

FYI, The write and flush methods in BufferedOutputStream are also synchronized, so we won't be able to do away with synchronization completely. In OutputStreamManager we synchronize multiple methods but these are nested calls. I thought reentrant synchronization had negligible overhead but I

Re: Logback performance improvements

I will try taking a look when I get home from work tonight. Ceki reported some strange numbers about Log4j 1 outperforming Log4j2 before, and when we showed results from 3 or 4 environments that disproved his claims, he never really explained how that happened. Not sure if there's some issue

Re: Logback performance improvements

Logback 1.2 has been released. I just ran our performance benchmarks against it and I am mystified. Logback 1.2 is coming out almost 4 times slower than 1.1.10. Can someone please verify my results? I am running them with java -jar target/benchmarks.jar ".*FileAppenderBenchmark.*" -f 1 -wi 10

Re: Logback performance improvements

I’m pretty sure the problem we have is that a) we are synchronizing many methods and b) we are synchronizing more than just the write. Unfortunately, I can’t figure out how to reduce that based on how dispersed the code has gotten. Ralph > On Feb 8, 2017, at 10:14 AM, Apache

Re: Logback performance improvements

I tried to modify FileManager to just use a BufferedOutputStream but discovered I couldn’t as the layouts now require the ByteBuffer. Ralph > On Feb 8, 2017, at 12:14 AM, Apache wrote: > > The append method isn’t synchronized but the writeBytes method acquires a

Re: Logback performance improvements

Is it possible that the memory mapped file starts resizing and remapping at this point? Sent from my iPhone > On Feb 8, 2017, at 15:12, Apache wrote: > > I used a ThreadLocal byte buffer and wrote to the file channel and if > anything, it performed slightly worse.

Re: Logback performance improvements

The append method isn’t synchronized but the writeBytes method acquires a lock. His code is actually a lot simpler than ours in that it just uses a BufferedOutputStream and he only obtains the lock when he is writing to it. Ralph > On Feb 6, 2017, at 5:23 PM, Matt Sicker

Re: Logback performance improvements

I used a ThreadLocal byte buffer and wrote to the file channel and if anything, it performed slightly worse. This is probably because I had to write after ever event, not when the buffer was full, otherwise the ordering of events in the output would get messed up. I decided to throw the

Re: Logback performance improvements

True, but I would still like to also see what difference it makes using the FileChannel instead of the OutputStream. Ralph > On Feb 7, 2017, at 9:45 AM, Remko Popma wrote: > > That is all doable but it may be a good idea to test if that is really where > the bottleneck

Re: Logback performance improvements

We should try to override getBuffer()/drain()/flushBuffer() from OutputStreamManager in FileManager and RandomAccessFileManager (just like we do in MenoryMappedFileManager). On Tue, Feb 7, 2017 at 5:45 PM, Remko Popma wrote: > That is all doable but it may be a good idea

Re: Logback performance improvements

That is all doable but it may be a good idea to test if that is really where the bottleneck is. We could try whether we get better numbers if we remove the current synchronization (ignoring any scrambled output, just for testing purposes). On Wed, Feb 8, 2017 at 1:40 AM, Apache

Re: Logback performance improvements

In looking at FileManager and OutputStreamManager it does have a ByteBuffer but it requires synchronization. I am thinking it might make more sense to have a ThreadLocal ByteBuffer and then pass that to FileChannel.write() so that no synchronization is required. Ralph > On Feb 7, 2017, at

Re: Logback performance improvements

Can't we use the ByteBuffers introduced in the GC-free epic? I was under the impression that byte arrays being passed to appenders was created from a ByteBuffer at this point, though I haven't really taken a close look at this. On 7 February 2017 at 10:05, Apache

Re: Logback performance improvements

A FileChannel is guaranteed to be thread safe. You can obtain a FileChannel from a FlieOutputStream, so that would seem to imply that FileOutputStream might be thread-safe, but you can’t really know that without looking at the source. The problem is that FileChannel.write() takes a ByteBuffer

Re: Logback performance improvements

I looked at 1.2-SNAPSHOT and 1.1.10 and saw nothing special other than a lack of a synchronized keyword on the equivalent append method. Perhaps he figured out a simpler way to emulate locking? I've been working with async/non-blocking streaming APIs for long enough now that I can't even remember

Re: Logback performance improvements

Logback 1.2-SNAPSHOT Ralph > On Feb 6, 2017, at 8:29 PM, Remko Popma wrote: > > Sorry what 1.2 do you mean? > > Sent from my iPhone > > On Feb 7, 2017, at 11:06, Apache > wrote: > >> In 1.2? That may

Re: Logback performance improvements

Sorry what 1.2 do you mean? Sent from my iPhone > On Feb 7, 2017, at 11:06, Apache wrote: > > In 1.2? That may work for a FileOutputStream but it isn’t guaranteed to work > for others. > > Ralph > >> On Feb 6, 2017, at 5:23 PM, Matt Sicker

Re: Logback performance improvements

In 1.2? That may work for a FileOutputStream but it isn’t guaranteed to work for others. Ralph > On Feb 6, 2017, at 5:23 PM, Matt Sicker wrote: > > I'm not sure if I'm looking in the right place, but a major difference now > between Logback's appenders and Log4j's is that

Re: Logback performance improvements

I'm not sure if I'm looking in the right place, but a major difference now between Logback's appenders and Log4j's is that Logback isn't synchronized on the append method. On 6 February 2017 at 18:18, Matt Sicker wrote: > Is this something we can improve performance on by

Re: Logback performance improvements

Is this something we can improve performance on by implementing a file appender based on FileChannel or AsynchronousFileChannel instead of OutputStream? On 6 February 2017 at 17:50, Apache wrote: > Ceki has updated his numbers to include those reported on the mailing

Re: Logback performance improvements

Ceki has updated his numbers to include those reported on the mailing list. https://docs.google.com/spreadsheets/d/1cpb5D7qnyye4W0RTlHUnXedYK98catNZytYIu5D91m0/edit#gid=0 I haven’t run the tests

Re: Logback performance improvements

Yes, that is still the standard approach most people use and is the only way to provide a head-to-head comparison against the logging frameworks. Ralph > On Feb 6, 2017, at 8:02 AM, Matt Sicker wrote: > > This is all in a synchronous appender, right? Either way, that's

Re: Logback performance improvements

This is all in a synchronous appender, right? Either way, that's rather interesting. On 6 February 2017 at 07:54, Apache wrote: > Someone posted numbers on the Logback user’s list that match mine. It > shows Logback 1.1.9 was pretty terrible, 1.1.10 is somewhat

Re: Logback performance improvements

Someone posted numbers on the Logback user’s list that match mine. It shows Logback 1.1.9 was pretty terrible, 1.1.10 is somewhat better and 1.2-SNAPSHOT is on par or slightly better than Log4j 2. Ralph > On Feb 5, 2017, at 3:25 PM, Matt Sicker wrote: > > I think we need

Re: Logback performance improvements

I think we need some comparisons on the log4j side: file appender with 256k buffer size, random access file appender with 256k buffer size (which appears to be the default), and memory mapped file appender. It'd be cool to see how these compose with async logging enabled in both log4j and logback.

Re: Logback performance improvements

You should run the code at https://github.com/ceki/logback-perf to compare your results to Ceki’s. You also should capture the cpubenchmark speed of your processor and get the speed of your hard drive. I used Blackmagic speed test on my Mac. I am

Re: Logback performance improvements

If you want, I can run tests on Windows once the build works on Windows again. Let me know what args/command line... Gary On Feb 5, 2017 11:58 AM, "Apache" wrote: > I guess my MacBook Pro must fit in the Slow CPU/Fast Hard drive category. > With Logback 1.10 and -t

Re: Logback performance improvements

I guess my MacBook Pro must fit in the Slow CPU/Fast Hard drive category. With Logback 1.10 and -t 4 now get Benchmark Mode SamplesScore Error Units o.a.l.l.p.j.FileAppenderBenchmark.julFilethrpt 2098187.673 ± 4935.712