logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Remko Popma <remko.po...@gmail.com>
Subject Re: Fast and Furious
Date Mon, 21 Mar 2016 07:29:20 GMT
Thanks. Will take another look.

On Monday, 21 March 2016, Gary Gregory <garydgregory@gmail.com> wrote:

> FYI: Yourkit has three profiling modes: sampling, counting and tracing.
> On Mar 20, 2016 11:47 PM, "Remko Popma" <remko.popma@gmail.com
> <javascript:_e(%7B%7D,'cvml','remko.popma@gmail.com');>> wrote:
>
>> I did try profiling with YourKit and MissionControl but they did not tell
>> me much. I suppose a sampling profiler does not help much for problems like
>> this when we are not spending a lot of time in certain methods... I'm
>> thinking to experiment further with the different event options for perf
>> stat, and take a look at Oracle Solaris Studio Performance Analyzer.
>>
>> There were many changes in 2.4 but most of the performance-related
>> changes were downstream from the Disruptor in layout etc. They should not
>> matter since I'm only measuring how fast an application can add simple
>> string log events in to the ring buffer. (The perf test is with a No-Op
>> appender.) The only thing that jumps out to me is the nano time support
>> change... I will experiment with how performance changes if I roll back
>> that feature.
>>
>> I'm not giving up just yet.
>>
>>
>> On Mon, Mar 21, 2016 at 5:17 PM, Ralph Goers <ralph.goers@dslextreme.com
>> <javascript:_e(%7B%7D,'cvml','ralph.goers@dslextreme.com');>> wrote:
>>
>>> Unfortunately there were a lot of changes in 2.4, many of which said
>>> they were to improve performance. We also switched from Java 6 to Java 7.
>>>
>>> Did you try profiling with YourKit?
>>>
>>> Ralph
>>>
>>> On Mar 20, 2016, at 11:07 PM, Remko Popma <remko.popma@gmail.com
>>> <javascript:_e(%7B%7D,'cvml','remko.popma@gmail.com');>> wrote:
>>>
>>> Quick update on the ongoing investigation in the performance regression:
>>> I tried running SimplePerfTest on linux with perf stat and got these
>>> results:
>>> <investigation20160319_23898_image002.png>
>>> ​How to read this:
>>> * Throughput is number of messages logged per second (1.0 ~= 7 million
>>> msg/sec)
>>> * Instr/cycle is instructions per clock cycle
>>> * Branch miss% is the number of branch prediction misses as a percentage
>>> of all branches
>>>
>>> Analysis:
>>> Throughput of log4j 2.0-2.3 on this machine is about 5.3 million msg/sec
>>> on average.
>>> From 2.4, this suddenly gaps down to 3.9 million msg/sec.
>>> At the same time, the number of branch misses jump up from 0.27% to
>>> 0.63%, correlating with a much less efficient execution: from 1.47 to 1.06
>>> instructions per clock cycle.
>>>
>>> Conclusion:
>>> It seems that one or more of the changes made in log4j 2.4 resulted in
>>> an increase in branch misses during execution.
>>> This may not be the only problem but it may help to give some direction
>>> in the search.
>>>
>>> Remko
>>>
>>> On Thu, Mar 10, 2016 at 3:06 AM, Remko Popma <remko.popma@gmail.com
>>> <javascript:_e(%7B%7D,'cvml','remko.popma@gmail.com');>> wrote:
>>>
>>>> I think you're right, that one should not leak.
>>>>
>>>> On Thu, Mar 10, 2016 at 2:40 AM, Matt Sicker <boards@gmail.com
>>>> <javascript:_e(%7B%7D,'cvml','boards@gmail.com');>> wrote:
>>>>
>>>>> I know it's Java 1.8+, but does ThreadLocal.withInitial(Supplier<S>)
>>>>> prevent that memory leak? They use their own JDK class to subclass
>>>>> ThreadLocal, so that shouldn't leak.
>>>>>
>>>>> On 8 March 2016 at 22:43, Remko Popma <remko.popma@gmail.com
>>>>> <javascript:_e(%7B%7D,'cvml','remko.popma@gmail.com');>> wrote:
>>>>>
>>>>>> ThreadLocals containing JDK classes (StringBuilder, etc) are not a
>>>>>> problem. Their classloader is the system classloader, not the web app
>>>>>> classloader, so these ThreadLocals do not have a reference to the web app
>>>>>> classes and do not prevent web app classes from being garbage collected.
>>>>>>
>>>>>> This idiom is safe:
>>>>>>
>>>>>> class SafeClass {
>>>>>>     // The type of this field is java.lang.ThreadLocal, and
>>>>>>     // both the key (ThreadLocal) and the value (StringBuilder) are JDK classes.    // This idiom is safe and will not cause memory leaks in web apps.
>>>>>>     static ThreadLocal<StringBuilder> safe = new ThreadLocal<StringBuilder>();
>>>>>>
>>>>>>     private StringBuilder getThreadLocalStringBuilder() {
>>>>>>         StringBuilder value = safe.get();
>>>>>>         if (value == null) {
>>>>>>             value = new StringBuilder(1024);
>>>>>>             safe.set(value);
>>>>>>         }
>>>>>>         return value;
>>>>>>     }
>>>>>> }
>>>>>>
>>>>>> However, as soon as we create an anonymous subclass like below we
>>>>>> cause memory leaks again:
>>>>>>
>>>>>> class MemoryLeakingClass {
>>>>>>     // The type of this field is MemoryLeakingClass$1, an anonymous subclass of java.lang.ThreadLocal!
>>>>>>     // In a web app, the classloader of this class is the web app class loader: may cause memory leak...
>>>>>>     static ThreadLocal<StringBuilder> anonymousSubclass = new ThreadLocal<StringBuilder>() {
>>>>>>
>>>>>>         @Override
>>>>>>         protected StringBuilder initialValue() {
>>>>>>             return new StringBuilder(1024);
>>>>>>         }
>>>>>>     };
>>>>>> }
>>>>>>
>>>>>>
>>>>>>
>>>>>> On Wed, Mar 9, 2016 at 11:32 AM, Ralph Goers <
>>>>>> ralph.goers@dslextreme.com
>>>>>> <javascript:_e(%7B%7D,'cvml','ralph.goers@dslextreme.com');>> wrote:
>>>>>>
>>>>>>> I still am unclear as to why you are thinking GC-free mode won’t
>>>>>>> work in web apps.  What is the issue with ThreadLocals that causes the
>>>>>>> problem?  We are using ThreadLocals for other things that seem to be
>>>>>>> working.
>>>>>>>
>>>>>>> Ralph
>>>>>>>
>>>>>>> On Mar 8, 2016, at 3:05 PM, Remko Popma <remko.popma@gmail.com
>>>>>>> <javascript:_e(%7B%7D,'cvml','remko.popma@gmail.com');>> wrote:
>>>>>>>
>>>>>>> Some of the recent changes were to fix issues introduced by the
>>>>>>> reusable message idea. It is good that we are not rushing this release, and
>>>>>>> thanks everyone for your patience.
>>>>>>>
>>>>>>> I originally wanted to make GC-free mode the default to begin with,
>>>>>>> but it may be smart to initially require that users switch GC-free mode on
>>>>>>> explicitly, and only make it the default after it has gained a track
>>>>>>> record. (Even so, it would only be switched on automatically for non-web
>>>>>>> apps.)
>>>>>>>
>>>>>>> The async logger performance investigation is still ongoing. I hope
>>>>>>> to be able to resolve it and do the GC-free write-up including performance
>>>>>>> test results in the next few weeks. I am currently on a business trip,
>>>>>>> working with people creating low latency trading systems, and they have
>>>>>>> good ideas on how to investigate the performance regression, so that is
>>>>>>> helpful.
>>>>>>>
>>>>>>> On Wed, Mar 9, 2016 at 4:01 AM, Gary Gregory <garydgregory@gmail.com
>>>>>>> <javascript:_e(%7B%7D,'cvml','garydgregory@gmail.com');>> wrote:
>>>>>>>
>>>>>>>> I'm even more concerned now that more of the no-GC changes are
>>>>>>>> coming in, still, fast and furious.
>>>>>>>>
>>>>>>>> I see what smells like a lot of non-OO code fly by here and there:
>>>>>>>> lots if-else-if-else-if-else, as opposed to subclassing or delegation if
>>>>>>>> appropriate.
>>>>>>>>
>>>>>>>> Are we rushing toward this no-GC goal without considering speed
>>>>>>>> performance?
>>>>>>>>
>>>>>>>> Where are we on the async logger slow down investigation?
>>>>>>>>
>>>>>>>> Concerned and glad to see to much activity all at the same time,
>>>>>>>> Gary
>>>>>>>>
>>>>>>>> On Thu, Mar 3, 2016 at 1:23 PM, Matt Sicker <boards@gmail.com
>>>>>>>> <javascript:_e(%7B%7D,'cvml','boards@gmail.com');>> wrote:
>>>>>>>>
>>>>>>>>> Remko (and anyone else who wants to try and solve this regression):
>>>>>>>>>
>>>>>>>>> https://www.jclarity.com/product/censum-free-trial/
>>>>>>>>>
>>>>>>>>> Go ahead and get the trial and the guys at JClarity will give us
>>>>>>>>> licenses. I'd use your apache.org email to be safe.
>>>>>>>>>
>>>>>>>>> On 3 March 2016 at 11:27, Matt Sicker <boards@gmail.com
>>>>>>>>> <javascript:_e(%7B%7D,'cvml','boards@gmail.com');>> wrote:
>>>>>>>>>
>>>>>>>>>> So far, Remko's proposal is language-neutral since he defined
>>>>>>>>>> endianness (big endian like java, but we could use either since ByteBuffer
>>>>>>>>>> supports both) and field widths..
>>>>>>>>>>
>>>>>>>>>> On 3 March 2016 at 03:15, Mikael Ståldal <
>>>>>>>>>> mikael.staldal@magine.com
>>>>>>>>>> <javascript:_e(%7B%7D,'cvml','mikael.staldal@magine.com');>>
>>>>>>>>>> wrote:
>>>>>>>>>>
>>>>>>>>>>> If we are to design a new binary log event format, then I think
>>>>>>>>>>> that we should make sure that it is not Java / JVM specific, and that it
>>>>>>>>>>> will be reasonably easy to implement reading and writing of it on other
>>>>>>>>>>> platforms.
>>>>>>>>>>>
>>>>>>>>>>> On Thu, Mar 3, 2016 at 5:14 AM, Remko Popma <
>>>>>>>>>>> remko.popma@gmail.com
>>>>>>>>>>> <javascript:_e(%7B%7D,'cvml','remko.popma@gmail.com');>> wrote:
>>>>>>>>>>>
>>>>>>>>>>>> I created https://issues.apache.org/jira/browse/LOG4J2-1305 as
>>>>>>>>>>>> a write up of my current thinking on the topic and a place to discuss
>>>>>>>>>>>> ideas. Still need to add some things we discussed here (tools,
>>>>>>>>>>>> endianness, versioning etc).
>>>>>>>>>>>>
>>>>>>>>>>>> It's a fascinating topic but I still have a lot of work to do
>>>>>>>>>>>> on the GC-free epic before I can start working on this one.
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> On Thursday, 3 March 2016, Remko Popma <remko.popma@gmail.com
>>>>>>>>>>>> <javascript:_e(%7B%7D,'cvml','remko.popma@gmail.com');>> wrote:
>>>>>>>>>>>>
>>>>>>>>>>>>> Not Java Serialization, I was thinking simple
>>>>>>>>>>>>> ByteBuffer.putLong, putInt, putBytes. This is much more performant (
>>>>>>>>>>>>> http://mechanical-sympathy.blogspot.jp/2012/07/native-cc-like-performance-for-java.html).
>>>>>>>>>>>>> SBE (Simple Binary Encoding) seems overkill, but open to other opinions.
>>>>>>>>>>>>>
>>>>>>>>>>>>> The less conditional logic in there the better, so I'm not
>>>>>>>>>>>>> that interested in configurability. All log event fields,
>>>>>>>>>>>>> ok. ThreadContextMap/Stack keys and values: similarly to other repeating
>>>>>>>>>>>>> strings like logger names: write to separate mapping file & only write int
>>>>>>>>>>>>> values (for count as well as key/value indices) to the "main" log file.
>>>>>>>>>>>>>
>>>>>>>>>>>>> Two things we would need to decide is how to handle
>>>>>>>>>>>>> versioning, and what Endianness to use.
>>>>>>>>>>>>>
>>>>>>>>>>>>> Version information (possibly with schema info) could be
>>>>>>>>>>>>> written to the log file header.
>>>>>>>>>>>>>
>>>>>>>>>>>>> Endianness could also be written to the header, or we could
>>>>>>>>>>>>> simply say we use network byte order (big endian). Intel chips use little
>>>>>>>>>>>>> endian, but apparently swapping is implemented with an intrinsic and is
>>>>>>>>>>>>> very fast.
>>>>>>>>>>>>>
>>>>>>>>>>>>> On Thursday, 3 March 2016, Matt Sicker <boards@gmail.com>
>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>
>>>>>>>>>>>>>> At that point, it would be nice if it were extensible. There
>>>>>>>>>>>>>> are some neat binary formats we could use that would allow for that.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> On 2 March 2016 at 12:09, Gary Gregory <
>>>>>>>>>>>>>> garydgregory@gmail.com> wrote:
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> I think we'd need to provide all LogEvent fields.
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Gary
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> On Wed, Mar 2, 2016 at 9:13 AM, Remko Popma <
>>>>>>>>>>>>>>> remko.popma@gmail.com> wrote:
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> That's what I meant, I didn't make myself clear. For
>>>>>>>>>>>>>>>> example, we could offer a simple binary layout:
>>>>>>>>>>>>>>>> time stamp (8 bytes)
>>>>>>>>>>>>>>>> level int (4 bytes)
>>>>>>>>>>>>>>>> thread ID (4 bytes) - Thread names in separate file
>>>>>>>>>>>>>>>> Logger ID (4 bytes) - Logger names in separate file.
>>>>>>>>>>>>>>>> message length (4 bytes)
>>>>>>>>>>>>>>>> message type (2 bytes)
>>>>>>>>>>>>>>>> message data (variable length)
>>>>>>>>>>>>>>>> throwable length (4 bytes)
>>>>>>>>>>>>>>>> throwable data (variable length)
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> It's a very different approach to logging. On the plus
>>>>>>>>>>>>>>>> side, this would be extremely compact and very fast to write.
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> On the other hand it would require a separate tool to
>>>>>>>>>>>>>>>> decode/display the data in human readable form. Such a tool should handle
>>>>>>>>>>>>>>>> text messages out of the box, but for custom messages I image there could
>>>>>>>>>>>>>>>> be some plugin mechanism for custom decoders.
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> All very interesting...
>>>>>>>>>>>>>>>> :-)
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Sent from my iPhone
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> On 2016/03/03, at 0:01, Matt Sicker <boards@gmail.com>
>>>>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> That's what I thought at first, but he means non-human
>>>>>>>>>>>>>>>> readable formats since we all use tools to parse logs as it is (Splunk and
>>>>>>>>>>>>>>>> ELK are the big two I know of).
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> On 2 March 2016 at 02:15, Remko Popma <
>>>>>>>>>>>>>>>> remko.popma@gmail.com> wrote:
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Re: binary logging, I think he's talking about providing
>>>>>>>>>>>>>>>>> an API to log objects directly into byte buffers without turning them into
>>>>>>>>>>>>>>>>> Strings first.
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> https://issues.apache.org/jira/browse/LOG4J2-1274 and
>>>>>>>>>>>>>>>>> https://issues.apache.org/jira/browse/LOG4J2-506
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> were created with that in mind and should be a good step
>>>>>>>>>>>>>>>>> in that direction.
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Sent from my iPhone
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> On 2016/03/02, at 15:11, Gary Gregory <
>>>>>>>>>>>>>>>>> garydgregory@gmail.com> wrote:
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Well, I've often wondered about creating a binary format
>>>>>>>>>>>>>>>>> but it seems that you could use JSON+ZIP or BSON and get most of the
>>>>>>>>>>>>>>>>> advantages.
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Gary
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> On Tue, Mar 1, 2016 at 9:12 PM, Matt Sicker <
>>>>>>>>>>>>>>>>> boards@gmail.com> wrote:
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> One other interesting thing I learned is that improper
>>>>>>>>>>>>>>>>>> use of logging is a huge source of performance problems. The GC-free
>>>>>>>>>>>>>>>>>> parameterized message factory will help with one aspect of that (I
>>>>>>>>>>>>>>>>>> suggested parameterized messages, but he countered with the Object[] that
>>>>>>>>>>>>>>>>>> is created), and encouraging users to use a Supplier<String> instead of
>>>>>>>>>>>>>>>>>> passing parameters should help as well (especially when those parameters
>>>>>>>>>>>>>>>>>> have to be computed). He had some strong criticisms of logging APIs
>>>>>>>>>>>>>>>>>> promoting bad practices which stems all the way back to log4j1 and affects
>>>>>>>>>>>>>>>>>> pretty much every logging API in Java (some criticisms were actually
>>>>>>>>>>>>>>>>>> outdated or didn't consider newer features of the API like markers and the
>>>>>>>>>>>>>>>>>> huge amount of filters available).
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> His other big idea was promoting the use of binary
>>>>>>>>>>>>>>>>>> logging formats because humans rarely read the raw log files as it is, but
>>>>>>>>>>>>>>>>>> it's not like there's a standard way to do that.
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> Now I kinda wonder if he'll find this thread one day and
>>>>>>>>>>>>>>>>>> tell me how I misinterpreted him or something. ;)
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> On 1 March 2016 at 22:28, Matt Sicker <boards@gmail.com>
>>>>>>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>> Alright, I learned some interesting things. I'm going to
>>>>>>>>>>>>>>>>>>> get us some tools we can use to try and profile this. Otherwise, he did
>>>>>>>>>>>>>>>>>>> suggest trying out this project:
>>>>>>>>>>>>>>>>>>> https://github.com/RichardWarburton/honest-profiler
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>> On 1 March 2016 at 19:31, Matt Sicker <boards@gmail.com>
>>>>>>>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>> So far he's said something about using lambdas for lazy
>>>>>>>>>>>>>>>>>>>> evaluation (though I don't think that would actually help us at all). I'll
>>>>>>>>>>>>>>>>>>>> try to talk to him one-on-one afterward to delve more into this.
>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>> On 1 March 2016 at 18:13, Ralph Goers <
>>>>>>>>>>>>>>>>>>>> ralph.goers@dslextreme.com> wrote:
>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>> Actually, most of the tests have the commands in the
>>>>>>>>>>>>>>>>>>>>> comments right in the class. Just cut and past.
>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>> Ralph
>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>> On Mar 1, 2016, at 1:43 PM, Matt Sicker <
>>>>>>>>>>>>>>>>>>>>> boards@gmail.com> wrote:
>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>> I can't even figure out how to execute the simple perf
>>>>>>>>>>>>>>>>>>>>> test class. IntelliJ gives me some annotation processing error, and doing
>>>>>>>>>>>>>>>>>>>>> it from the command line is turning into a classpath nightmare to figure
>>>>>>>>>>>>>>>>>>>>> out what jars are needed to execute the test manually.
>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>> On 1 March 2016 at 11:34, Gary Gregory <
>>>>>>>>>>>>>>>>>>>>> garydgregory@gmail.com> wrote:
>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>> Before the talk: Hi, I'm Remko, I help on Apache
>>>>>>>>>>>>>>>>>>>>>> Log4j, are you available after the preso to talk about some issue we are
>>>>>>>>>>>>>>>>>>>>>> seeing?
>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>> Gary
>>>>>>>>>>>>>>>>>>>>>> On Mar 1, 2016 8:29 AM, "Matt Sicker" <
>>>>>>>>>>>>>>>>>>>>>> boards@gmail.com> wrote:
>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>> I'm attending a JUG meetup tonight with Kirk
>>>>>>>>>>>>>>>>>>>>>>> Pepperdine presenting. It's supposed to be a Java performance workshop type
>>>>>>>>>>>>>>>>>>>>>>> of thing, so if you've got a decent way to ask about it, I could see if he
>>>>>>>>>>>>>>>>>>>>>>> can help figure out this regression. I can at least show off the
>>>>>>>>>>>>>>>>>>>>>>> SimplePerfTest and any microbenchmarks we have.
>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>> On 28 February 2016 at 11:54, Matt Sicker <
>>>>>>>>>>>>>>>>>>>>>>> boards@gmail.com> wrote:
>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>> Take a look at the git bisect command. Might help
>>>>>>>>>>>>>>>>>>>>>>>> you find which changes caused the problem.
>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>> On Sunday, 28 February 2016, Gary Gregory <
>>>>>>>>>>>>>>>>>>>>>>>> garydgregory@gmail.com> wrote:
>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>> Thank you for digging in Remko. This is will be a
>>>>>>>>>>>>>>>>>>>>>>>>> nice theme to publicize when you get it figured out.
>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>> Gary
>>>>>>>>>>>>>>>>>>>>>>>>> On Feb 28, 2016 4:08 AM, "Remko Popma" <
>>>>>>>>>>>>>>>>>>>>>>>>> remko.popma@gmail.com> wrote:
>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>> After removing the potential impact of appenders
>>>>>>>>>>>>>>>>>>>>>>>>>> and layouts by testing with
>>>>>>>>>>>>>>>>>>>>>>>>>> log4j-core\src\test\resources\perf-CountingNoOpAppender.xml and
>>>>>>>>>>>>>>>>>>>>>>>>>> org.apache.logging.log4j.core.async.perftest.SimplePerfTest, I've confirmed
>>>>>>>>>>>>>>>>>>>>>>>>>> my initial numbers:
>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>> 2.0: 7.5M ops/sec
>>>>>>>>>>>>>>>>>>>>>>>>>> 2.1: 6M ops/sec
>>>>>>>>>>>>>>>>>>>>>>>>>> 2.2: 6M ops/sec
>>>>>>>>>>>>>>>>>>>>>>>>>> 2.3: 6M ops/sec
>>>>>>>>>>>>>>>>>>>>>>>>>> 2.4: 4.5M ops/sec
>>>>>>>>>>>>>>>>>>>>>>>>>> 2.5: 4M ops/sec
>>>>>>>>>>>>>>>>>>>>>>>>>> 2.6: 2M ops/sec
>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>> I tried reverting various changes made to
>>>>>>>>>>>>>>>>>>>>>>>>>> AsyncLogger since 2.0, performance improves a little up to 4M ops/sec.
>>>>>>>>>>>>>>>>>>>>>>>>>> However, when completely reverting AsyncLogger
>>>>>>>>>>>>>>>>>>>>>>>>>> source to the 2.0 version, performance is back to 7.5M ops/sec.
>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>> I'll try starting from the 2.0 source and getting
>>>>>>>>>>>>>>>>>>>>>>>>>> back to 2.6 functionality without losing performance...
>>>>>>>>>>>>>>>>>>>>>>>>>> (Lengthy process...)
>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>> On Sat, Feb 27, 2016 at 12:18 PM, Remko Popma <
>>>>>>>>>>>>>>>>>>>>>>>>>> remko.popma@gmail.com> wrote:
>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>> This is the PerfTestDriver test class (in
>>>>>>>>>>>>>>>>>>>>>>>>>>> log4j-core/test, package ...async.perf).
>>>>>>>>>>>>>>>>>>>>>>>>>>> Mainly perf3PlainNoLocation.xml:
>>>>>>>>>>>>>>>>>>>>>>>>>>> RollingRandomAccessFileAppender, PatternLayout,
>>>>>>>>>>>>>>>>>>>>>>>>>>> all loggers are AsyncLoggers, logging a simple string without parameters.
>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>> Profiling with YourKit did not tell me anything
>>>>>>>>>>>>>>>>>>>>>>>>>>> useful.
>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>> I'm now eliminating the effect of
>>>>>>>>>>>>>>>>>>>>>>>>>>> Layouts/Appenders, using CountingNoOpAppender, and seeing similar numbers.
>>>>>>>>>>>>>>>>>>>>>>>>>>> So this seems to be mostly an issue in AsyncLogger.
>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>> I'll let you know when I find out more.
>>>>>>>>>>>>>>>>>>>>>>>>>>> There's a lot of trial and error here, so this
>>>>>>>>>>>>>>>>>>>>>>>>>>> may take a while...
>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>> Remko
>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>> Sent from my iPhone
>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>> On 2016/02/26, at 21:02, Mikael Ståldal <
>>>>>>>>>>>>>>>>>>>>>>>>>>> mikael.staldal@magine.com> wrote:
>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>> Which components (appenders, layouts) are
>>>>>>>>>>>>>>>>>>>>>>>>>>> involved in the tests? Would it be possible to do some profiling to see if
>>>>>>>>>>>>>>>>>>>>>>>>>>> there is any particular component which is to blame?
>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>> On Fri, Feb 26, 2016 at 12:51 PM, Remko Popma <
>>>>>>>>>>>>>>>>>>>>>>>>>>> remko.popma@gmail.com> wrote:
>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>>> To give you some rough impression on concrete
>>>>>>>>>>>>>>>>>>>>>>>>>>>> numbers for this trend:
>>>>>>>>>>>>>>>>>>>>>>>>>>>> 2.0: ~6M ops/sec
>>>>>>>>>>>>>>>>>>>>>>>>>>>> 2.1-2.2: ~5M ops/sec
>>>>>>>>>>>>>>>>>>>>>>>>>>>> 2.3-2.4: ~3-4M ops/sec
>>>>>>>>>>>>>>>>>>>>>>>>>>>> 2.5: ~3M ops/sec
>>>>>>>>>>>>>>>>>>>>>>>>>>>> 2.6: ~2M ops/sec
>>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>>> On Friday, 26 February 2016, Remko Popma <
>>>>>>>>>>>>>>>>>>>>>>>>>>>> remko.popma@gmail.com> wrote:
>>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> You're absolutely right. I still have quite a
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> few unit tests to add.
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> Initial perf testing shows a downward trend in
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> Async Logger performance with every release. (Logging simple
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> string messages without params.) This is worrisome and I'm focusing on
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> figuring that out first: this will likely involve additional code changes
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> and I'll add more tests after that.
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> Sent from my iPhone
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> On 2016/02/26, at 10:38, Gary Gregory <
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> garydgregory@gmail.com> wrote:
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> Wow, I love the activity we are seeing toward
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> 2.6! All the perf work on top of an existing sizable change set. Very
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> exciting indeed.
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> There sure are a lot of changes coming in. I
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> hope that we all can pitch in to make sure most if not all of these changes
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> get code coverage from unit tests. I've not checked closely, but it seems
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> like we may not have good coverage _yet_, or do I have the wrong impression?
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> I want to make sure we keep our stability in
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> tip top shape :-) and that we have no regression from previous releases.
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> Gary
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> Java Persistence with Hibernate, Second Edition
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> <http://www.manning.com/bauer3/>
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> JUnit in Action, Second Edition
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> <http://www.manning.com/tahchiev/>
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> Spring Batch in Action
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> <http://www.manning.com/templier/>
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> Blog: http://garygregory.wordpress.com
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> Home: http://garygregory.com/
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> Tweet! http://twitter.com/GaryGregory
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>>>>>>>>>>>>> [image: MagineTV]
>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>> *Mikael Ståldal*
>>>>>>>>>>>>>>>>>>>>>>>>>>> Senior software developer
>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>> *Magine TV*
>>>>>>>>>>>>>>>>>>>>>>>>>>> mikael.staldal@magine.com
>>>>>>>>>>>>>>>>>>>>>>>>>>> Grev Turegatan 3  | 114 46 Stockholm, Sweden  |
>>>>>>>>>>>>>>>>>>>>>>>>>>> www.magine.com
>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>> Privileged and/or Confidential Information may
>>>>>>>>>>>>>>>>>>>>>>>>>>> be contained in this message. If you are not the addressee indicated in
>>>>>>>>>>>>>>>>>>>>>>>>>>> this message
>>>>>>>>>>>>>>>>>>>>>>>>>>> (or responsible for delivery of the message to
>>>>>>>>>>>>>>>>>>>>>>>>>>> such a person), you may not copy or deliver this message to anyone. In such
>>>>>>>>>>>>>>>>>>>>>>>>>>> case,
>>>>>>>>>>>>>>>>>>>>>>>>>>> you should destroy this message and kindly
>>>>>>>>>>>>>>>>>>>>>>>>>>> notify the sender by reply email.
>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>>>>>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>>>>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>>>>>>>>>>>>>>> Java Persistence with Hibernate, Second Edition
>>>>>>>>>>>>>>>>> <http://www.manning.com/bauer3/>
>>>>>>>>>>>>>>>>> JUnit in Action, Second Edition
>>>>>>>>>>>>>>>>> <http://www.manning.com/tahchiev/>
>>>>>>>>>>>>>>>>> Spring Batch in Action <http://www.manning.com/templier/>
>>>>>>>>>>>>>>>>> Blog: http://garygregory.wordpress.com
>>>>>>>>>>>>>>>>> Home: http://garygregory.com/
>>>>>>>>>>>>>>>>> Tweet! http://twitter.com/GaryGregory
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>>>>>>>>>>>>> Java Persistence with Hibernate, Second Edition
>>>>>>>>>>>>>>> <http://www.manning.com/bauer3/>
>>>>>>>>>>>>>>> JUnit in Action, Second Edition
>>>>>>>>>>>>>>> <http://www.manning.com/tahchiev/>
>>>>>>>>>>>>>>> Spring Batch in Action <http://www.manning.com/templier/>
>>>>>>>>>>>>>>> Blog: http://garygregory.wordpress.com
>>>>>>>>>>>>>>> Home: http://garygregory.com/
>>>>>>>>>>>>>>> Tweet! http://twitter.com/GaryGregory
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> --
>>>>>>>>>>>>>> Matt Sicker <boards@gmail.com>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> --
>>>>>>>>>>> [image: MagineTV]
>>>>>>>>>>>
>>>>>>>>>>> *Mikael Ståldal*
>>>>>>>>>>> Senior software developer
>>>>>>>>>>>
>>>>>>>>>>> *Magine TV*
>>>>>>>>>>> mikael.staldal@magine.com
>>>>>>>>>>> <javascript:_e(%7B%7D,'cvml','mikael.staldal@magine.com');>
>>>>>>>>>>> Grev Turegatan 3  | 114 46 Stockholm, Sweden  |   www.magine.com
>>>>>>>>>>>
>>>>>>>>>>> Privileged and/or Confidential Information may be contained in
>>>>>>>>>>> this message. If you are not the addressee indicated in this message
>>>>>>>>>>> (or responsible for delivery of the message to such a person),
>>>>>>>>>>> you may not copy or deliver this message to anyone. In such case,
>>>>>>>>>>> you should destroy this message and kindly notify the sender by
>>>>>>>>>>> reply email.
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> --
>>>>>>>>>> Matt Sicker <boards@gmail.com
>>>>>>>>>> <javascript:_e(%7B%7D,'cvml','boards@gmail.com');>>
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> --
>>>>>>>>> Matt Sicker <boards@gmail.com
>>>>>>>>> <javascript:_e(%7B%7D,'cvml','boards@gmail.com');>>
>>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> --
>>>>>>>> E-Mail: garydgregory@gmail.com
>>>>>>>> <javascript:_e(%7B%7D,'cvml','garydgregory@gmail.com');> | ggregory@apache.org
>>>>>>>> <javascript:_e(%7B%7D,'cvml','ggregory@apache.org');>
>>>>>>>> Java Persistence with Hibernate, Second Edition
>>>>>>>> <http://www.manning.com/bauer3/>
>>>>>>>> JUnit in Action, Second Edition <http://www.manning.com/tahchiev/>
>>>>>>>> Spring Batch in Action <http://www.manning.com/templier/>
>>>>>>>> Blog: http://garygregory.wordpress.com
>>>>>>>> Home: http://garygregory.com/
>>>>>>>> Tweet! http://twitter.com/GaryGregory
>>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>
>>>>>
>>>>>
>>>>> --
>>>>> Matt Sicker <boards@gmail.com
>>>>> <javascript:_e(%7B%7D,'cvml','boards@gmail.com');>>
>>>>>
>>>>
>>>>
>>>
>>>
>>

Mime
View raw message