You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by Remko Popma <re...@gmail.com> on 2016/05/17 17:13:08 UTC
Garbage-free Log4j docs preview
Hi all,
First, my thanks to the many people who gave helpful advice and feedback on
how to measure Log4j response time on this list some time ago.
We're about to start the Log4j 2.6 release.
If anyone is interested, a preview of the garbage-free logging manual page
is here: http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
and a preview of the updated performance page is here:
http://home.apache.org/~rpopma/log4j/2.6/performance.html
Feedback welcome!
Remko
Re: Garbage-free Log4j docs preview
Posted by Gary Gregory <ga...@gmail.com>.
But wouldn't that mess up output when another thread does sys out println?
Or do we hook in to System.setOut and setErr?
Gary
On May 24, 2016 7:27 AM, "Mikael Ståldal" <mi...@magine.com> wrote:
> Could we avoid that by using FileDescriptor.out / FileDescriptor.err
> instead of System.out / System.err ?
>
> On Tue, May 24, 2016 at 4:09 PM, Matt Sicker <bo...@gmail.com> wrote:
>
>> All the PrintStream.write() methods have locks.
>>
>> On 24 May 2016 at 02:56, Mikael Ståldal <mi...@magine.com>
>> wrote:
>>
>>> Do we know why Console has so bad performance (compared to File)? Is
>>> this true also if you redirect STDOUT to a file?
>>>
>>> On Tue, May 17, 2016 at 7:13 PM, Remko Popma <re...@gmail.com>
>>> wrote:
>>>
>>>> Hi all,
>>>>
>>>> First, my thanks to the many people who gave helpful advice and
>>>> feedback on how to measure Log4j response time on this list some time ago.
>>>>
>>>> We're about to start the Log4j 2.6 release.
>>>> If anyone is interested, a preview of the garbage-free logging manual
>>>> page is here:
>>>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>>>> and a preview of the updated performance page is here:
>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>
>>>> Feedback welcome!
>>>>
>>>> Remko
>>>>
>>>>
>>>>
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>>>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>>>
>>>
>>>
>>>
>>> --
>>> [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 <bo...@gmail.com>
>>
>
>
>
> --
> [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.
>
Re: Garbage-free Log4j docs preview
Posted by Ralph Goers <ra...@dslextreme.com>.
It may be that the spec says the FileDescriptor has to point at a FileInputStream, in which case System.out would have to wrap it.
Ralph
> On May 25, 2016, at 5:43 AM, Ralph Goers <ra...@dslextreme.com> wrote:
>
> You are missing the point. What does IBM's JDK do? What does the gnu JDK do? What does Android do? You can only rely on what the spec says. I haven't read the spec, but the javadoc certainly says nothing.
>
> Ralph
>
>> On May 25, 2016, at 4:09 AM, Mikael Ståldal <mi...@magine.com> wrote:
>>
>> http://grepcode.com/file/repository.grepcode.com/java/root/jdk/openjdk/6-b14/java/lang/System.java#1087
>>
>>> On Wed, May 25, 2016 at 12:51 PM, Ralph Goers <ra...@dslextreme.com> wrote:
>>> I haven't looked at the source, but the point is that FileDescriptor gives no guarantees what it is referencing.
>>>
>>> Sent from my iPad
>>>
>>>> On May 25, 2016, at 12:49 AM, Mikael Ståldal <mi...@magine.com> wrote:
>>>>
>>>> > but I would guess the the FileDescriptor may just be a reference to the PrintStream.
>>>>
>>>> I think it's the other way around, System.out is a wrapper around FileDescriptor.out. Look at the source code for java.lang.System in JDK 8.
>>>>
>>>>> On Tue, May 24, 2016 at 7:53 PM, Ralph Goers <ra...@dslextreme.com> wrote:
>>>>> The javadoc for FileDescriptor is fairly ambiguous. I’d have to look at the code, but I would guess the the FileDescriptor may just be a reference to the PrintStream. I really don’t think you can count on what it points to. I would also worry about us trying to use the FileDescriptor while the application might be writing to System.out.
>>>>>
>>>>> Ralph
>>>>>
>>>>>> On May 24, 2016, at 10:30 AM, Remko Popma <re...@gmail.com> wrote:
>>>>>>
>>>>>>
>>>>>>> On Tuesday, May 24, 2016 at 11:27:33 PM UTC+9, Mikael Ståldal wrote:
>>>>>>> Could we avoid that by using FileDescriptor.out / FileDescriptor.err instead of System.out / System.err ?
>>>>>>>
>>>>>>>> On Tue, May 24, 2016 at 4:09 PM, Matt Sicker <bo...@gmail.com> wrote:
>>>>>>>> All the PrintStream.write() methods have locks.
>>>>>>>>
>>>>>>>>> On 24 May 2016 at 02:56, Mikael Ståldal <mi...@magine.com> wrote:
>>>>>>>>> Do we know why Console has so bad performance (compared to File)? Is this true also if you redirect STDOUT to a file?
>>>>>>>>>
>>>>>>>>>> and a preview of the updated performance page is here: http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>>>
>>>>>> I think these are really interesting questions, and I am curious if anyone on this list can share their insights
>>>>>>
>>>>>>
>>>>>> ---------------------------------------------------------------------
>>>>>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>>>>>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>>>>
>>>>
>>>>
>>>>
>>>> --
>>>>
>>>>
>>>> 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.
>>
>>
>>
>> --
>>
>>
>> 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.
Re: Garbage-free Log4j docs preview
Posted by Ralph Goers <ra...@dslextreme.com>.
You are missing the point. What does IBM's JDK do? What does the gnu JDK do? What does Android do? You can only rely on what the spec says. I haven't read the spec, but the javadoc certainly says nothing.
Ralph
> On May 25, 2016, at 4:09 AM, Mikael Ståldal <mi...@magine.com> wrote:
>
> http://grepcode.com/file/repository.grepcode.com/java/root/jdk/openjdk/6-b14/java/lang/System.java#1087
>
>> On Wed, May 25, 2016 at 12:51 PM, Ralph Goers <ra...@dslextreme.com> wrote:
>> I haven't looked at the source, but the point is that FileDescriptor gives no guarantees what it is referencing.
>>
>> Sent from my iPad
>>
>>> On May 25, 2016, at 12:49 AM, Mikael Ståldal <mi...@magine.com> wrote:
>>>
>>> > but I would guess the the FileDescriptor may just be a reference to the PrintStream.
>>>
>>> I think it's the other way around, System.out is a wrapper around FileDescriptor.out. Look at the source code for java.lang.System in JDK 8.
>>>
>>>> On Tue, May 24, 2016 at 7:53 PM, Ralph Goers <ra...@dslextreme.com> wrote:
>>>> The javadoc for FileDescriptor is fairly ambiguous. I’d have to look at the code, but I would guess the the FileDescriptor may just be a reference to the PrintStream. I really don’t think you can count on what it points to. I would also worry about us trying to use the FileDescriptor while the application might be writing to System.out.
>>>>
>>>> Ralph
>>>>
>>>>> On May 24, 2016, at 10:30 AM, Remko Popma <re...@gmail.com> wrote:
>>>>>
>>>>>
>>>>>> On Tuesday, May 24, 2016 at 11:27:33 PM UTC+9, Mikael Ståldal wrote:
>>>>>> Could we avoid that by using FileDescriptor.out / FileDescriptor.err instead of System.out / System.err ?
>>>>>>
>>>>>>> On Tue, May 24, 2016 at 4:09 PM, Matt Sicker <bo...@gmail.com> wrote:
>>>>>>> All the PrintStream.write() methods have locks.
>>>>>>>
>>>>>>>> On 24 May 2016 at 02:56, Mikael Ståldal <mi...@magine.com> wrote:
>>>>>>>> Do we know why Console has so bad performance (compared to File)? Is this true also if you redirect STDOUT to a file?
>>>>>>>>
>>>>>>>>> and a preview of the updated performance page is here: http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>>
>>>>> I think these are really interesting questions, and I am curious if anyone on this list can share their insights
>>>>>
>>>>>
>>>>> ---------------------------------------------------------------------
>>>>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>>>>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>>
>>>
>>>
>>> --
>>>
>>>
>>> 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.
>
>
>
> --
>
>
> 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.
Re: Garbage-free Log4j docs preview
Posted by Mikael Ståldal <mi...@magine.com>.
http://grepcode.com/file/repository.grepcode.com/java/root/jdk/openjdk/6-b14/java/lang/System.java#1087
On Wed, May 25, 2016 at 12:51 PM, Ralph Goers <ra...@dslextreme.com>
wrote:
> I haven't looked at the source, but the point is that FileDescriptor gives
> no guarantees what it is referencing.
>
> Sent from my iPad
>
> On May 25, 2016, at 12:49 AM, Mikael Ståldal <mi...@magine.com>
> wrote:
>
> > but I would guess the the FileDescriptor may just be a reference to the
> PrintStream.
>
> I think it's the other way around, System.out is a wrapper around
> FileDescriptor.out. Look at the source code for java.lang.System in JDK 8.
>
> On Tue, May 24, 2016 at 7:53 PM, Ralph Goers <ra...@dslextreme.com>
> wrote:
>
>> The javadoc for FileDescriptor is fairly ambiguous. I’d have to look at
>> the code, but I would guess the the FileDescriptor may just be a reference
>> to the PrintStream. I really don’t think you can count on what it points
>> to. I would also worry about us trying to use the FileDescriptor while the
>> application might be writing to System.out.
>>
>> Ralph
>>
>> On May 24, 2016, at 10:30 AM, Remko Popma <re...@gmail.com> wrote:
>>
>>
>> On Tuesday, May 24, 2016 at 11:27:33 PM UTC+9, Mikael Ståldal wrote:
>>>
>>> Could we avoid that by using FileDescriptor.out / FileDescriptor.err
>>> instead of System.out / System.err ?
>>>
>>> On Tue, May 24, 2016 at 4:09 PM, Matt Sicker <bo...@gmail.com> wrote:
>>>
>>>> All the PrintStream.write() methods have locks.
>>>>
>>>> On 24 May 2016 at 02:56, Mikael Ståldal <mi...@magine.com> wrote:
>>>>
>>>>> Do we know why Console has so bad performance (compared to File)? Is
>>>>> this true also if you redirect STDOUT to a file?
>>>>>
>>>>> and a preview of the updated performance page is here:
>>>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>>>
>>>>>
>> I think these are really interesting questions, and I am curious if
>> anyone on this list can share their insights
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>
>>
>>
>
>
> --
> [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.
>
>
--
[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.
Re: Garbage-free Log4j docs preview
Posted by Ralph Goers <ra...@dslextreme.com>.
I haven't looked at the source, but the point is that FileDescriptor gives no guarantees what it is referencing.
Sent from my iPad
> On May 25, 2016, at 12:49 AM, Mikael Ståldal <mi...@magine.com> wrote:
>
> > but I would guess the the FileDescriptor may just be a reference to the PrintStream.
>
> I think it's the other way around, System.out is a wrapper around FileDescriptor.out. Look at the source code for java.lang.System in JDK 8.
>
>> On Tue, May 24, 2016 at 7:53 PM, Ralph Goers <ra...@dslextreme.com> wrote:
>> The javadoc for FileDescriptor is fairly ambiguous. I’d have to look at the code, but I would guess the the FileDescriptor may just be a reference to the PrintStream. I really don’t think you can count on what it points to. I would also worry about us trying to use the FileDescriptor while the application might be writing to System.out.
>>
>> Ralph
>>
>>> On May 24, 2016, at 10:30 AM, Remko Popma <re...@gmail.com> wrote:
>>>
>>>
>>>> On Tuesday, May 24, 2016 at 11:27:33 PM UTC+9, Mikael Ståldal wrote:
>>>> Could we avoid that by using FileDescriptor.out / FileDescriptor.err instead of System.out / System.err ?
>>>>
>>>>> On Tue, May 24, 2016 at 4:09 PM, Matt Sicker <bo...@gmail.com> wrote:
>>>>> All the PrintStream.write() methods have locks.
>>>>>
>>>>>> On 24 May 2016 at 02:56, Mikael Ståldal <mi...@magine.com> wrote:
>>>>>> Do we know why Console has so bad performance (compared to File)? Is this true also if you redirect STDOUT to a file?
>>>>>>
>>>>>>> and a preview of the updated performance page is here: http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>
>>> I think these are really interesting questions, and I am curious if anyone on this list can share their insights
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>
>
>
>
> --
>
>
> 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.
Re: Garbage-free Log4j docs preview
Posted by Mikael Ståldal <mi...@magine.com>.
> but I would guess the the FileDescriptor may just be a reference to the
PrintStream.
I think it's the other way around, System.out is a wrapper around
FileDescriptor.out. Look at the source code for java.lang.System in JDK 8.
On Tue, May 24, 2016 at 7:53 PM, Ralph Goers <ra...@dslextreme.com>
wrote:
> The javadoc for FileDescriptor is fairly ambiguous. I’d have to look at
> the code, but I would guess the the FileDescriptor may just be a reference
> to the PrintStream. I really don’t think you can count on what it points
> to. I would also worry about us trying to use the FileDescriptor while the
> application might be writing to System.out.
>
> Ralph
>
> On May 24, 2016, at 10:30 AM, Remko Popma <re...@gmail.com> wrote:
>
>
> On Tuesday, May 24, 2016 at 11:27:33 PM UTC+9, Mikael Ståldal wrote:
>>
>> Could we avoid that by using FileDescriptor.out / FileDescriptor.err
>> instead of System.out / System.err ?
>>
>> On Tue, May 24, 2016 at 4:09 PM, Matt Sicker <bo...@gmail.com> wrote:
>>
>>> All the PrintStream.write() methods have locks.
>>>
>>> On 24 May 2016 at 02:56, Mikael Ståldal <mi...@magine.com> wrote:
>>>
>>>> Do we know why Console has so bad performance (compared to File)? Is
>>>> this true also if you redirect STDOUT to a file?
>>>>
>>>> and a preview of the updated performance page is here:
>>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>>
>>>>
> I think these are really interesting questions, and I am curious if anyone
> on this list can share their insights
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
>
>
--
[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.
Re: Garbage-free Log4j docs preview
Posted by Ralph Goers <ra...@dslextreme.com>.
The javadoc for FileDescriptor is fairly ambiguous. I’d have to look at the code, but I would guess the the FileDescriptor may just be a reference to the PrintStream. I really don’t think you can count on what it points to. I would also worry about us trying to use the FileDescriptor while the application might be writing to System.out.
Ralph
> On May 24, 2016, at 10:30 AM, Remko Popma <re...@gmail.com> wrote:
>
>
> On Tuesday, May 24, 2016 at 11:27:33 PM UTC+9, Mikael Ståldal wrote:
> Could we avoid that by using FileDescriptor.out / FileDescriptor.err instead of System.out / System.err ?
>
> On Tue, May 24, 2016 at 4:09 PM, Matt Sicker <boa...@gmail.com <javascript:>> wrote:
> All the PrintStream.write() methods have locks.
>
> On 24 May 2016 at 02:56, Mikael Ståldal <mikael....@magine.com <javascript:>> wrote:
> Do we know why Console has so bad performance (compared to File)? Is this true also if you redirect STDOUT to a file?
>
> and a preview of the updated performance page is here: http://home.apache.org/~rpopma/log4j/2.6/performance.html <http://home.apache.org/~rpopma/log4j/2.6/performance.html>
>
> I think these are really interesting questions, and I am curious if anyone on this list can share their insights
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
On Tuesday, May 24, 2016 at 11:27:33 PM UTC+9, Mikael Ståldal wrote:
>
> Could we avoid that by using FileDescriptor.out / FileDescriptor.err
> instead of System.out / System.err ?
>
> On Tue, May 24, 2016 at 4:09 PM, Matt Sicker <boa...@gmail.com
> <javascript:>> wrote:
>
>> All the PrintStream.write() methods have locks.
>>
>> On 24 May 2016 at 02:56, Mikael Ståldal <mikael....@magine.com
>> <javascript:>> wrote:
>>
>>> Do we know why Console has so bad performance (compared to File)? Is
>>> this true also if you redirect STDOUT to a file?
>>>
>>> and a preview of the updated performance page is here:
>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>
>>>
I think these are really interesting questions, and I am curious if anyone
on this list can share their insights
Re: Garbage-free Log4j docs preview
Posted by Mikael Ståldal <mi...@magine.com>.
I just tried, gives a 5x performance boost. See Git branch LOG4J2-1395
<https://issues.apache.org/jira/browse/LOG4J2-1395> .
On Tue, May 24, 2016 at 4:27 PM, Mikael Ståldal <mi...@magine.com>
wrote:
> Could we avoid that by using FileDescriptor.out / FileDescriptor.err
> instead of System.out / System.err ?
>
> On Tue, May 24, 2016 at 4:09 PM, Matt Sicker <bo...@gmail.com> wrote:
>
>> All the PrintStream.write() methods have locks.
>>
>> On 24 May 2016 at 02:56, Mikael Ståldal <mi...@magine.com>
>> wrote:
>>
>>> Do we know why Console has so bad performance (compared to File)? Is
>>> this true also if you redirect STDOUT to a file?
>>>
>>> On Tue, May 17, 2016 at 7:13 PM, Remko Popma <re...@gmail.com>
>>> wrote:
>>>
>>>> Hi all,
>>>>
>>>> First, my thanks to the many people who gave helpful advice and
>>>> feedback on how to measure Log4j response time on this list some time ago.
>>>>
>>>> We're about to start the Log4j 2.6 release.
>>>> If anyone is interested, a preview of the garbage-free logging manual
>>>> page is here:
>>>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>>>> and a preview of the updated performance page is here:
>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>
>>>> Feedback welcome!
>>>>
>>>> Remko
>>>>
>>>>
>>>>
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>>>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>>>
>>>
>>>
>>>
>>> --
>>> [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 <bo...@gmail.com>
>>
>
>
>
> --
> [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.
>
--
[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.
Re: Garbage-free Log4j docs preview
Posted by Gary Gregory <ga...@gmail.com>.
On Thu, May 26, 2016 at 11:33 AM, Matt Sicker <bo...@gmail.com> wrote:
> There's a bson dependency in log4j-nosql as well (from mongo).
>
Right, the wire format for MongoDB is BSON IIRC.
Gary
>
> On 26 May 2016 at 11:46, Gary Gregory <ga...@gmail.com> wrote:
>
>> I think we can support BSON through Jackson. That would be interesting
>> for 2.7.
>>
>> Gary
>> On May 26, 2016 6:47 AM, "Remko Popma" <re...@gmail.com> wrote:
>>
>>> Kirk,
>>>
>>> Logging in binary format has been on my todo list for a while.
>>> We did some preliminary analysis here:
>>> https://issues.apache.org/jira/browse/LOG4J2-1305
>>> Your thoughts on this effort would be much appreciated.
>>>
>>> Remko
>>>
>>> On Thursday, May 26, 2016 at 5:32:27 PM UTC+9, Kirk Pepperdine wrote:
>>>>
>>>> Hi,
>>>>
>>>> Sorry this might read a bit provocative then intended. In general I
>>>> applaud this effort and to be fair I’ve not only picked on Log4J in the
>>>> past. IM(not so)HO, all logger and in particular JDK logging has been a
>>>> disaster from both an API and underlying design POV.
>>>>
>>>>
>>>> On May 26, 2016, at 9:41 AM, Mikael Ståldal <mi...@magine.com>
>>>> wrote:
>>>>
>>>> http://12factor.net/logs
>>>>
>>>>
>>>> I actually see little wrong with this approach. It is rare that I run
>>>> into an application that isn’t bottlenecked on logging when you combine all
>>>> of the problem that come from logging. The JDK logger, because of it’s
>>>> design, is responsible for class loader leaks. The API’s in all loggers
>>>> encourage programming styles that are responsible for excessive memory
>>>> pressure. Though I gripe about the obscene amount of work that logging
>>>> frameworks engage in, generally it’s not the logging framework that is
>>>> directly responsible for memory pressure, it’s what has to be done to use
>>>> the logging framework that is the source of the problem.
>>>>
>>>> To tackle this I’ve been pushing simple solutions such that the one
>>>> pushed here. Loggers should only push messages directly to a sync point and
>>>> do no more than that. Anything that injects extra work into a threads
>>>> workflow should be discarded. This includes activities such as decorating
>>>> and/or reformatting running through appenders.. and so on.... Even record
>>>> ordering (if it needs to be done) should happen else where. Additionally, I
>>>> give the ( very unpopular) advice) that logging should use binary/machine
>>>> readable formats (a practice adopted by Twitter and a number of other
>>>> players) in favor of eye readable formats (which tend to be neither human
>>>> nor machine readable). In messaging, of which logging is a form of
>>>> messaging, information density counts and human readable formats tend to be
>>>> exceptionally information sparse. When you combine these techniques you can
>>>> get tremendous (orders of magnitude) improvements in performance. As much
>>>> as I’m a fan of the disruptor, I fail to see how building on top of it
>>>> solves any of the above mentioned problems.
>>>>
>>>> Kind regards,
>>>> Kirk
>>>>
>>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>>
>>
>
>
> --
> Matt Sicker <bo...@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
Re: Garbage-free Log4j docs preview
Posted by Matt Sicker <bo...@gmail.com>.
There's a bson dependency in log4j-nosql as well (from mongo).
On 26 May 2016 at 11:46, Gary Gregory <ga...@gmail.com> wrote:
> I think we can support BSON through Jackson. That would be interesting for
> 2.7.
>
> Gary
> On May 26, 2016 6:47 AM, "Remko Popma" <re...@gmail.com> wrote:
>
>> Kirk,
>>
>> Logging in binary format has been on my todo list for a while.
>> We did some preliminary analysis here:
>> https://issues.apache.org/jira/browse/LOG4J2-1305
>> Your thoughts on this effort would be much appreciated.
>>
>> Remko
>>
>> On Thursday, May 26, 2016 at 5:32:27 PM UTC+9, Kirk Pepperdine wrote:
>>>
>>> Hi,
>>>
>>> Sorry this might read a bit provocative then intended. In general I
>>> applaud this effort and to be fair I’ve not only picked on Log4J in the
>>> past. IM(not so)HO, all logger and in particular JDK logging has been a
>>> disaster from both an API and underlying design POV.
>>>
>>>
>>> On May 26, 2016, at 9:41 AM, Mikael Ståldal <mi...@magine.com>
>>> wrote:
>>>
>>> http://12factor.net/logs
>>>
>>>
>>> I actually see little wrong with this approach. It is rare that I run
>>> into an application that isn’t bottlenecked on logging when you combine all
>>> of the problem that come from logging. The JDK logger, because of it’s
>>> design, is responsible for class loader leaks. The API’s in all loggers
>>> encourage programming styles that are responsible for excessive memory
>>> pressure. Though I gripe about the obscene amount of work that logging
>>> frameworks engage in, generally it’s not the logging framework that is
>>> directly responsible for memory pressure, it’s what has to be done to use
>>> the logging framework that is the source of the problem.
>>>
>>> To tackle this I’ve been pushing simple solutions such that the one
>>> pushed here. Loggers should only push messages directly to a sync point and
>>> do no more than that. Anything that injects extra work into a threads
>>> workflow should be discarded. This includes activities such as decorating
>>> and/or reformatting running through appenders.. and so on.... Even record
>>> ordering (if it needs to be done) should happen else where. Additionally, I
>>> give the ( very unpopular) advice) that logging should use binary/machine
>>> readable formats (a practice adopted by Twitter and a number of other
>>> players) in favor of eye readable formats (which tend to be neither human
>>> nor machine readable). In messaging, of which logging is a form of
>>> messaging, information density counts and human readable formats tend to be
>>> exceptionally information sparse. When you combine these techniques you can
>>> get tremendous (orders of magnitude) improvements in performance. As much
>>> as I’m a fan of the disruptor, I fail to see how building on top of it
>>> solves any of the above mentioned problems.
>>>
>>> Kind regards,
>>> Kirk
>>>
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>
>
--
Matt Sicker <bo...@gmail.com>
Re: Garbage-free Log4j docs preview
Posted by Gary Gregory <ga...@gmail.com>.
I think we can support BSON through Jackson. That would be interesting for
2.7.
Gary
On May 26, 2016 6:47 AM, "Remko Popma" <re...@gmail.com> wrote:
> Kirk,
>
> Logging in binary format has been on my todo list for a while.
> We did some preliminary analysis here:
> https://issues.apache.org/jira/browse/LOG4J2-1305
> Your thoughts on this effort would be much appreciated.
>
> Remko
>
> On Thursday, May 26, 2016 at 5:32:27 PM UTC+9, Kirk Pepperdine wrote:
>>
>> Hi,
>>
>> Sorry this might read a bit provocative then intended. In general I
>> applaud this effort and to be fair I’ve not only picked on Log4J in the
>> past. IM(not so)HO, all logger and in particular JDK logging has been a
>> disaster from both an API and underlying design POV.
>>
>>
>> On May 26, 2016, at 9:41 AM, Mikael Ståldal <mi...@magine.com>
>> wrote:
>>
>> http://12factor.net/logs
>>
>>
>> I actually see little wrong with this approach. It is rare that I run
>> into an application that isn’t bottlenecked on logging when you combine all
>> of the problem that come from logging. The JDK logger, because of it’s
>> design, is responsible for class loader leaks. The API’s in all loggers
>> encourage programming styles that are responsible for excessive memory
>> pressure. Though I gripe about the obscene amount of work that logging
>> frameworks engage in, generally it’s not the logging framework that is
>> directly responsible for memory pressure, it’s what has to be done to use
>> the logging framework that is the source of the problem.
>>
>> To tackle this I’ve been pushing simple solutions such that the one
>> pushed here. Loggers should only push messages directly to a sync point and
>> do no more than that. Anything that injects extra work into a threads
>> workflow should be discarded. This includes activities such as decorating
>> and/or reformatting running through appenders.. and so on.... Even record
>> ordering (if it needs to be done) should happen else where. Additionally, I
>> give the ( very unpopular) advice) that logging should use binary/machine
>> readable formats (a practice adopted by Twitter and a number of other
>> players) in favor of eye readable formats (which tend to be neither human
>> nor machine readable). In messaging, of which logging is a form of
>> messaging, information density counts and human readable formats tend to be
>> exceptionally information sparse. When you combine these techniques you can
>> get tremendous (orders of magnitude) improvements in performance. As much
>> as I’m a fan of the disruptor, I fail to see how building on top of it
>> solves any of the above mentioned problems.
>>
>> Kind regards,
>> Kirk
>>
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
Kirk,
Logging in binary format has been on my todo list for a while.
We did some preliminary analysis here:
https://issues.apache.org/jira/browse/LOG4J2-1305
Your thoughts on this effort would be much appreciated.
Remko
On Thursday, May 26, 2016 at 5:32:27 PM UTC+9, Kirk Pepperdine wrote:
>
> Hi,
>
> Sorry this might read a bit provocative then intended. In general I
> applaud this effort and to be fair I’ve not only picked on Log4J in the
> past. IM(not so)HO, all logger and in particular JDK logging has been a
> disaster from both an API and underlying design POV.
>
>
> On May 26, 2016, at 9:41 AM, Mikael Ståldal <mikael....@magine.com
> <javascript:>> wrote:
>
> http://12factor.net/logs
>
>
> I actually see little wrong with this approach. It is rare that I run
> into an application that isn’t bottlenecked on logging when you combine all
> of the problem that come from logging. The JDK logger, because of it’s
> design, is responsible for class loader leaks. The API’s in all loggers
> encourage programming styles that are responsible for excessive memory
> pressure. Though I gripe about the obscene amount of work that logging
> frameworks engage in, generally it’s not the logging framework that is
> directly responsible for memory pressure, it’s what has to be done to use
> the logging framework that is the source of the problem.
>
> To tackle this I’ve been pushing simple solutions such that the one pushed
> here. Loggers should only push messages directly to a sync point and do no
> more than that. Anything that injects extra work into a threads workflow
> should be discarded. This includes activities such as decorating and/or
> reformatting running through appenders.. and so on.... Even record ordering
> (if it needs to be done) should happen else where. Additionally, I give the
> ( very unpopular) advice) that logging should use binary/machine readable
> formats (a practice adopted by Twitter and a number of other players) in
> favor of eye readable formats (which tend to be neither human nor machine
> readable). In messaging, of which logging is a form of messaging,
> information density counts and human readable formats tend to be
> exceptionally information sparse. When you combine these techniques you can
> get tremendous (orders of magnitude) improvements in performance. As much
> as I’m a fan of the disruptor, I fail to see how building on top of it
> solves any of the above mentioned problems.
>
> Kind regards,
> Kirk
>
>
Re: Garbage-free Log4j docs preview
Posted by Mikael Ståldal <mi...@magine.com>.
http://12factor.net/logs
(I don't fully agree with this, but it would be nice if we can support it
in an efficient way.)
On Wed, May 25, 2016 at 6:50 PM, Matt Sicker <bo...@gmail.com> wrote:
> Plus there's the fact that some people are encouraging all logging to
> happen to stdout (in containers) for simpler log configuration and
> handling. It would be nice if we can support that scenario better.
>
> On 25 May 2016 at 09:18, Mikael Ståldal <mi...@magine.com> wrote:
>
>> There are use cases for logging to standard out/err and redirecting to a
>> file or something else than an actual console. It would be good if we would
>> optimize so that is not 50x slower than logging directly to file.
>>
>> On Wed, May 25, 2016 at 4:09 PM, Remko Popma <re...@gmail.com>
>> wrote:
>>
>>>
>>>
>>> On Wednesday, May 25, 2016 at 3:02:33 AM UTC+9, Richard Warburton wrote:
>>>>
>>>> Hi,
>>>>
>>>> Could we avoid that by using FileDescriptor.out / FileDescriptor.err
>>>>> instead of System.out / System.err ?
>>>>>
>>>>> On Tue, May 24, 2016 at 4:09 PM, Matt Sicker <bo...@gmail.com> wrote:
>>>>>
>>>>>> All the PrintStream.write() methods have locks.
>>>>>>
>>>>>> On 24 May 2016 at 02:56, Mikael Ståldal <mi...@magine.com>
>>>>>> wrote:
>>>>>>
>>>>>>> Do we know why Console has so bad performance (compared to File)? Is
>>>>>>> this true also if you redirect STDOUT to a file?
>>>>>>>
>>>>>>
>>>> There's a couple of other things to consider:
>>>>
>>>> * Console writes in Java flush on every newline.
>>>> * The terminal that is being written to might also spend time
>>>> rendering text, if your benchmark actually writes STDOUT. I've seen
>>>> terminals eat 3x more CPU rendering logs than a program was using to
>>>> produce them.
>>>>
>>> Is rendering the bottleneck? I'm just wondering what causes this. The
>>> 50x difference with writing to a file is staggering... (I haven't benchmark
>>> File I/O when flushing on every write, may be interesting to try.)
>>>
>>>
>>>> regards,
>>>>
>>>> Richard Warburton
>>>>
>>>> http://insightfullogic.com
>>>> @RichardWarburto <http://twitter.com/richardwarburto>
>>>>
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>>
>>
>>
>>
>> --
>> [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 <bo...@gmail.com>
>
--
[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.
Re: Garbage-free Log4j docs preview
Posted by Matt Sicker <bo...@gmail.com>.
Plus there's the fact that some people are encouraging all logging to
happen to stdout (in containers) for simpler log configuration and
handling. It would be nice if we can support that scenario better.
On 25 May 2016 at 09:18, Mikael Ståldal <mi...@magine.com> wrote:
> There are use cases for logging to standard out/err and redirecting to a
> file or something else than an actual console. It would be good if we would
> optimize so that is not 50x slower than logging directly to file.
>
> On Wed, May 25, 2016 at 4:09 PM, Remko Popma <re...@gmail.com>
> wrote:
>
>>
>>
>> On Wednesday, May 25, 2016 at 3:02:33 AM UTC+9, Richard Warburton wrote:
>>>
>>> Hi,
>>>
>>> Could we avoid that by using FileDescriptor.out / FileDescriptor.err
>>>> instead of System.out / System.err ?
>>>>
>>>> On Tue, May 24, 2016 at 4:09 PM, Matt Sicker <bo...@gmail.com> wrote:
>>>>
>>>>> All the PrintStream.write() methods have locks.
>>>>>
>>>>> On 24 May 2016 at 02:56, Mikael Ståldal <mi...@magine.com> wrote:
>>>>>
>>>>>> Do we know why Console has so bad performance (compared to File)? Is
>>>>>> this true also if you redirect STDOUT to a file?
>>>>>>
>>>>>
>>> There's a couple of other things to consider:
>>>
>>> * Console writes in Java flush on every newline.
>>> * The terminal that is being written to might also spend time rendering
>>> text, if your benchmark actually writes STDOUT. I've seen terminals eat 3x
>>> more CPU rendering logs than a program was using to produce them.
>>>
>> Is rendering the bottleneck? I'm just wondering what causes this. The 50x
>> difference with writing to a file is staggering... (I haven't benchmark
>> File I/O when flushing on every write, may be interesting to try.)
>>
>>
>>> regards,
>>>
>>> Richard Warburton
>>>
>>> http://insightfullogic.com
>>> @RichardWarburto <http://twitter.com/richardwarburto>
>>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>
>
>
>
> --
> [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 <bo...@gmail.com>
Re: Garbage-free Log4j docs preview
Posted by Mikael Ståldal <mi...@magine.com>.
There are use cases for logging to standard out/err and redirecting to a
file or something else than an actual console. It would be good if we would
optimize so that is not 50x slower than logging directly to file.
On Wed, May 25, 2016 at 4:09 PM, Remko Popma <re...@gmail.com> wrote:
>
>
> On Wednesday, May 25, 2016 at 3:02:33 AM UTC+9, Richard Warburton wrote:
>>
>> Hi,
>>
>> Could we avoid that by using FileDescriptor.out / FileDescriptor.err
>>> instead of System.out / System.err ?
>>>
>>> On Tue, May 24, 2016 at 4:09 PM, Matt Sicker <bo...@gmail.com> wrote:
>>>
>>>> All the PrintStream.write() methods have locks.
>>>>
>>>> On 24 May 2016 at 02:56, Mikael Ståldal <mi...@magine.com> wrote:
>>>>
>>>>> Do we know why Console has so bad performance (compared to File)? Is
>>>>> this true also if you redirect STDOUT to a file?
>>>>>
>>>>
>> There's a couple of other things to consider:
>>
>> * Console writes in Java flush on every newline.
>> * The terminal that is being written to might also spend time rendering
>> text, if your benchmark actually writes STDOUT. I've seen terminals eat 3x
>> more CPU rendering logs than a program was using to produce them.
>>
> Is rendering the bottleneck? I'm just wondering what causes this. The 50x
> difference with writing to a file is staggering... (I haven't benchmark
> File I/O when flushing on every write, may be interesting to try.)
>
>
>> regards,
>>
>> Richard Warburton
>>
>> http://insightfullogic.com
>> @RichardWarburto <http://twitter.com/richardwarburto>
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
--
[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.
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
On Wednesday, May 25, 2016 at 3:02:33 AM UTC+9, Richard Warburton wrote:
>
> Hi,
>
> Could we avoid that by using FileDescriptor.out / FileDescriptor.err
>> instead of System.out / System.err ?
>>
>> On Tue, May 24, 2016 at 4:09 PM, Matt Sicker <boa...@gmail.com
>> <javascript:>> wrote:
>>
>>> All the PrintStream.write() methods have locks.
>>>
>>> On 24 May 2016 at 02:56, Mikael Ståldal <mikael....@magine.com
>>> <javascript:>> wrote:
>>>
>>>> Do we know why Console has so bad performance (compared to File)? Is
>>>> this true also if you redirect STDOUT to a file?
>>>>
>>>
> There's a couple of other things to consider:
>
> * Console writes in Java flush on every newline.
> * The terminal that is being written to might also spend time rendering
> text, if your benchmark actually writes STDOUT. I've seen terminals eat 3x
> more CPU rendering logs than a program was using to produce them.
>
Is rendering the bottleneck? I'm just wondering what causes this. The 50x
difference with writing to a file is staggering... (I haven't benchmark
File I/O when flushing on every write, may be interesting to try.)
> regards,
>
> Richard Warburton
>
> http://insightfullogic.com
> @RichardWarburto <http://twitter.com/richardwarburto>
>
Re: Garbage-free Log4j docs preview
Posted by Mikael Ståldal <mi...@magine.com>.
Could we avoid that by using FileDescriptor.out / FileDescriptor.err
instead of System.out / System.err ?
On Tue, May 24, 2016 at 4:09 PM, Matt Sicker <bo...@gmail.com> wrote:
> All the PrintStream.write() methods have locks.
>
> On 24 May 2016 at 02:56, Mikael Ståldal <mi...@magine.com> wrote:
>
>> Do we know why Console has so bad performance (compared to File)? Is this
>> true also if you redirect STDOUT to a file?
>>
>> On Tue, May 17, 2016 at 7:13 PM, Remko Popma <re...@gmail.com>
>> wrote:
>>
>>> Hi all,
>>>
>>> First, my thanks to the many people who gave helpful advice and feedback
>>> on how to measure Log4j response time on this list some time ago.
>>>
>>> We're about to start the Log4j 2.6 release.
>>> If anyone is interested, a preview of the garbage-free logging manual
>>> page is here:
>>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>>> and a preview of the updated performance page is here:
>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>
>>> Feedback welcome!
>>>
>>> Remko
>>>
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>>
>>
>>
>>
>> --
>> [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 <bo...@gmail.com>
>
--
[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.
Re: Garbage-free Log4j docs preview
Posted by Matt Sicker <bo...@gmail.com>.
All the PrintStream.write() methods have locks.
On 24 May 2016 at 02:56, Mikael Ståldal <mi...@magine.com> wrote:
> Do we know why Console has so bad performance (compared to File)? Is this
> true also if you redirect STDOUT to a file?
>
> On Tue, May 17, 2016 at 7:13 PM, Remko Popma <re...@gmail.com>
> wrote:
>
>> Hi all,
>>
>> First, my thanks to the many people who gave helpful advice and feedback
>> on how to measure Log4j response time on this list some time ago.
>>
>> We're about to start the Log4j 2.6 release.
>> If anyone is interested, a preview of the garbage-free logging manual
>> page is here:
>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>> and a preview of the updated performance page is here:
>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>
>> Feedback welcome!
>>
>> Remko
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>
>
>
>
> --
> [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 <bo...@gmail.com>
Re: Garbage-free Log4j docs preview
Posted by Mikael Ståldal <mi...@magine.com>.
Do we know why Console has so bad performance (compared to File)? Is this
true also if you redirect STDOUT to a file?
On Tue, May 17, 2016 at 7:13 PM, Remko Popma <re...@gmail.com> wrote:
> Hi all,
>
> First, my thanks to the many people who gave helpful advice and feedback
> on how to measure Log4j response time on this list some time ago.
>
> We're about to start the Log4j 2.6 release.
> If anyone is interested, a preview of the garbage-free logging manual page
> is here: http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
> and a preview of the updated performance page is here:
> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>
> Feedback welcome!
>
> Remko
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
--
[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.
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
I used no special config for the JMH benchmarks, so the ConsoleAppender
writes to the terminal.
Perhaps it is a good idea to suggest redirecting to a file in the text that
accompanies these benchmark results.
Or add a benchmark result for how fast ConsoleAppender is when redirected.
On Thu, May 26, 2016 at 11:09 PM, Mikael Ståldal <mi...@magine.com>
wrote:
> Did you redirect standard out to a file, or did you let it write to the
> terminal, when running the Log4j2AppenderComparisonBenchmark?
>
> I just tried both, and that gives you a significant 5-10x difference.
>
> On Tue, May 17, 2016 at 7:13 PM, Remko Popma <re...@gmail.com>
> wrote:
>
>> Hi all,
>>
>> First, my thanks to the many people who gave helpful advice and feedback
>> on how to measure Log4j response time on this list some time ago.
>>
>> We're about to start the Log4j 2.6 release.
>> If anyone is interested, a preview of the garbage-free logging manual
>> page is here:
>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>> and a preview of the updated performance page is here:
>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>
>> Feedback welcome!
>>
>> Remko
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>
>
>
>
> --
> [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.
>
Re: Garbage-free Log4j docs preview
Posted by Mikael Ståldal <mi...@magine.com>.
Did you redirect standard out to a file, or did you let it write to the
terminal, when running the Log4j2AppenderComparisonBenchmark?
I just tried both, and that gives you a significant 5-10x difference.
On Tue, May 17, 2016 at 7:13 PM, Remko Popma <re...@gmail.com> wrote:
> Hi all,
>
> First, my thanks to the many people who gave helpful advice and feedback
> on how to measure Log4j response time on this list some time ago.
>
> We're about to start the Log4j 2.6 release.
> If anyone is interested, a preview of the garbage-free logging manual page
> is here: http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
> and a preview of the updated performance page is here:
> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>
> Feedback welcome!
>
> Remko
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
--
[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.
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
To log4j-dev:
FYI the Mechanical Sympathy Google group is where a number of Java
performance experts hang out.
My previous post there was:
https://groups.google.com/forum/m/#!topic/mechanical-sympathy/HwTrOMnm6h0
Remko
On Wednesday, 18 May 2016, Remko Popma <re...@gmail.com> wrote:
> Hi all,
>
> First, my thanks to the many people who gave helpful advice and feedback
> on how to measure Log4j response time on this list some time ago.
>
> We're about to start the Log4j 2.6 release.
> If anyone is interested, a preview of the garbage-free logging manual page
> is here: http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
> and a preview of the updated performance page is here:
> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>
> Feedback welcome!
>
> Remko
>
>
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
After looking more closely I found that the
org.slf4j.spi.LocationAwareLogger::log
<http://www.slf4j.org/api/org/slf4j/spi/LocationAwareLogger.html#log(org.slf4j.Marker,
java.lang.String, int, java.lang.String, java.lang.Object[],
java.lang.Throwable)> method is currently not implemented in a garbage-free
manner in the log4j-slf4j-impl binding. It creates a new message object for
each call. If there is interest we can address this in a future release.
Other methods seem okay.
On Thursday, May 19, 2016 at 4:57:10 PM UTC+9, Jerry Shea wrote:
>
> Ok thanks!
> On 19 May 2016 5:10 pm, "Remko Popma" <remko...@gmail.com <javascript:>>
> wrote:
>
>> On Thursday, May 19, 2016 at 11:10:45 AM UTC+9, Jerry Shea wrote:
>> > This is fantastic, thanks for this Remko.
>> >
>> >
>> > Can I ask a couple of questions?
>> > 1. is log4j 2.6 designed to operate garbage-free when used as an SLF4J
>> implementation too, or only with the native API?
>>
>> The log4j-slf4j-impl binding is trying to be garbage-free, but the SLF4J
>> API only offers up to two parameters for a parameterized message. More than
>> that uses varargs which creates a temporary object for the parameter array.
>> The native Log4j 2.6 API has methods for up to ten unrolled parameters.
>>
>> Another consideration is that the native Log4j 2 API lets you log
>> Objects, not just Strings. Any Object that implements CharSequence can be
>> logged without creating garbage.
>>
>> You can also implement the log4j Message interface if you want to
>> separate formatting from your business domain objects.
>>
>> Finally, the native Log4j 2 API has support for logging Java 8 lambdas
>> (since 2.4).
>>
>> > 2. when do you expect log4j 2.6 to be released GA i.e. ready for
>> production use?
>>
>> Barring any showstoppers, I expect it will be available in a week or so.
>>
>>
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
On Thursday, May 19, 2016 at 11:10:45 AM UTC+9, Jerry Shea wrote:
> This is fantastic, thanks for this Remko.
>
>
> Can I ask a couple of questions?
> 1. is log4j 2.6 designed to operate garbage-free when used as an SLF4J implementation too, or only with the native API?
The log4j-slf4j-impl binding is trying to be garbage-free, but the SLF4J API only offers up to two parameters for a parameterized message. More than that uses varargs which creates a temporary object for the parameter array. The native Log4j 2.6 API has methods for up to ten unrolled parameters.
Another consideration is that the native Log4j 2 API lets you log Objects, not just Strings. Any Object that implements CharSequence can be logged without creating garbage.
You can also implement the log4j Message interface if you want to separate formatting from your business domain objects.
Finally, the native Log4j 2 API has support for logging Java 8 lambdas (since 2.4).
> 2. when do you expect log4j 2.6 to be released GA i.e. ready for production use?
Barring any showstoppers, I expect it will be available in a week or so.
>
>
> Thansk, Jerry
>
> On Thursday, 19 May 2016 09:36:01 UTC+10, Remko Popma wrote:
> Thank you Martin, appreciated! :-)
>
> On Wednesday, May 18, 2016 at 2:33:55 AM UTC+9, Martin Thompson wrote:
> Hi Remko,
>
>
> I'd just like to say that it is a great service to the community as a whole that someone is seriously looking at improving logging.
>
>
> If you keep it up you'll be putting folks like me out of a job :)
>
>
> Martin...
>
>
>
>
> On 17 May 2016 at 18:13, Remko Popma <re...@gmail.com> wrote:
>
> Hi all,
>
>
> First, my thanks to the many people who gave helpful advice and feedback on how to measure Log4j response time on this list some time ago.
>
>
> We're about to start the Log4j 2.6 release.
> If anyone is interested, a preview of the garbage-free logging manual page is here: http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
> and a preview of the updated performance page is here: http://home.apache.org/~rpopma/log4j/2.6/performance.html
>
>
> Feedback welcome!
>
>
> Remko
>
>
>
>
>
>
> --
>
> You received this message because you are subscribed to the Google Groups "mechanical-sympathy" group.
>
> To unsubscribe from this group and stop receiving emails from it, send an email to mechanical-sympathy+unsubscribe@googlegroups.com.
>
> For more options, visit https://groups.google.com/d/optout.
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
Thank you Martin, appreciated! :-)
On Wednesday, May 18, 2016 at 2:33:55 AM UTC+9, Martin Thompson wrote:
>
> Hi Remko,
>
> I'd just like to say that it is a great service to the community as a
> whole that someone is seriously looking at improving logging.
>
> If you keep it up you'll be putting folks like me out of a job :)
>
> Martin...
>
>
> On 17 May 2016 at 18:13, Remko Popma <remko...@gmail.com <javascript:>>
> wrote:
>
>> Hi all,
>>
>> First, my thanks to the many people who gave helpful advice and feedback
>> on how to measure Log4j response time on this list some time ago.
>>
>> We're about to start the Log4j 2.6 release.
>> If anyone is interested, a preview of the garbage-free logging manual
>> page is here:
>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>> and a preview of the updated performance page is here:
>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>
>> Feedback welcome!
>>
>> Remko
>>
>> --
>> You received this message because you are subscribed to the Google Groups
>> "mechanical-sympathy" group.
>> To unsubscribe from this group and stop receiving emails from it, send an
>> email to mechanical-sympathy+unsubscribe@googlegroups.com <javascript:>.
>> For more options, visit https://groups.google.com/d/optout.
>>
>
>
Re: Garbage-free Log4j docs preview
Posted by Gary Gregory <ga...@gmail.com>.
On Mon, Jun 6, 2016 at 2:50 PM, Remko Popma <re...@gmail.com> wrote:
>
>
> Sent from my iPhone
>
> On 2016/06/07, at 0:16, Gary Gregory <ga...@gmail.com> wrote:
>
>
> On Jun 6, 2016 6:48 AM, "Remko Popma" <re...@gmail.com> wrote:
> >
> >
> >
> > On Monday, June 6, 2016 at 6:16:52 PM UTC+9, Anthony Maire wrote:
> >>
> >> Hi Remko
> >>
> >> Great job !
> >> As Martin said, it's really a good thing for the high-performance
> community that someone is trying to improve existing logging frameworks.
> >> The company I'm working for even started to write it's own custom SLF4J
> implementation, and now we are evaluating if it's better for us to finish
> this internal project or to write some custom filters and switch to log4j.
> >
> > Would you like to hear my totally unbiased opinion/advice? :-)
> > I'm not a fan of SLF4J... It means you can never use the rich feature
> set of the underlying logger. Like no lambdas! No CharSequences or plain
> domain objects, only Strings.
> > Not sure why people would want to use it in enterprise software.
> > Maybe, well, likely, I'm biased :-) but I honestly don't see the
> advantage.
> > If the concern is the ability to change your mind later, there is always
> the log4j-to-slf4j adapter...
> >
> >>
> >>
> >> I think there is one possible improvement with boxed primitive types:
> for the moment we want to use only SLF4J api (as a consequence, we're
> aiming for a low allocation rate, but not necessarily no allocation at
> all), so the "Unboxer" mecanism provided in log4j is not an option for us
> to deal with primitive types.
> >> Is this possible in a future release to have a special cases in
> ParameterFormatter.appendSpecialTypes() for boxed primitive types ?
> Currently, when using parametrized message with both Object and primitive
> parameters, I haven't find a "SLF4J-compatible" way to avoid this
> allocation when formatting.
> >
> >
> > If I understand correctly, you're less concerned with the varargs and
> the auto-boxed primitives, but would like to avoid calling toString() on
> the objects that resulted from the auto-boxing (please correct me if I
> misunderstood). Is something like the below what you have in mind? Would
> you mind raising a feature request on the Log4j2 issue tracker for this?
> >
> > private static boolean appendSpecialTypes(final Object o, final
> StringBuilder str) {
> >
> > ...
> > } else if (o instanceof Long) {
> > str.append(((Long) o).longValue());
> > return true;
> >
> > } else if (o instanceof Integer) {
> > str.append(((Integer) o).intValue());
> >
> > return true;
> >
> > } else if (o instanceof Double) {
> > str.append(((Double) o).doubleValue());
> >
> > return true;
> > } // similarly for float, short and boolean.
> > ...
> >
> > }
>
> How about a map lookup to a code instead of a cascading if-else? Or...
> switch to Java 8 ;-)
>
> I don't understand the Java 8 idea: does Java 8 have some mechanism that
> this code can be written differently?
>
> Shall we discuss further on the Jira?
> https://issues.apache.org/jira/browse/LOG4J2-1415
>
Commenting in JIRA then :-) ...
Gary
>
> >
> >
> >>
> >> Kind Regards,
> >> Anthony
> >
> >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> > For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
>
--
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
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
Sent from my iPhone
> On 2016/06/07, at 0:16, Gary Gregory <ga...@gmail.com> wrote:
>
>
> On Jun 6, 2016 6:48 AM, "Remko Popma" <re...@gmail.com> wrote:
> >
> >
> >
> > On Monday, June 6, 2016 at 6:16:52 PM UTC+9, Anthony Maire wrote:
> >>
> >> Hi Remko
> >>
> >> Great job !
> >> As Martin said, it's really a good thing for the high-performance community that someone is trying to improve existing logging frameworks.
> >> The company I'm working for even started to write it's own custom SLF4J implementation, and now we are evaluating if it's better for us to finish this internal project or to write some custom filters and switch to log4j.
> >
> > Would you like to hear my totally unbiased opinion/advice? :-)
> > I'm not a fan of SLF4J... It means you can never use the rich feature set of the underlying logger. Like no lambdas! No CharSequences or plain domain objects, only Strings.
> > Not sure why people would want to use it in enterprise software.
> > Maybe, well, likely, I'm biased :-) but I honestly don't see the advantage.
> > If the concern is the ability to change your mind later, there is always the log4j-to-slf4j adapter...
> >
> >>
> >>
> >> I think there is one possible improvement with boxed primitive types: for the moment we want to use only SLF4J api (as a consequence, we're aiming for a low allocation rate, but not necessarily no allocation at all), so the "Unboxer" mecanism provided in log4j is not an option for us to deal with primitive types.
> >> Is this possible in a future release to have a special cases in ParameterFormatter.appendSpecialTypes() for boxed primitive types ? Currently, when using parametrized message with both Object and primitive parameters, I haven't find a "SLF4J-compatible" way to avoid this allocation when formatting.
> >
> >
> > If I understand correctly, you're less concerned with the varargs and the auto-boxed primitives, but would like to avoid calling toString() on the objects that resulted from the auto-boxing (please correct me if I misunderstood). Is something like the below what you have in mind? Would you mind raising a feature request on the Log4j2 issue tracker for this?
> >
> > private static boolean appendSpecialTypes(final Object o, final StringBuilder str) {
> >
> > ...
> > } else if (o instanceof Long) {
> > str.append(((Long) o).longValue());
> > return true;
> >
> > } else if (o instanceof Integer) {
> > str.append(((Integer) o).intValue());
> >
> > return true;
> >
> > } else if (o instanceof Double) {
> > str.append(((Double) o).doubleValue());
> >
> > return true;
> > } // similarly for float, short and boolean.
> > ...
> >
> > }
>
> How about a map lookup to a code instead of a cascading if-else? Or... switch to Java 8 ;-)
>
I don't understand the Java 8 idea: does Java 8 have some mechanism that this code can be written differently?
Shall we discuss further on the Jira?
https://issues.apache.org/jira/browse/LOG4J2-1415
> >
> >
> >>
> >> Kind Regards,
> >> Anthony
> >
> >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> > For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Garbage-free Log4j docs preview
Posted by Gary Gregory <ga...@gmail.com>.
On Jun 6, 2016 6:48 AM, "Remko Popma" <re...@gmail.com> wrote:
>
>
>
> On Monday, June 6, 2016 at 6:16:52 PM UTC+9, Anthony Maire wrote:
>>
>> Hi Remko
>>
>> Great job !
>> As Martin said, it's really a good thing for the high-performance
community that someone is trying to improve existing logging frameworks.
>> The company I'm working for even started to write it's own custom SLF4J
implementation, and now we are evaluating if it's better for us to finish
this internal project or to write some custom filters and switch to log4j.
>
> Would you like to hear my totally unbiased opinion/advice? :-)
> I'm not a fan of SLF4J... It means you can never use the rich feature set
of the underlying logger. Like no lambdas! No CharSequences or plain domain
objects, only Strings.
> Not sure why people would want to use it in enterprise software.
> Maybe, well, likely, I'm biased :-) but I honestly don't see the
advantage.
> If the concern is the ability to change your mind later, there is always
the log4j-to-slf4j adapter...
>
>>
>>
>> I think there is one possible improvement with boxed primitive types:
for the moment we want to use only SLF4J api (as a consequence, we're
aiming for a low allocation rate, but not necessarily no allocation at
all), so the "Unboxer" mecanism provided in log4j is not an option for us
to deal with primitive types.
>> Is this possible in a future release to have a special cases in
ParameterFormatter.appendSpecialTypes() for boxed primitive types ?
Currently, when using parametrized message with both Object and primitive
parameters, I haven't find a "SLF4J-compatible" way to avoid this
allocation when formatting.
>
>
> If I understand correctly, you're less concerned with the varargs and the
auto-boxed primitives, but would like to avoid calling toString() on the
objects that resulted from the auto-boxing (please correct me if I
misunderstood). Is something like the below what you have in mind? Would
you mind raising a feature request on the Log4j2 issue tracker for this?
>
> private static boolean appendSpecialTypes(final Object o, final
StringBuilder str) {
>
> ...
> } else if (o instanceof Long) {
> str.append(((Long) o).longValue());
> return true;
>
> } else if (o instanceof Integer) {
> str.append(((Integer) o).intValue());
>
> return true;
>
> } else if (o instanceof Double) {
> str.append(((Double) o).doubleValue());
>
> return true;
> } // similarly for float, short and boolean.
> ...
>
> }
How about a map lookup to a code instead of a cascading if-else? Or...
switch to Java 8 ;-)
>
>
>>
>> Kind Regards,
>> Anthony
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
On Monday, June 6, 2016 at 6:16:52 PM UTC+9, Anthony Maire wrote:
>
> Hi Remko
>
> Great job !
> As Martin said, it's really a good thing for the high-performance
> community that someone is trying to improve existing logging frameworks.
> The company I'm working for even started to write it's own custom SLF4J
> implementation, and now we are evaluating if it's better for us to finish
> this internal project or to write some custom filters and switch to log4j.
>
Would you like to hear my totally unbiased opinion/advice? :-)
I'm not a fan of SLF4J... It means you can never use the rich feature set
of the underlying logger. Like no lambdas
<http://logging.apache.org/log4j/2.x/manual/api.html#LambdaSupport>! No
CharSequences or plain domain objects, only Strings.
Not sure why people would want to use it in enterprise software.
Maybe, well, likely, I'm biased :-) but I honestly don't see the advantage.
If the concern is the ability to change your mind later, there is always
the log4j-to-slf4j adapter
<http://logging.apache.org/log4j/2.x/log4j-to-slf4j/index.html>...
>
> I think there is one possible improvement with boxed primitive types: for
> the moment we want to use only SLF4J api (as a consequence, we're aiming
> for a low allocation rate, but not necessarily no allocation at all), so
> the "Unboxer" mecanism provided in log4j is not an option for us to deal
> with primitive types.
> Is this possible in a future release to have a special cases in
> ParameterFormatter.appendSpecialTypes() for boxed primitive types ?
> Currently, when using parametrized message with both Object and primitive
> parameters, I haven't find a "SLF4J-compatible" way to avoid this
> allocation when formatting.
>
If I understand correctly, you're less concerned with the varargs and the
auto-boxed primitives, but would like to avoid calling toString() on the
objects that resulted from the auto-boxing (please correct me if I
misunderstood). Is something like the below what you have in mind? Would
you mind raising a feature request on the Log4j2 issue tracker
<https://issues.apache.org/jira/browse/LOG4J2> for this?
private static boolean appendSpecialTypes(final Object o, final StringBuilder str) {
...
} else if (o instanceof Long) {
str.append(((Long) o).longValue());
return true;
} else if (o instanceof Integer) {
str.append(((Integer) o).intValue());
return true;
} else if (o instanceof Double) {
str.append(((Double) o).doubleValue());
return true;
} // similarly for float, short and boolean.
...
}
> Kind Regards,
> Anthony
>
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
On Sunday, June 5, 2016 at 7:39:25 PM UTC+9, Philippe Marschall wrote:
>
>
>
> On Friday, June 3, 2016 at 5:50:36 PM UTC+2, Remko Popma wrote:
>>
>>
>>
>> On Friday, June 3, 2016 at 4:42:51 PM UTC+9, Philippe Marschall wrote:
>>>
>>>
>>>
>>> On Tuesday, May 17, 2016 at 7:13:09 PM UTC+2, Remko Popma wrote:
>>>>
>>>> Hi all,
>>>>
>>>> First, my thanks to the many people who gave helpful advice and
>>>> feedback on how to measure Log4j response time on this list some time ago.
>>>>
>>>> We're about to start the Log4j 2.6 release.
>>>> If anyone is interested, a preview of the garbage-free logging manual
>>>> page is here:
>>>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>>>> and a preview of the updated performance page is here:
>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>
>>>
>>> Forgive me my ignorance. Maybe I'm missing something or misunderstanding
>>> something. If I want to a custom domain object like this
>>>
>>> LOG.info("something happened with {}", aDomainObject);
>>>
>>> then #toString() will be called on that object which very likely will
>>> result in allocation. If I don't want this my domain object has to
>>> implement CharSequence. I image this to be quite though to do without
>>> allocation eg. how can I know the value of #charAt(10)? I would have to
>>> "render" the entire object without allocation for every #charAt call.
>>>
>>> What I would really need is an alternative to #toString() that takes an
>>> Appendable. Ideally that would be a JDK interface.
>>>
>>> public interface Loggable {
>>>
>>> void logTo(Appendable log);
>>>
>>> }
>>>
>>
>> Philippe, I completely agree. The only thing is that no such interface
>> exists in the JDK, so Log4j 2.6 includes a custom interface:
>>
>> package org.apache.logging.log4j.util;
>> public interface StringBuilderFormattable {
>> /**
>> * Writes a text representation of this object into the specified {@code StringBuilder},
>> * ideally without allocating temporary objects.
>>
>> *
>> * @param buffer the StringBuilder to write into
>> */
>> void formatTo(StringBuilder buffer);
>> }
>>
>>
>> We chose StringBuilder because the Appendable API is not rich enough.
>> Any Object that is logged, either standalone or as a parameter, if it
>> does not implement CharSequence but it does
>> implement StringBuilderFormattable then Log4j 2.6 will call
>> formatTo(StringBuilder) instead of toString() on it. You can use this to
>> render the domain object to text without creating temporary objects.
>>
>> I hope this is useful.
>>
>
> This is exactly what I'm looking for, I somehow missed that part at the
> bottom. Thank you for our work, hopefully this will get more exposure in
> the future.
>
My fault: this was not properly documented. I've updated the docs and we
will update the site with the upcoming 2.6.1 bugfix release.
Glad this is useful, feedback and feature requests always welcome! -Remko
>
> Cheers
> Philippe
>
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
On Friday, June 3, 2016 at 4:42:51 PM UTC+9, Philippe Marschall wrote:
>
>
>
> On Tuesday, May 17, 2016 at 7:13:09 PM UTC+2, Remko Popma wrote:
>>
>> Hi all,
>>
>> First, my thanks to the many people who gave helpful advice and feedback
>> on how to measure Log4j response time on this list some time ago.
>>
>> We're about to start the Log4j 2.6 release.
>> If anyone is interested, a preview of the garbage-free logging manual
>> page is here:
>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>> and a preview of the updated performance page is here:
>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>
>
> Forgive me my ignorance. Maybe I'm missing something or misunderstanding
> something. If I want to a custom domain object like this
>
> LOG.info("something happened with {}", aDomainObject);
>
> then #toString() will be called on that object which very likely will
> result in allocation. If I don't want this my domain object has to
> implement CharSequence. I image this to be quite though to do without
> allocation eg. how can I know the value of #charAt(10)? I would have to
> "render" the entire object without allocation for every #charAt call.
>
> What I would really need is an alternative to #toString() that takes an
> Appendable. Ideally that would be a JDK interface.
>
> public interface Loggable {
>
> void logTo(Appendable log);
>
> }
>
Philippe, I completely agree. The only thing is that no such interface
exists in the JDK, so Log4j 2.6 includes a custom interface:
package org.apache.logging.log4j.util;
public interface StringBuilderFormattable {
/**
* Writes a text representation of this object into the specified {@code StringBuilder},
* ideally without allocating temporary objects.
*
* @param buffer the StringBuilder to write into
*/
void formatTo(StringBuilder buffer);
}
We chose StringBuilder because the Appendable API is not rich enough.
Any Object that is logged, either standalone or as a parameter, if it does
not implement CharSequence then Log4j 2.6 will check if it implements
StringBuilderFormattable before calling toString() on it.
I hope this is useful.
Kind regards, Remko
> Cheers
> Philippe
>
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
I see. I was under the impression that the Filter checked
by Logger.isEnabled() was a composite of the global filters and the Logger
filter, but I just assumed and never really checked. Thanks for correcting
me.
Yes, I agree this is a good idea for a future enhancement.
I don't know how often people configure filters on AppenderRef though.
Depending on how expensive it is to check AppenderRef filters it may make
most sense to just check the LoggerConfig filters before enqueuing the log
event.
Remko
On Wednesday, 18 May 2016, Ralph Goers <ra...@dslextreme.com> wrote:
> That is only checking the global filters. Filters can also be on the
> Logger (or more accurately, the LoggerConfig), AppenderRef, or Appender. I
> don’t think it would ever work to check the filters on the appenders, but I
> would think it would be possible to check those on the Logger and possibly
> even the AppenderRef, although checking the AppenderRef could get very
> complicated.
>
> Ralph
>
> On May 17, 2016, at 6:37 PM, Remko Popma <remko.popma@gmail.com
> <javascript:_e(%7B%7D,'cvml','remko.popma@gmail.com');>> wrote:
>
> Ralph,
>
> I don't think so: AbstractLogger calls logIfEnabled() which calls
> isEnabled() before calling logMessage().
>
> So, even with AsyncLogger the Filters on the Logger are checked before the
> event is created or enqueued.
>
> I don't see an issue with the current code.
>
> Remko
>
> Sent from my iPhone
>
> On 2016/05/18, at 6:33, Ralph Goers <ralph.goers@dslextreme.com
> <javascript:_e(%7B%7D,'cvml','ralph.goers@dslextreme.com');>> wrote:
>
> Remko,
>
> Benedict makes a good point. While I don’t think filters on appenders
> should be called before putting events on the queue we should probably be
> executing the filters on the Logger. But currently those are called in the
> LoggerConfig, which I think is after the events are added to the queue.
>
> Ralph
>
> On May 17, 2016, at 12:55 PM, Benedict Elliott Smith <benedict@apache.org
> <javascript:_e(%7B%7D,'cvml','benedict@apache.org');>> wrote:
>
> Could I suggest that you run tests for latency and throughput effects of
> using this in systems with only moderate-to-low numbers of logging calls?
> (i.e. the vast majority of systems!)
>
> It's very likely that in such systems messages will not reach a velocity
> to keep the Dispatcher running, and so logging calls may often (or always)
> involve a Futex call - which is not a trivial cost. There will almost
> certainly be systems out there with anti-ideal characteristics - logging
> just often enough that these costs materially impact throughput, but not
> often enough that they suddenly disappear.
>
> Even though a majority of systems *do not need this*, because it "async"
> and the new hotness, and there are no advertised downsides, everyone will
> try to use it. It's up to those who know better to make sure these people
> are informed it isn't a free lunch. Making sure all of the caveats are
> reported on the advertising page would be a great start IMO.
>
> Might I also separately suggest you consider filtering events prior to
> placing them on the queue for processing by the dispatcher? I've only
> briefly glanced at the code, but it seems not to be the case currently.
>
>
> On 17 May 2016 at 18:50, Benedict Elliott Smith <_@belliottsmith.com
> <javascript:_e(%7B%7D,'cvml','_@belliottsmith.com');>> wrote:
>
>> Could I suggest that you run tests for latency and throughput effects of
>> using this in systems with only moderate-to-low numbers of logging calls?
>> (i.e. the vast majority of systems!)
>>
>> It's very likely that in such systems messages will not reach a velocity
>> to keep the Dispatcher running, and so logging calls may often (or always)
>> involve a Futex call - which is not a trivial cost. There will almost
>> certainly be systems out there with anti-ideal characteristics - logging
>> just often enough that these costs materially impact throughput, but not
>> often enough that they suddenly disappear.
>>
>> Even though a majority of systems *do not need this*, because it "async"
>> and the new hotness, and there are no advertised downsides, everyone will
>> try to use it. It's up to those who know better to make sure these people
>> are informed it isn't a free lunch. Making sure all of the caveats are
>> reported on the advertising page would be a great start IMO.
>>
>> Might I also separately suggest you consider filtering events prior to
>> placing them on the queue for processing by the dispatcher? I've only
>> briefly glanced at the code, but it seems not to be the case currently.
>>
>> On 17 May 2016 at 18:33, Martin Thompson <mjpt777@gmail.com
>> <javascript:_e(%7B%7D,'cvml','mjpt777@gmail.com');>> wrote:
>>
>>> Hi Remko,
>>>
>>> I'd just like to say that it is a great service to the community as a
>>> whole that someone is seriously looking at improving logging.
>>>
>>> If you keep it up you'll be putting folks like me out of a job :)
>>>
>>> Martin...
>>>
>>>
>>> On 17 May 2016 at 18:13, Remko Popma <remko.popma@gmail.com
>>> <javascript:_e(%7B%7D,'cvml','remko.popma@gmail.com');>> wrote:
>>>
>>>> Hi all,
>>>>
>>>> First, my thanks to the many people who gave helpful advice and
>>>> feedback on how to measure Log4j response time on this list some time ago.
>>>>
>>>> We're about to start the Log4j 2.6 release.
>>>> If anyone is interested, a preview of the garbage-free logging manual
>>>> page is here:
>>>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>>>> and a preview of the updated performance page is here:
>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>
>>>> Feedback welcome!
>>>>
>>>> Remko
>>>>
>>>>
>>>> --
>>>> You received this message because you are subscribed to the Google
>>>> Groups "mechanical-sympathy" group.
>>>> To unsubscribe from this group and stop receiving emails from it, send
>>>> an email to mechanical-sympathy+unsubscribe@googlegroups.com
>>>> <javascript:_e(%7B%7D,'cvml','mechanical-sympathy%2Bunsubscribe@googlegroups.com');>
>>>> .
>>>> For more options, visit https://groups.google.com/d/optout.
>>>>
>>>
>>>
>>> --
>>> You received this message because you are subscribed to the Google
>>> Groups "mechanical-sympathy" group.
>>> To unsubscribe from this group and stop receiving emails from it, send
>>> an email to mechanical-sympathy+unsubscribe@googlegroups.com
>>> <javascript:_e(%7B%7D,'cvml','mechanical-sympathy%2Bunsubscribe@googlegroups.com');>
>>> .
>>> For more options, visit https://groups.google.com/d/optout.
>>>
>>
>>
>
>
>
Re: Garbage-free Log4j docs preview
Posted by Ralph Goers <ra...@dslextreme.com>.
That is only checking the global filters. Filters can also be on the Logger (or more accurately, the LoggerConfig), AppenderRef, or Appender. I don’t think it would ever work to check the filters on the appenders, but I would think it would be possible to check those on the Logger and possibly even the AppenderRef, although checking the AppenderRef could get very complicated.
Ralph
> On May 17, 2016, at 6:37 PM, Remko Popma <re...@gmail.com> wrote:
>
> Ralph,
>
> I don't think so: AbstractLogger calls logIfEnabled() which calls isEnabled() before calling logMessage().
>
> So, even with AsyncLogger the Filters on the Logger are checked before the event is created or enqueued.
>
> I don't see an issue with the current code.
>
> Remko
>
> Sent from my iPhone
>
> On 2016/05/18, at 6:33, Ralph Goers <ralph.goers@dslextreme.com <ma...@dslextreme.com>> wrote:
>
>> Remko,
>>
>> Benedict makes a good point. While I don’t think filters on appenders should be called before putting events on the queue we should probably be executing the filters on the Logger. But currently those are called in the LoggerConfig, which I think is after the events are added to the queue.
>>
>> Ralph
>>
>>> On May 17, 2016, at 12:55 PM, Benedict Elliott Smith <benedict@apache.org <ma...@apache.org>> wrote:
>>>
>>> Could I suggest that you run tests for latency and throughput effects of using this in systems with only moderate-to-low numbers of logging calls? (i.e. the vast majority of systems!)
>>>
>>> It's very likely that in such systems messages will not reach a velocity to keep the Dispatcher running, and so logging calls may often (or always) involve a Futex call - which is not a trivial cost. There will almost certainly be systems out there with anti-ideal characteristics - logging just often enough that these costs materially impact throughput, but not often enough that they suddenly disappear.
>>>
>>> Even though a majority of systems do not need this, because it "async" and the new hotness, and there are no advertised downsides, everyone will try to use it. It's up to those who know better to make sure these people are informed it isn't a free lunch. Making sure all of the caveats are reported on the advertising page would be a great start IMO.
>>>
>>> Might I also separately suggest you consider filtering events prior to placing them on the queue for processing by the dispatcher? I've only briefly glanced at the code, but it seems not to be the case currently.
>>>
>>>
>>> On 17 May 2016 at 18:50, Benedict Elliott Smith <_@belliottsmith.com <ma...@belliottsmith.com>> wrote:
>>> Could I suggest that you run tests for latency and throughput effects of using this in systems with only moderate-to-low numbers of logging calls? (i.e. the vast majority of systems!)
>>>
>>> It's very likely that in such systems messages will not reach a velocity to keep the Dispatcher running, and so logging calls may often (or always) involve a Futex call - which is not a trivial cost. There will almost certainly be systems out there with anti-ideal characteristics - logging just often enough that these costs materially impact throughput, but not often enough that they suddenly disappear.
>>>
>>> Even though a majority of systems do not need this, because it "async" and the new hotness, and there are no advertised downsides, everyone will try to use it. It's up to those who know better to make sure these people are informed it isn't a free lunch. Making sure all of the caveats are reported on the advertising page would be a great start IMO.
>>>
>>> Might I also separately suggest you consider filtering events prior to placing them on the queue for processing by the dispatcher? I've only briefly glanced at the code, but it seems not to be the case currently.
>>>
>>> On 17 May 2016 at 18:33, Martin Thompson <mjpt777@gmail.com <ma...@gmail.com>> wrote:
>>> Hi Remko,
>>>
>>> I'd just like to say that it is a great service to the community as a whole that someone is seriously looking at improving logging.
>>>
>>> If you keep it up you'll be putting folks like me out of a job :)
>>>
>>> Martin...
>>>
>>>
>>> On 17 May 2016 at 18:13, Remko Popma <remko.popma@gmail.com <ma...@gmail.com>> wrote:
>>> Hi all,
>>>
>>> First, my thanks to the many people who gave helpful advice and feedback on how to measure Log4j response time on this list some time ago.
>>>
>>> We're about to start the Log4j 2.6 release.
>>> If anyone is interested, a preview of the garbage-free logging manual page is here: http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html <http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html>
>>> and a preview of the updated performance page is here: http://home.apache.org/~rpopma/log4j/2.6/performance.html <http://home.apache.org/~rpopma/log4j/2.6/performance.html>
>>>
>>> Feedback welcome!
>>>
>>> Remko
>>>
>>>
>>> --
>>> You received this message because you are subscribed to the Google Groups "mechanical-sympathy" group.
>>> To unsubscribe from this group and stop receiving emails from it, send an email to mechanical-sympathy+unsubscribe@googlegroups.com <ma...@googlegroups.com>.
>>> For more options, visit https://groups.google.com/d/optout <https://groups.google.com/d/optout>.
>>>
>>>
>>> --
>>> You received this message because you are subscribed to the Google Groups "mechanical-sympathy" group.
>>> To unsubscribe from this group and stop receiving emails from it, send an email to mechanical-sympathy+unsubscribe@googlegroups.com <ma...@googlegroups.com>.
>>> For more options, visit https://groups.google.com/d/optout <https://groups.google.com/d/optout>.
>>>
>>>
>>
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
Ralph,
I don't think so: AbstractLogger calls logIfEnabled() which calls isEnabled() before calling logMessage().
So, even with AsyncLogger the Filters on the Logger are checked before the event is created or enqueued.
I don't see an issue with the current code.
Remko
Sent from my iPhone
> On 2016/05/18, at 6:33, Ralph Goers <ra...@dslextreme.com> wrote:
>
> Remko,
>
> Benedict makes a good point. While I don�ft think filters on appenders should be called before putting events on the queue we should probably be executing the filters on the Logger. But currently those are called in the LoggerConfig, which I think is after the events are added to the queue.
>
> Ralph
>
>> On May 17, 2016, at 12:55 PM, Benedict Elliott Smith <be...@apache.org> wrote:
>>
>> Could I suggest that you run tests for latency and throughput effects of using this in systems with only moderate-to-low numbers of logging calls? (i.e. the vast majority of systems!)
>>
>> It's very likely that in such systems messages will not reach a velocity to keep the Dispatcher running, and so logging calls may often (or always) involve a Futex call - which is not a trivial cost. There will almost certainly be systems out there with anti-ideal characteristics - logging just often enough that these costs materially impact throughput, but not often enough that they suddenly disappear.
>>
>> Even though a majority of systems do not need this, because it "async" and the new hotness, and there are no advertised downsides, everyone will try to use it. It's up to those who know better to make sure these people are informed it isn't a free lunch. Making sure all of the caveats are reported on the advertising page would be a great start IMO.
>>
>> Might I also separately suggest you consider filtering events prior to placing them on the queue for processing by the dispatcher? I've only briefly glanced at the code, but it seems not to be the case currently.
>>
>>
>>> On 17 May 2016 at 18:50, Benedict Elliott Smith <_...@belliottsmith.com> wrote:
>>> Could I suggest that you run tests for latency and throughput effects of using this in systems with only moderate-to-low numbers of logging calls? (i.e. the vast majority of systems!)
>>>
>>> It's very likely that in such systems messages will not reach a velocity to keep the Dispatcher running, and so logging calls may often (or always) involve a Futex call - which is not a trivial cost. There will almost certainly be systems out there with anti-ideal characteristics - logging just often enough that these costs materially impact throughput, but not often enough that they suddenly disappear.
>>>
>>> Even though a majority of systems do not need this, because it "async" and the new hotness, and there are no advertised downsides, everyone will try to use it. It's up to those who know better to make sure these people are informed it isn't a free lunch. Making sure all of the caveats are reported on the advertising page would be a great start IMO.
>>>
>>> Might I also separately suggest you consider filtering events prior to placing them on the queue for processing by the dispatcher? I've only briefly glanced at the code, but it seems not to be the case currently.
>>>
>>>> On 17 May 2016 at 18:33, Martin Thompson <mj...@gmail.com> wrote:
>>>> Hi Remko,
>>>>
>>>> I'd just like to say that it is a great service to the community as a whole that someone is seriously looking at improving logging.
>>>>
>>>> If you keep it up you'll be putting folks like me out of a job :)
>>>>
>>>> Martin...
>>>>
>>>>
>>>>> On 17 May 2016 at 18:13, Remko Popma <re...@gmail.com> wrote:
>>>>> Hi all,
>>>>>
>>>>> First, my thanks to the many people who gave helpful advice and feedback on how to measure Log4j response time on this list some time ago.
>>>>>
>>>>> We're about to start the Log4j 2.6 release.
>>>>> If anyone is interested, a preview of the garbage-free logging manual page is here: http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>>>>> and a preview of the updated performance page is here: http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>>
>>>>> Feedback welcome!
>>>>>
>>>>> Remko
>>>>>
>>>>>
>>>>> --
>>>>> You received this message because you are subscribed to the Google Groups "mechanical-sympathy" group.
>>>>> To unsubscribe from this group and stop receiving emails from it, send an email to mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>
>>>>
>>>> --
>>>> You received this message because you are subscribed to the Google Groups "mechanical-sympathy" group.
>>>> To unsubscribe from this group and stop receiving emails from it, send an email to mechanical-sympathy+unsubscribe@googlegroups.com.
>>>> For more options, visit https://groups.google.com/d/optout.
>
Re: Garbage-free Log4j docs preview
Posted by Ralph Goers <ra...@dslextreme.com>.
Remko,
Benedict makes a good point. While I don’t think filters on appenders should be called before putting events on the queue we should probably be executing the filters on the Logger. But currently those are called in the LoggerConfig, which I think is after the events are added to the queue.
Ralph
> On May 17, 2016, at 12:55 PM, Benedict Elliott Smith <be...@apache.org> wrote:
>
> Could I suggest that you run tests for latency and throughput effects of using this in systems with only moderate-to-low numbers of logging calls? (i.e. the vast majority of systems!)
>
> It's very likely that in such systems messages will not reach a velocity to keep the Dispatcher running, and so logging calls may often (or always) involve a Futex call - which is not a trivial cost. There will almost certainly be systems out there with anti-ideal characteristics - logging just often enough that these costs materially impact throughput, but not often enough that they suddenly disappear.
>
> Even though a majority of systems do not need this, because it "async" and the new hotness, and there are no advertised downsides, everyone will try to use it. It's up to those who know better to make sure these people are informed it isn't a free lunch. Making sure all of the caveats are reported on the advertising page would be a great start IMO.
>
> Might I also separately suggest you consider filtering events prior to placing them on the queue for processing by the dispatcher? I've only briefly glanced at the code, but it seems not to be the case currently.
>
>
> On 17 May 2016 at 18:50, Benedict Elliott Smith <_@belliottsmith.com <ma...@belliottsmith.com>> wrote:
> Could I suggest that you run tests for latency and throughput effects of using this in systems with only moderate-to-low numbers of logging calls? (i.e. the vast majority of systems!)
>
> It's very likely that in such systems messages will not reach a velocity to keep the Dispatcher running, and so logging calls may often (or always) involve a Futex call - which is not a trivial cost. There will almost certainly be systems out there with anti-ideal characteristics - logging just often enough that these costs materially impact throughput, but not often enough that they suddenly disappear.
>
> Even though a majority of systems do not need this, because it "async" and the new hotness, and there are no advertised downsides, everyone will try to use it. It's up to those who know better to make sure these people are informed it isn't a free lunch. Making sure all of the caveats are reported on the advertising page would be a great start IMO.
>
> Might I also separately suggest you consider filtering events prior to placing them on the queue for processing by the dispatcher? I've only briefly glanced at the code, but it seems not to be the case currently.
>
> On 17 May 2016 at 18:33, Martin Thompson <mjpt777@gmail.com <ma...@gmail.com>> wrote:
> Hi Remko,
>
> I'd just like to say that it is a great service to the community as a whole that someone is seriously looking at improving logging.
>
> If you keep it up you'll be putting folks like me out of a job :)
>
> Martin...
>
>
> On 17 May 2016 at 18:13, Remko Popma <remko.popma@gmail.com <ma...@gmail.com>> wrote:
> Hi all,
>
> First, my thanks to the many people who gave helpful advice and feedback on how to measure Log4j response time on this list some time ago.
>
> We're about to start the Log4j 2.6 release.
> If anyone is interested, a preview of the garbage-free logging manual page is here: http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html <http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html>
> and a preview of the updated performance page is here: http://home.apache.org/~rpopma/log4j/2.6/performance.html <http://home.apache.org/~rpopma/log4j/2.6/performance.html>
>
> Feedback welcome!
>
> Remko
>
>
> --
> You received this message because you are subscribed to the Google Groups "mechanical-sympathy" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to mechanical-sympathy+unsubscribe@googlegroups.com <ma...@googlegroups.com>.
> For more options, visit https://groups.google.com/d/optout <https://groups.google.com/d/optout>.
>
>
> --
> You received this message because you are subscribed to the Google Groups "mechanical-sympathy" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to mechanical-sympathy+unsubscribe@googlegroups.com <ma...@googlegroups.com>.
> For more options, visit https://groups.google.com/d/optout <https://groups.google.com/d/optout>.
>
>
Re: Garbage-free Log4j docs preview
Posted by Mikael Ståldal <mi...@magine.com>.
Can the support for Intel TSX in Java 8u20 be relevant here?
https://bugs.openjdk.java.net/browse/JDK-8031320
On Sun, May 22, 2016 at 3:42 PM, Remko Popma <re...@gmail.com> wrote:
>
>
> On Sunday, May 22, 2016 at 6:34:13 PM UTC+9, Benedict Elliott Smith wrote:
>>
>> Hi Remko,
>>
>> I realise that I was looking at the old log4j code without realising it,
>> in which there is always a futex involved.
>>
> Which class is this? Async Loggers in Log4j 2 have always been lock-free.
> What may be confusing is that Log4j 2 also has an Async*Appender*, which
> does not use the Disruptor but uses a JDK BlockingArrayQueue. This appender
> is very similar to how Logback and Log4j 1 do asynchronous logging. Async
> *Appender* (in Log4j 2, Log4j 1 and Logback, they all use a blocking
> queue) is sensitive to lock contention and does not scale with more threads.
>
>
>>
>> However the behaviour of the disruptor that backs the new code will
>> depend on the wait strategy employed (and I'll note your default is a
>> blocking strategy, for which my prior statement holds*).
>>
> Perhaps the key misunderstanding is here. I think I did not explain it
> well in my previous message. Let me try again.
>
> Async Loggers use the Disruptor and are lock-free. This means that
> multiple application threads can log concurrently and are not blocked by
> each other. This is true for very low workloads, medium workloads and high
> workloads.
>
> Only if an application logs messages at a very high rate for a long period
> of time, or uses a slow appender, the Disruptor ringbuffer can fill up and
> application threads will have to wait until a slot in the ringbuffer
> becomes available. For the 2.6 release I have added text to the
> Trade-offs section
> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Trade-offs>
> to explain this last point, based on your feedback.
>
> Note that the Disruptor wait strategy is irrelevant to all this.
> Application threads are *not *impacted by the wait strategy.
>
>
>> Here we obviously get into the territory of people needing to understand
>> the disruptor as well as your logging framework, but since you have a whole
>> section labelled "Trade-offs" in which you draw attention to the improved
>> throughput and latency profile under "Benefits," under "Drawbacks" it might
>> be nice to mention these possible confounders. Or at least raise a bat
>> signal to go and understand the tradeoffs for the disruptor (which is also
>> regrettably poorly understood).
>>
>> It might also be helpful to explicitly call out the configuration used
>> for your benchmarks,
>>
> Tests on the 2.6 performance page
> <http://home.apache.org/~rpopma/log4j/2.6/performance.html> are mostly
> done with JMH benchmarks where parameters are in the javadoc.
> Tests on the Async Loggers page are partly with the new ResponseTimeTest
> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java>class
> (params in the doc
> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Latency>) and
> partly still shows results from the older PerfTestDriver
> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTestDriver.java>
> class. This last one has parameters in the code. You'll need to spend some
> time to get familiar with it if you want to run it.
>
> and perhaps to run a comparison against some real software - github does
>> not lack for applications using log4j! Unfortunately I bet this would
>> result in a much less sexy graph.
>>
> Log4j 2 has had lock-free Async Loggers from its 2.0-beta5 release
> <http://logging.apache.org/log4j/2.x/changes-report.html#a2.0-beta5>,
> three years ago. If there are any serious performance drawbacks like you
> seem to think there are I hope I would have heard of them. Fortunately the
> opposite is true. People report very positive experiences
> <http://tech.finn.no/2014/07/01/log4j2-in-production-making-it-fly/>.
> People who did their own measurements reported it makes their logging as
> fast as if it was switched off
> <http://blogs.mulesoft.com/dev/mule-dev/mule-3-6-asynchronous-logging/>.
>
>
>> Finally, I really think people should (in your wiki page) explicitly be
>> *discouraged* from using this part of your framework *unless they know
>> they need it*. It's a fantastic piece of work for people who *do* need
>> it.
>>
> Again, I think you are laboring under a misapprehension. I cannot imagine
> a scenario where lock-free logging would be a bad thing. If you think there
> is, please show evidence.
>
>
>> But 99.99% of people would be better off with a logger that just avoids
>> blocking threads when one is already in the process of logging.
>>
> Avoiding blocking is exactly what the Async Loggers are for. (So I really
> think there is some misunderstanding somewhere.)
> Based on your feedback, I've updated
> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html> the side nav
> menu and page title for the 2.6 release to clarify that Async Loggers are
> lock-free. I hope this will help avoid misunderstandings.
>
>
>>
>> (*It looks like you silently ignore misconfiguration, and default to
>> timeout wait strategy also, which is probably going to surprise some people)
>>
>>
>>
>>
>>
>> On 19 May 2016 at 00:34, Remko Popma <re...@gmail.com> wrote:
>>
>>> Benedict, thanks for your feedback!
>>>
>>> With regards to filtering, global filters are already considered before
>>> the event is enqueued. Filters configured on the Logger and AppenderRef are
>>> applied prior to enqueueing with mixed Sync/Async
>>> <http://logging.apache.org/log4j/2.x/manual/async.html#MixedSync-Async>
>>> Loggers but when all loggers are async
>>> <http://logging.apache.org/log4j/2.x/manual/async.html#AllAsync> these
>>> filters are applied by the background thread. We can probably improve this,
>>> thanks for the suggestion!
>>>
>>> Your suggestion to run performance tests under lower loads is reasonable
>>> and we will look at this for a future release.
>>> I did experiment with this a little a while back and did see larger
>>> response time pauses. Perhaps others with more experience can chime in.
>>>
>>> My understanding of how the Disruptor works is that enqueueing the event
>>> is lock-free, so applications threads doing the logging should not
>>> experience any context switches or suffer latency from Futex calls caused
>>> by logging (regardless of the workload). The background thread is another
>>> story. Under moderate to low workloads the background thread may (depending
>>> on the wait policy) fall asleep and experience delays before waking up when
>>> work arrives. However, if there are enough cores to serve all threads I
>>> don't see how such background thread delays can impact (cause response time
>>> pauses for) the application that is doing the logging. Please correct me if
>>> my understanding is incorrect.
>>>
>>> My thinking is that using async loggers is good for reactive
>>> applications that need to respond quickly to external events. It is
>>> especially useful if the application needs to deal with occasional bursts
>>> of work (and accompanied bursts of logging). This is where async loggers
>>> can deliver value even if the normal workload is low.
>>>
>>> Remko
>>>
>>> On Wednesday, May 18, 2016 at 2:56:18 AM UTC+9, Benedict Elliott Smith
>>> wrote:
>>>>
>>>> Regrettably it seems impossible (or at least very annoying) to send to
>>>> both lists simultaneously...
>>>>
>>>> On 17 May 2016 at 18:55, Benedict Elliott Smith <be...@apache.org>
>>>> wrote:
>>>>
>>>>> Could I suggest that you run tests for latency and throughput effects
>>>>> of using this in systems with only moderate-to-low numbers of logging
>>>>> calls? (i.e. the vast majority of systems!)
>>>>>
>>>>
>>>>> It's very likely that in such systems messages will not reach a
>>>>> velocity to keep the Dispatcher running, and so logging calls may often (or
>>>>> always) involve a Futex call - which is not a trivial cost. There will
>>>>> almost certainly be systems out there with anti-ideal characteristics -
>>>>> logging just often enough that these costs materially impact throughput,
>>>>> but not often enough that they suddenly disappear.
>>>>>
>>>>> Even though a majority of systems *do not need this*, because it
>>>>> "async" and the new hotness, and there are no advertised downsides,
>>>>> everyone will try to use it. It's up to those who know better to make sure
>>>>> these people are informed it isn't a free lunch. Making sure all of the
>>>>> caveats are reported on the advertising page would be a great start IMO.
>>>>>
>>>>> Might I also separately suggest you consider filtering events prior to
>>>>> placing them on the queue for processing by the dispatcher? I've only
>>>>> briefly glanced at the code, but it seems not to be the case currently.
>>>>>
>>>>>>
>>>>>> On 17 May 2016 at 18:33, Martin Thompson <mj...@gmail.com> wrote:
>>>>>>
>>>>>>> Hi Remko,
>>>>>>>
>>>>>>> I'd just like to say that it is a great service to the community as
>>>>>>> a whole that someone is seriously looking at improving logging.
>>>>>>>
>>>>>>> If you keep it up you'll be putting folks like me out of a job :)
>>>>>>>
>>>>>>> Martin...
>>>>>>>
>>>>>>>
>>>>>>> On 17 May 2016 at 18:13, Remko Popma <re...@gmail.com> wrote:
>>>>>>>
>>>>>>>> Hi all,
>>>>>>>>
>>>>>>>> First, my thanks to the many people who gave helpful advice and
>>>>>>>> feedback on how to measure Log4j response time on this list some time ago.
>>>>>>>>
>>>>>>>> We're about to start the Log4j 2.6 release.
>>>>>>>> If anyone is interested, a preview of the garbage-free logging
>>>>>>>> manual page is here:
>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>>>>>>>> and a preview of the updated performance page is here:
>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>>>>>
>>>>>>>> Feedback welcome!
>>>>>>>>
>>>>>>>> Remko
>>>>>>>>
>>>>>>>> --
>>>>>>>> You received this message because you are subscribed to the Google
>>>>>>>> Groups "mechanical-sympathy" group.
>>>>>>>> To unsubscribe from this group and stop receiving emails from it,
>>>>>>>> send an email to mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>>
>>>>>>>
>>>>>>> --
>>>>>>> You received this message because you are subscribed to the Google
>>>>>>> Groups "mechanical-sympathy" group.
>>>>>>> To unsubscribe from this group and stop receiving emails from it,
>>>>>>> send an email to mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>
>>>>>>
>>>>>>
>>>>>
>>>>
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
--
[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.
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
Yes, potentially *very* relevant!
Please post this on the mechanical sympathy mailing list!
On Monday, 23 May 2016, Mikael Ståldal <mi...@magine.com> wrote:
> Can the support for Intel TSX in Java 8u20 be relevant here?
>
> https://bugs.openjdk.java.net/browse/JDK-8031320
>
> On Sun, May 22, 2016 at 5:40 PM, Remko Popma <remko.popma@gmail.com
> <javascript:_e(%7B%7D,'cvml','remko.popma@gmail.com');>> wrote:
>
>>
>>
>> On Sunday, May 22, 2016 at 11:08:37 PM UTC+9, Benedict Elliott Smith
>> wrote:
>>>
>>> It's possible I'm missing some other aspect that insulates the
>>> application thread from the disruptor, but from your message it seems to me
>>> that you fall into the all-too-common category of people who do not fully
>>> understand the semantics of the disruptor. Application threads (i.e.
>>> disruptor producers) very much *are* affected by the wait strategy.
>>> Under normal use, *if the disruptor consumer thread is employing a
>>> blocking strategy, there will be futex call to unblock it when work is
>>> provided*. i.e. whenever the queue transitions from empty to
>>> non-empty, i.e. for most messages with low-to-medium logging rates.
>>>
>>> In this situation the enqueueing of a message is also* not lock free*,
>>> as while futexes can in theory be lock-free, the JVM uses a lock to
>>> synchronise access to the semaphore that controls its runnable state, so
>>> all threads attempting to wake it up concurrently will compete for this
>>> lock.
>>>
>>
>> Well... Looks like you were right and I was wrong.
>>
>> Interesting. Apart from the dent in my pride here, this is actually good
>> news. It means we can do better!
>>
>> So in the worst-case scenario Async Loggers/Disruptor with the blocking
>> wait strategy give performance equivalent to AsyncAppender with a
>> BlockingArrayQueue. We can expect Async Loggers with Disruptor to
>> outperform AsyncAppender with BlockingArrayQueue when workloads are high or
>> bursts of work keep the background thread busy for some time. At least this
>> is my understanding now. Or did I miss something and are there cases where
>> Async Loggers with Disruptor will perform worse than AsyncAppender with
>> BlockingArrayQueue?
>>
>> In terms of how to improve, short-term we should probably look at using
>> the PhasedBackoffWaitStrategy as the default, although there will always be
>> workloads that "miss the window". The trade-off is increased CPU. We need
>> to tread carefully here because users reporting high CPU is why we changed
>> from the sleeping wait strategy to blocking. (The default in Log4j 2.6 will
>> be timeout blocking wait to deal with a deadlock issue in Solaris.)
>>
>> Long-term we should probably explore other data structures.
>>
>> Exciting times. Thanks for correcting me!
>>
>>
>>>
>>> On 22 May 2016 at 15:07, Benedict Elliott Smith <be...@apache.org>
>>> wrote:
>>>
>>>> It's possible I'm missing some other aspect that insulates the
>>>> application thread from the disruptor, but from your message it seems to me
>>>> that you fall into the all-too-common category of people who do not fully
>>>> understand the semantics of the disruptor. Application threads (i.e.
>>>> disruptor producers) very much *are* affected by the wait strategy.
>>>> Under normal use, *if the disruptor consumer thread is employing a
>>>> blocking strategy, there will be futex call to unblock it when work is
>>>> provided*. i.e. whenever the queue transitions from empty to
>>>> non-empty, i.e. for most messages with low-to-medium logging rates.
>>>>
>>>> In this situation the enqueueing of a message is also* not lock free*,
>>>> as while futexes can in theory be lock-free, the JVM uses a lock to
>>>> synchronise access to the semaphore that controls its runnable state, so
>>>> all threads attempting to wake it up concurrently will compete for this
>>>> lock.
>>>>
>>>>
>>>>
>>>> On 22 May 2016 at 14:42, Remko Popma <re...@gmail.com> wrote:
>>>>
>>>>>
>>>>>
>>>>> On Sunday, May 22, 2016 at 6:34:13 PM UTC+9, Benedict Elliott Smith
>>>>> wrote:
>>>>>>
>>>>>> Hi Remko,
>>>>>>
>>>>>> I realise that I was looking at the old log4j code without realising
>>>>>> it, in which there is always a futex involved.
>>>>>>
>>>>> Which class is this? Async Loggers in Log4j 2 have always been
>>>>> lock-free. What may be confusing is that Log4j 2 also has an Async
>>>>> *Appender*, which does not use the Disruptor but uses a JDK
>>>>> BlockingArrayQueue. This appender is very similar to how Logback and Log4j
>>>>> 1 do asynchronous logging. Async*Appender* (in Log4j 2, Log4j 1 and
>>>>> Logback, they all use a blocking queue) is sensitive to lock contention and
>>>>> does not scale with more threads.
>>>>>
>>>>>
>>>>>>
>>>>>> However the behaviour of the disruptor that backs the new code will
>>>>>> depend on the wait strategy employed (and I'll note your default is a
>>>>>> blocking strategy, for which my prior statement holds*).
>>>>>>
>>>>> Perhaps the key misunderstanding is here. I think I did not explain it
>>>>> well in my previous message. Let me try again.
>>>>>
>>>>> Async Loggers use the Disruptor and are lock-free. This means that
>>>>> multiple application threads can log concurrently and are not blocked by
>>>>> each other. This is true for very low workloads, medium workloads and high
>>>>> workloads.
>>>>>
>>>>> Only if an application logs messages at a very high rate for a long
>>>>> period of time, or uses a slow appender, the Disruptor ringbuffer can fill
>>>>> up and application threads will have to wait until a slot in the ringbuffer
>>>>> becomes available. For the 2.6 release I have added text to the
>>>>> Trade-offs section
>>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Trade-offs>
>>>>> to explain this last point, based on your feedback.
>>>>>
>>>>> Note that the Disruptor wait strategy is irrelevant to all this.
>>>>> Application threads are *not *impacted by the wait strategy.
>>>>>
>>>>>
>>>>>> Here we obviously get into the territory of people needing to
>>>>>> understand the disruptor as well as your logging framework, but since you
>>>>>> have a whole section labelled "Trade-offs" in which you draw attention to
>>>>>> the improved throughput and latency profile under "Benefits," under
>>>>>> "Drawbacks" it might be nice to mention these possible confounders. Or at
>>>>>> least raise a bat signal to go and understand the tradeoffs for the
>>>>>> disruptor (which is also regrettably poorly understood).
>>>>>>
>>>>>> It might also be helpful to explicitly call out the configuration
>>>>>> used for your benchmarks,
>>>>>>
>>>>> Tests on the 2.6 performance page
>>>>> <http://home.apache.org/~rpopma/log4j/2.6/performance.html> are
>>>>> mostly done with JMH benchmarks where parameters are in the javadoc.
>>>>> Tests on the Async Loggers page are partly with the new ResponseTimeTest
>>>>>
>>>>> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java>class
>>>>> (params in the doc
>>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Latency>)
>>>>> and partly still shows results from the older PerfTestDriver
>>>>> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTestDriver.java>
>>>>> class. This last one has parameters in the code. You'll need to spend some
>>>>> time to get familiar with it if you want to run it.
>>>>>
>>>>> and perhaps to run a comparison against some real software - github
>>>>>> does not lack for applications using log4j! Unfortunately I bet this would
>>>>>> result in a much less sexy graph.
>>>>>>
>>>>> Log4j 2 has had lock-free Async Loggers from its 2.0-beta5 release
>>>>> <http://logging.apache.org/log4j/2.x/changes-report.html#a2.0-beta5>,
>>>>> three years ago. If there are any serious performance drawbacks like you
>>>>> seem to think there are I hope I would have heard of them. Fortunately the
>>>>> opposite is true. People report very positive experiences
>>>>> <http://tech.finn.no/2014/07/01/log4j2-in-production-making-it-fly/>.
>>>>> People who did their own measurements reported it makes their logging as
>>>>> fast as if it was switched off
>>>>> <http://blogs.mulesoft.com/dev/mule-dev/mule-3-6-asynchronous-logging/>
>>>>> .
>>>>>
>>>>>
>>>>>> Finally, I really think people should (in your wiki page) explicitly
>>>>>> be *discouraged* from using this part of your framework *unless they
>>>>>> know they need it*. It's a fantastic piece of work for people who
>>>>>> *do* need it.
>>>>>>
>>>>> Again, I think you are laboring under a misapprehension. I cannot
>>>>> imagine a scenario where lock-free logging would be a bad thing. If you
>>>>> think there is, please show evidence.
>>>>>
>>>>>
>>>>>> But 99.99% of people would be better off with a logger that just
>>>>>> avoids blocking threads when one is already in the process of logging.
>>>>>>
>>>>> Avoiding blocking is exactly what the Async Loggers are for. (So I
>>>>> really think there is some misunderstanding somewhere.)
>>>>> Based on your feedback, I've updated
>>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html> the side
>>>>> nav menu and page title for the 2.6 release to clarify that Async Loggers
>>>>> are lock-free. I hope this will help avoid misunderstandings.
>>>>>
>>>>>
>>>>>>
>>>>>> (*It looks like you silently ignore misconfiguration, and default to
>>>>>> timeout wait strategy also, which is probably going to surprise some people)
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> On 19 May 2016 at 00:34, Remko Popma <re...@gmail.com> wrote:
>>>>>>
>>>>>>> Benedict, thanks for your feedback!
>>>>>>>
>>>>>>> With regards to filtering, global filters are already considered
>>>>>>> before the event is enqueued. Filters configured on the Logger and
>>>>>>> AppenderRef are applied prior to enqueueing with mixed Sync/Async
>>>>>>> <http://logging.apache.org/log4j/2.x/manual/async.html#MixedSync-Async>
>>>>>>> Loggers but when all loggers are async
>>>>>>> <http://logging.apache.org/log4j/2.x/manual/async.html#AllAsync>
>>>>>>> these filters are applied by the background thread. We can probably improve
>>>>>>> this, thanks for the suggestion!
>>>>>>>
>>>>>>> Your suggestion to run performance tests under lower loads is
>>>>>>> reasonable and we will look at this for a future release.
>>>>>>> I did experiment with this a little a while back and did see larger
>>>>>>> response time pauses. Perhaps others with more experience can chime in.
>>>>>>>
>>>>>>> My understanding of how the Disruptor works is that enqueueing the
>>>>>>> event is lock-free, so applications threads doing the logging should not
>>>>>>> experience any context switches or suffer latency from Futex calls caused
>>>>>>> by logging (regardless of the workload). The background thread is another
>>>>>>> story. Under moderate to low workloads the background thread may (depending
>>>>>>> on the wait policy) fall asleep and experience delays before waking up when
>>>>>>> work arrives. However, if there are enough cores to serve all threads I
>>>>>>> don't see how such background thread delays can impact (cause response time
>>>>>>> pauses for) the application that is doing the logging. Please correct me if
>>>>>>> my understanding is incorrect.
>>>>>>>
>>>>>>> My thinking is that using async loggers is good for reactive
>>>>>>> applications that need to respond quickly to external events. It is
>>>>>>> especially useful if the application needs to deal with occasional bursts
>>>>>>> of work (and accompanied bursts of logging). This is where async loggers
>>>>>>> can deliver value even if the normal workload is low.
>>>>>>>
>>>>>>> Remko
>>>>>>>
>>>>>>> On Wednesday, May 18, 2016 at 2:56:18 AM UTC+9, Benedict Elliott
>>>>>>> Smith wrote:
>>>>>>>>
>>>>>>>> Regrettably it seems impossible (or at least very annoying) to send
>>>>>>>> to both lists simultaneously...
>>>>>>>>
>>>>>>>> On 17 May 2016 at 18:55, Benedict Elliott Smith <bene...@apache.org
>>>>>>>> > wrote:
>>>>>>>>
>>>>>>>>> Could I suggest that you run tests for latency and throughput
>>>>>>>>> effects of using this in systems with only moderate-to-low numbers of
>>>>>>>>> logging calls? (i.e. the vast majority of systems!)
>>>>>>>>>
>>>>>>>>
>>>>>>>>> It's very likely that in such systems messages will not reach a
>>>>>>>>> velocity to keep the Dispatcher running, and so logging calls may often (or
>>>>>>>>> always) involve a Futex call - which is not a trivial cost. There will
>>>>>>>>> almost certainly be systems out there with anti-ideal characteristics -
>>>>>>>>> logging just often enough that these costs materially impact throughput,
>>>>>>>>> but not often enough that they suddenly disappear.
>>>>>>>>>
>>>>>>>>> Even though a majority of systems *do not need this*, because it
>>>>>>>>> "async" and the new hotness, and there are no advertised downsides,
>>>>>>>>> everyone will try to use it. It's up to those who know better to make sure
>>>>>>>>> these people are informed it isn't a free lunch. Making sure all of the
>>>>>>>>> caveats are reported on the advertising page would be a great start IMO.
>>>>>>>>>
>>>>>>>>> Might I also separately suggest you consider filtering events
>>>>>>>>> prior to placing them on the queue for processing by the dispatcher? I've
>>>>>>>>> only briefly glanced at the code, but it seems not to be the case currently.
>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> On 17 May 2016 at 18:33, Martin Thompson <mj...@gmail.com>
>>>>>>>>>> wrote:
>>>>>>>>>>
>>>>>>>>>>> Hi Remko,
>>>>>>>>>>>
>>>>>>>>>>> I'd just like to say that it is a great service to the community
>>>>>>>>>>> as a whole that someone is seriously looking at improving logging.
>>>>>>>>>>>
>>>>>>>>>>> If you keep it up you'll be putting folks like me out of a job :)
>>>>>>>>>>>
>>>>>>>>>>> Martin...
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> On 17 May 2016 at 18:13, Remko Popma <re...@gmail.com> wrote:
>>>>>>>>>>>
>>>>>>>>>>>> Hi all,
>>>>>>>>>>>>
>>>>>>>>>>>> First, my thanks to the many people who gave helpful advice and
>>>>>>>>>>>> feedback on how to measure Log4j response time on this list some time ago.
>>>>>>>>>>>>
>>>>>>>>>>>> We're about to start the Log4j 2.6 release.
>>>>>>>>>>>> If anyone is interested, a preview of the garbage-free logging
>>>>>>>>>>>> manual page is here:
>>>>>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>>>>>>>>>>>> and a preview of the updated performance page is here:
>>>>>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>>>>>>>>>
>>>>>>>>>>>> Feedback welcome!
>>>>>>>>>>>>
>>>>>>>>>>>> Remko
>>>>>>>>>>>>
>>>>>>>>>>>> --
>>>>>>>>>>>> You received this message because you are subscribed to the
>>>>>>>>>>>> Google Groups "mechanical-sympathy" group.
>>>>>>>>>>>> To unsubscribe from this group and stop receiving emails from
>>>>>>>>>>>> it, send an email to
>>>>>>>>>>>> mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> --
>>>>>>>>>>> You received this message because you are subscribed to the
>>>>>>>>>>> Google Groups "mechanical-sympathy" group.
>>>>>>>>>>> To unsubscribe from this group and stop receiving emails from
>>>>>>>>>>> it, send an email to
>>>>>>>>>>> mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>> --
>>>>> You received this message because you are subscribed to the Google
>>>>> Groups "mechanical-sympathy" group.
>>>>> To unsubscribe from this group and stop receiving emails from it, send
>>>>> an email to mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>
>>>>
>>>>
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>> <javascript:_e(%7B%7D,'cvml','log4j-dev-unsubscribe@logging.apache.org');>
>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>> <javascript:_e(%7B%7D,'cvml','log4j-dev-help@logging.apache.org');>
>>
>
>
>
> --
> [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.
>
Re: Garbage-free Log4j docs preview
Posted by Mikael Ståldal <mi...@magine.com>.
Can the support for Intel TSX in Java 8u20 be relevant here?
https://bugs.openjdk.java.net/browse/JDK-8031320
On Sun, May 22, 2016 at 5:40 PM, Remko Popma <re...@gmail.com> wrote:
>
>
> On Sunday, May 22, 2016 at 11:08:37 PM UTC+9, Benedict Elliott Smith wrote:
>>
>> It's possible I'm missing some other aspect that insulates the
>> application thread from the disruptor, but from your message it seems to me
>> that you fall into the all-too-common category of people who do not fully
>> understand the semantics of the disruptor. Application threads (i.e.
>> disruptor producers) very much *are* affected by the wait strategy.
>> Under normal use, *if the disruptor consumer thread is employing a
>> blocking strategy, there will be futex call to unblock it when work is
>> provided*. i.e. whenever the queue transitions from empty to non-empty,
>> i.e. for most messages with low-to-medium logging rates.
>>
>> In this situation the enqueueing of a message is also* not lock free*,
>> as while futexes can in theory be lock-free, the JVM uses a lock to
>> synchronise access to the semaphore that controls its runnable state, so
>> all threads attempting to wake it up concurrently will compete for this
>> lock.
>>
>
> Well... Looks like you were right and I was wrong.
>
> Interesting. Apart from the dent in my pride here, this is actually good
> news. It means we can do better!
>
> So in the worst-case scenario Async Loggers/Disruptor with the blocking
> wait strategy give performance equivalent to AsyncAppender with a
> BlockingArrayQueue. We can expect Async Loggers with Disruptor to
> outperform AsyncAppender with BlockingArrayQueue when workloads are high or
> bursts of work keep the background thread busy for some time. At least this
> is my understanding now. Or did I miss something and are there cases where
> Async Loggers with Disruptor will perform worse than AsyncAppender with
> BlockingArrayQueue?
>
> In terms of how to improve, short-term we should probably look at using
> the PhasedBackoffWaitStrategy as the default, although there will always be
> workloads that "miss the window". The trade-off is increased CPU. We need
> to tread carefully here because users reporting high CPU is why we changed
> from the sleeping wait strategy to blocking. (The default in Log4j 2.6 will
> be timeout blocking wait to deal with a deadlock issue in Solaris.)
>
> Long-term we should probably explore other data structures.
>
> Exciting times. Thanks for correcting me!
>
>
>>
>> On 22 May 2016 at 15:07, Benedict Elliott Smith <be...@apache.org>
>> wrote:
>>
>>> It's possible I'm missing some other aspect that insulates the
>>> application thread from the disruptor, but from your message it seems to me
>>> that you fall into the all-too-common category of people who do not fully
>>> understand the semantics of the disruptor. Application threads (i.e.
>>> disruptor producers) very much *are* affected by the wait strategy.
>>> Under normal use, *if the disruptor consumer thread is employing a
>>> blocking strategy, there will be futex call to unblock it when work is
>>> provided*. i.e. whenever the queue transitions from empty to
>>> non-empty, i.e. for most messages with low-to-medium logging rates.
>>>
>>> In this situation the enqueueing of a message is also* not lock free*,
>>> as while futexes can in theory be lock-free, the JVM uses a lock to
>>> synchronise access to the semaphore that controls its runnable state, so
>>> all threads attempting to wake it up concurrently will compete for this
>>> lock.
>>>
>>>
>>>
>>> On 22 May 2016 at 14:42, Remko Popma <re...@gmail.com> wrote:
>>>
>>>>
>>>>
>>>> On Sunday, May 22, 2016 at 6:34:13 PM UTC+9, Benedict Elliott Smith
>>>> wrote:
>>>>>
>>>>> Hi Remko,
>>>>>
>>>>> I realise that I was looking at the old log4j code without realising
>>>>> it, in which there is always a futex involved.
>>>>>
>>>> Which class is this? Async Loggers in Log4j 2 have always been
>>>> lock-free. What may be confusing is that Log4j 2 also has an Async
>>>> *Appender*, which does not use the Disruptor but uses a JDK
>>>> BlockingArrayQueue. This appender is very similar to how Logback and Log4j
>>>> 1 do asynchronous logging. Async*Appender* (in Log4j 2, Log4j 1 and
>>>> Logback, they all use a blocking queue) is sensitive to lock contention and
>>>> does not scale with more threads.
>>>>
>>>>
>>>>>
>>>>> However the behaviour of the disruptor that backs the new code will
>>>>> depend on the wait strategy employed (and I'll note your default is a
>>>>> blocking strategy, for which my prior statement holds*).
>>>>>
>>>> Perhaps the key misunderstanding is here. I think I did not explain it
>>>> well in my previous message. Let me try again.
>>>>
>>>> Async Loggers use the Disruptor and are lock-free. This means that
>>>> multiple application threads can log concurrently and are not blocked by
>>>> each other. This is true for very low workloads, medium workloads and high
>>>> workloads.
>>>>
>>>> Only if an application logs messages at a very high rate for a long
>>>> period of time, or uses a slow appender, the Disruptor ringbuffer can fill
>>>> up and application threads will have to wait until a slot in the ringbuffer
>>>> becomes available. For the 2.6 release I have added text to the
>>>> Trade-offs section
>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Trade-offs>
>>>> to explain this last point, based on your feedback.
>>>>
>>>> Note that the Disruptor wait strategy is irrelevant to all this.
>>>> Application threads are *not *impacted by the wait strategy.
>>>>
>>>>
>>>>> Here we obviously get into the territory of people needing to
>>>>> understand the disruptor as well as your logging framework, but since you
>>>>> have a whole section labelled "Trade-offs" in which you draw attention to
>>>>> the improved throughput and latency profile under "Benefits," under
>>>>> "Drawbacks" it might be nice to mention these possible confounders. Or at
>>>>> least raise a bat signal to go and understand the tradeoffs for the
>>>>> disruptor (which is also regrettably poorly understood).
>>>>>
>>>>> It might also be helpful to explicitly call out the configuration used
>>>>> for your benchmarks,
>>>>>
>>>> Tests on the 2.6 performance page
>>>> <http://home.apache.org/~rpopma/log4j/2.6/performance.html> are mostly
>>>> done with JMH benchmarks where parameters are in the javadoc.
>>>> Tests on the Async Loggers page are partly with the new ResponseTimeTest
>>>>
>>>> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java>class
>>>> (params in the doc
>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Latency>)
>>>> and partly still shows results from the older PerfTestDriver
>>>> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTestDriver.java>
>>>> class. This last one has parameters in the code. You'll need to spend some
>>>> time to get familiar with it if you want to run it.
>>>>
>>>> and perhaps to run a comparison against some real software - github
>>>>> does not lack for applications using log4j! Unfortunately I bet this would
>>>>> result in a much less sexy graph.
>>>>>
>>>> Log4j 2 has had lock-free Async Loggers from its 2.0-beta5 release
>>>> <http://logging.apache.org/log4j/2.x/changes-report.html#a2.0-beta5>,
>>>> three years ago. If there are any serious performance drawbacks like you
>>>> seem to think there are I hope I would have heard of them. Fortunately the
>>>> opposite is true. People report very positive experiences
>>>> <http://tech.finn.no/2014/07/01/log4j2-in-production-making-it-fly/>.
>>>> People who did their own measurements reported it makes their logging as
>>>> fast as if it was switched off
>>>> <http://blogs.mulesoft.com/dev/mule-dev/mule-3-6-asynchronous-logging/>
>>>> .
>>>>
>>>>
>>>>> Finally, I really think people should (in your wiki page) explicitly
>>>>> be *discouraged* from using this part of your framework *unless they
>>>>> know they need it*. It's a fantastic piece of work for people who
>>>>> *do* need it.
>>>>>
>>>> Again, I think you are laboring under a misapprehension. I cannot
>>>> imagine a scenario where lock-free logging would be a bad thing. If you
>>>> think there is, please show evidence.
>>>>
>>>>
>>>>> But 99.99% of people would be better off with a logger that just
>>>>> avoids blocking threads when one is already in the process of logging.
>>>>>
>>>> Avoiding blocking is exactly what the Async Loggers are for. (So I
>>>> really think there is some misunderstanding somewhere.)
>>>> Based on your feedback, I've updated
>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html> the side
>>>> nav menu and page title for the 2.6 release to clarify that Async Loggers
>>>> are lock-free. I hope this will help avoid misunderstandings.
>>>>
>>>>
>>>>>
>>>>> (*It looks like you silently ignore misconfiguration, and default to
>>>>> timeout wait strategy also, which is probably going to surprise some people)
>>>>>
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> On 19 May 2016 at 00:34, Remko Popma <re...@gmail.com> wrote:
>>>>>
>>>>>> Benedict, thanks for your feedback!
>>>>>>
>>>>>> With regards to filtering, global filters are already considered
>>>>>> before the event is enqueued. Filters configured on the Logger and
>>>>>> AppenderRef are applied prior to enqueueing with mixed Sync/Async
>>>>>> <http://logging.apache.org/log4j/2.x/manual/async.html#MixedSync-Async>
>>>>>> Loggers but when all loggers are async
>>>>>> <http://logging.apache.org/log4j/2.x/manual/async.html#AllAsync>
>>>>>> these filters are applied by the background thread. We can probably improve
>>>>>> this, thanks for the suggestion!
>>>>>>
>>>>>> Your suggestion to run performance tests under lower loads is
>>>>>> reasonable and we will look at this for a future release.
>>>>>> I did experiment with this a little a while back and did see larger
>>>>>> response time pauses. Perhaps others with more experience can chime in.
>>>>>>
>>>>>> My understanding of how the Disruptor works is that enqueueing the
>>>>>> event is lock-free, so applications threads doing the logging should not
>>>>>> experience any context switches or suffer latency from Futex calls caused
>>>>>> by logging (regardless of the workload). The background thread is another
>>>>>> story. Under moderate to low workloads the background thread may (depending
>>>>>> on the wait policy) fall asleep and experience delays before waking up when
>>>>>> work arrives. However, if there are enough cores to serve all threads I
>>>>>> don't see how such background thread delays can impact (cause response time
>>>>>> pauses for) the application that is doing the logging. Please correct me if
>>>>>> my understanding is incorrect.
>>>>>>
>>>>>> My thinking is that using async loggers is good for reactive
>>>>>> applications that need to respond quickly to external events. It is
>>>>>> especially useful if the application needs to deal with occasional bursts
>>>>>> of work (and accompanied bursts of logging). This is where async loggers
>>>>>> can deliver value even if the normal workload is low.
>>>>>>
>>>>>> Remko
>>>>>>
>>>>>> On Wednesday, May 18, 2016 at 2:56:18 AM UTC+9, Benedict Elliott
>>>>>> Smith wrote:
>>>>>>>
>>>>>>> Regrettably it seems impossible (or at least very annoying) to send
>>>>>>> to both lists simultaneously...
>>>>>>>
>>>>>>> On 17 May 2016 at 18:55, Benedict Elliott Smith <be...@apache.org>
>>>>>>> wrote:
>>>>>>>
>>>>>>>> Could I suggest that you run tests for latency and throughput
>>>>>>>> effects of using this in systems with only moderate-to-low numbers of
>>>>>>>> logging calls? (i.e. the vast majority of systems!)
>>>>>>>>
>>>>>>>
>>>>>>>> It's very likely that in such systems messages will not reach a
>>>>>>>> velocity to keep the Dispatcher running, and so logging calls may often (or
>>>>>>>> always) involve a Futex call - which is not a trivial cost. There will
>>>>>>>> almost certainly be systems out there with anti-ideal characteristics -
>>>>>>>> logging just often enough that these costs materially impact throughput,
>>>>>>>> but not often enough that they suddenly disappear.
>>>>>>>>
>>>>>>>> Even though a majority of systems *do not need this*, because it
>>>>>>>> "async" and the new hotness, and there are no advertised downsides,
>>>>>>>> everyone will try to use it. It's up to those who know better to make sure
>>>>>>>> these people are informed it isn't a free lunch. Making sure all of the
>>>>>>>> caveats are reported on the advertising page would be a great start IMO.
>>>>>>>>
>>>>>>>> Might I also separately suggest you consider filtering events prior
>>>>>>>> to placing them on the queue for processing by the dispatcher? I've only
>>>>>>>> briefly glanced at the code, but it seems not to be the case currently.
>>>>>>>>
>>>>>>>>>
>>>>>>>>> On 17 May 2016 at 18:33, Martin Thompson <mj...@gmail.com> wrote:
>>>>>>>>>
>>>>>>>>>> Hi Remko,
>>>>>>>>>>
>>>>>>>>>> I'd just like to say that it is a great service to the community
>>>>>>>>>> as a whole that someone is seriously looking at improving logging.
>>>>>>>>>>
>>>>>>>>>> If you keep it up you'll be putting folks like me out of a job :)
>>>>>>>>>>
>>>>>>>>>> Martin...
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> On 17 May 2016 at 18:13, Remko Popma <re...@gmail.com> wrote:
>>>>>>>>>>
>>>>>>>>>>> Hi all,
>>>>>>>>>>>
>>>>>>>>>>> First, my thanks to the many people who gave helpful advice and
>>>>>>>>>>> feedback on how to measure Log4j response time on this list some time ago.
>>>>>>>>>>>
>>>>>>>>>>> We're about to start the Log4j 2.6 release.
>>>>>>>>>>> If anyone is interested, a preview of the garbage-free logging
>>>>>>>>>>> manual page is here:
>>>>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>>>>>>>>>>> and a preview of the updated performance page is here:
>>>>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>>>>>>>>
>>>>>>>>>>> Feedback welcome!
>>>>>>>>>>>
>>>>>>>>>>> Remko
>>>>>>>>>>>
>>>>>>>>>>> --
>>>>>>>>>>> You received this message because you are subscribed to the
>>>>>>>>>>> Google Groups "mechanical-sympathy" group.
>>>>>>>>>>> To unsubscribe from this group and stop receiving emails from
>>>>>>>>>>> it, send an email to
>>>>>>>>>>> mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> --
>>>>>>>>>> You received this message because you are subscribed to the
>>>>>>>>>> Google Groups "mechanical-sympathy" group.
>>>>>>>>>> To unsubscribe from this group and stop receiving emails from it,
>>>>>>>>>> send an email to mechanical-sympathy+unsubscribe@googlegroups.com
>>>>>>>>>> .
>>>>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>> --
>>>> You received this message because you are subscribed to the Google
>>>> Groups "mechanical-sympathy" group.
>>>> To unsubscribe from this group and stop receiving emails from it, send
>>>> an email to mechanical-sympathy+unsubscribe@googlegroups.com.
>>>> For more options, visit https://groups.google.com/d/optout.
>>>>
>>>
>>>
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
--
[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.
Re: Garbage-free Log4j docs preview
Posted by Mikael Ståldal <mi...@magine.com>.
> But I don't understand why users should only configure async logging in
rare cases? Synchronous logging also involves holding a lock. Log4j 2 makes
an effort to release this lock as soon as
> possible (locking only while copying a byte array from a thread-local
buffer to the I/O device), but as Martin pointed out, in addition to the
lock contention, other things may cause response time
> pauses when writing to the I/O device.
There is also another reason for using async logging, to protect the app
from errors and unpredictable response time from a network based appender.
However, for that the ArrayBlockingQueue based AsyncAppender is sufficient.
On Mon, May 23, 2016 at 2:38 PM, Remko Popma <re...@gmail.com> wrote:
>
>
> On Monday, May 23, 2016 at 2:47:05 AM UTC+9, Benedict Elliott Smith wrote:
>>
>> Your pride should be saved by your gracious recognition of the error :)
>>
>>
>> However this is the core of my point: you’re clearly an intelligent,
>> conscientious and talented developer, and yet you did not fully understand
>> these concerns. You are writing core infrastructure many people will
>> deploy, and a majority will understand it much much less well. So the very
>> best thing you can do is to educate them. Doubly so if you needed
>> educating yourself!
>>
> ;-)
>
>>
>> I would make it very clear that users should only consider asynchronous
>> logging if they are having performance problems caused by their logging.
>> Only with sub-millisecond latency requirements should async be considered,
>> and below 100 micros you are entering busy-spinning territory. Or if huge
>> message rates are being seen. The best default is a blocking strategy, as
>> this has the closest performance profile to synchronous, and will prevent
>> the many users who deploy this without needing it from suffering any major
>> ill-effect.
>>
> I think I missed a step here. You made it plausible that under low
> workload, the Disruptor may not be better than ArrayBlockingQueue.
> Understood.
>
> But I don't understand why users should only configure async logging in
> rare cases? Synchronous logging also involves holding a lock. Log4j 2 makes
> an effort to release this lock as soon as possible (locking only while
> copying a byte array from a thread-local buffer to the I/O device), but as
> Martin pointed out, in addition to the lock contention, other things may
> cause response time pauses when writing to the I/O device.
>
> So which is "better": holding a lock to signal a
> java.util.concurrent.locks.Condition, versus holding a lock to write a byte
> array to the I/O device? The latter sounds like it has more risk of latency
> spikes. So I'm not sure I agree with your assessment that async logging has
> more risk of major ill effects.
>
> Under low loads the upside of Async Loggers may not be as high as the
> graph suggests but I don't see any real downsides either. Please let me
> know if I'm missing something.
>
>
>>
>> I would also do a performance comparison with a real application.
>> Cassandra uses log4j, and the community has an easily utilised performance
>> tool. You could try both DEBUG and INFO level, and put up some graphs.
>> This would help users make a more realistic and informed decision.
>>
> I agree it may be interesting for users to see a case study of some sort
> with a real application. Can you point me to the tool you are referring to?
>
>
>>
>> This may all seem a little disappointing: to *reduce* the number of
>> people who might use your amazing new technology. But there will be
>> plenty, who both need it and do not and don't read or heed the warnings.
>>
> That's okay. It is garbage-free logging that is new in the 2.6 release,
> not the Async Loggers. The Disruptor-based Async Loggers have been used in
> the wild for about three years now. The response has generally been
> positive so I'm not panicking just yet.
> I do intend to follow up though and I take your point that under low load
> this technology may not give as much benefit as under high load. (Again,
> please correct me if there is a bigger problem and I'm missing any other
> downsides/risks.)
>
>
>>
>> Regarding improvements: In my opinion, a better algorithm for this
>> majority, of low-to-moderate traffic that is not extremely latency
>> sensitive, is semi-synchronous. By which I mean for the first log call in
>> a batch to take exclusive ownership of the output and to write its message
>> synchronously; any messages that arrive while it has ownership are passed
>> to the owner to persist, i.e. they are written asynchronously. To ensure
>> any thread’s ownership is brief, it would impose a time-limit, after which
>> a dedicated consumer could be started if the queue is still not exhausted.
>> This would have better than synchronous behaviour for low-to-moderate
>> traffic and scale gracefully to high traffic.
>>
> This is really interesting. It reminds me of one of the co-operative
> algorithms I read about in the Art of Multiprocessor Programming (I tried
> to look it up but could not find it last night).
>
> It may be an idea to enhance the Disruptor for lower workloads: I guess
> the question is whether it is possible to incorporate a cheap check before
> calling waitStrategy.signalAllWhenBlocking() in MultiProducerSequence, and
> avoid calling that method if another thread is already signalling the
> consumer thread.
> ...and it turns out this already exists and is called
> LiteBlockingWaitStrategy. Good stuff! Perhaps all that is needed is combine
> the TimeoutBlockingWaitStrategy with this one and we can improve things
> nicely for lower workloads.
>
> Does anyone on this list have any experience with
> LiteBlockingWaitStrategy? I see it was used in projectreactor.io, would
> be interested to hear how that worked, either on list of off-list.
>
>>
>>
>> On Sunday, 22 May 2016 16:40:21 UTC+1, Remko Popma wrote:
>>>
>>>
>>>
>>> On Sunday, May 22, 2016 at 11:08:37 PM UTC+9, Benedict Elliott Smith
>>> wrote:
>>>>
>>>> It's possible I'm missing some other aspect that insulates the
>>>> application thread from the disruptor, but from your message it seems to me
>>>> that you fall into the all-too-common category of people who do not fully
>>>> understand the semantics of the disruptor. Application threads (i.e.
>>>> disruptor producers) very much *are* affected by the wait strategy.
>>>> Under normal use, *if the disruptor consumer thread is employing a
>>>> blocking strategy, there will be futex call to unblock it when work is
>>>> provided*. i.e. whenever the queue transitions from empty to
>>>> non-empty, i.e. for most messages with low-to-medium logging rates.
>>>>
>>>> In this situation the enqueueing of a message is also* not lock free*,
>>>> as while futexes can in theory be lock-free, the JVM uses a lock to
>>>> synchronise access to the semaphore that controls its runnable state, so
>>>> all threads attempting to wake it up concurrently will compete for this
>>>> lock.
>>>>
>>>
>>> Well... Looks like you were right and I was wrong.
>>>
>>> Interesting. Apart from the dent in my pride here, this is actually good
>>> news. It means we can do better!
>>>
>>> So in the worst-case scenario Async Loggers/Disruptor with the blocking
>>> wait strategy give performance equivalent to AsyncAppender with a
>>> BlockingArrayQueue. We can expect Async Loggers with Disruptor to
>>> outperform AsyncAppender with BlockingArrayQueue when workloads are high or
>>> bursts of work keep the background thread busy for some time. At least this
>>> is my understanding now. Or did I miss something and are there cases where
>>> Async Loggers with Disruptor will perform worse than AsyncAppender with
>>> BlockingArrayQueue?
>>>
>>> In terms of how to improve, short-term we should probably look at using
>>> the PhasedBackoffWaitStrategy as the default, although there will always be
>>> workloads that "miss the window". The trade-off is increased CPU. We need
>>> to tread carefully here because users reporting high CPU is why we changed
>>> from the sleeping wait strategy to blocking. (The default in Log4j 2.6 will
>>> be timeout blocking wait to deal with a deadlock issue in Solaris.)
>>>
>>> Long-term we should probably explore other data structures.
>>>
>>> Exciting times. Thanks for correcting me!
>>>
>>>
>>>>
>>>> On 22 May 2016 at 15:07, Benedict Elliott Smith <be...@apache.org>
>>>> wrote:
>>>>
>>>>> It's possible I'm missing some other aspect that insulates the
>>>>> application thread from the disruptor, but from your message it seems to me
>>>>> that you fall into the all-too-common category of people who do not fully
>>>>> understand the semantics of the disruptor. Application threads (i.e.
>>>>> disruptor producers) very much *are* affected by the wait strategy.
>>>>> Under normal use, *if the disruptor consumer thread is employing a
>>>>> blocking strategy, there will be futex call to unblock it when work is
>>>>> provided*. i.e. whenever the queue transitions from empty to
>>>>> non-empty, i.e. for most messages with low-to-medium logging rates.
>>>>>
>>>>> In this situation the enqueueing of a message is also* not lock free*,
>>>>> as while futexes can in theory be lock-free, the JVM uses a lock to
>>>>> synchronise access to the semaphore that controls its runnable state, so
>>>>> all threads attempting to wake it up concurrently will compete for this
>>>>> lock.
>>>>>
>>>>>
>>>>>
>>>>> On 22 May 2016 at 14:42, Remko Popma <re...@gmail.com> wrote:
>>>>>
>>>>>>
>>>>>>
>>>>>> On Sunday, May 22, 2016 at 6:34:13 PM UTC+9, Benedict Elliott Smith
>>>>>> wrote:
>>>>>>>
>>>>>>> Hi Remko,
>>>>>>>
>>>>>>> I realise that I was looking at the old log4j code without realising
>>>>>>> it, in which there is always a futex involved.
>>>>>>>
>>>>>> Which class is this? Async Loggers in Log4j 2 have always been
>>>>>> lock-free. What may be confusing is that Log4j 2 also has an Async
>>>>>> *Appender*, which does not use the Disruptor but uses a JDK
>>>>>> BlockingArrayQueue. This appender is very similar to how Logback and Log4j
>>>>>> 1 do asynchronous logging. Async*Appender* (in Log4j 2, Log4j 1 and
>>>>>> Logback, they all use a blocking queue) is sensitive to lock contention and
>>>>>> does not scale with more threads.
>>>>>>
>>>>>>
>>>>>>>
>>>>>>> However the behaviour of the disruptor that backs the new code will
>>>>>>> depend on the wait strategy employed (and I'll note your default is a
>>>>>>> blocking strategy, for which my prior statement holds*).
>>>>>>>
>>>>>> Perhaps the key misunderstanding is here. I think I did not explain
>>>>>> it well in my previous message. Let me try again.
>>>>>>
>>>>>> Async Loggers use the Disruptor and are lock-free. This means that
>>>>>> multiple application threads can log concurrently and are not blocked by
>>>>>> each other. This is true for very low workloads, medium workloads and high
>>>>>> workloads.
>>>>>>
>>>>>> Only if an application logs messages at a very high rate for a long
>>>>>> period of time, or uses a slow appender, the Disruptor ringbuffer can fill
>>>>>> up and application threads will have to wait until a slot in the ringbuffer
>>>>>> becomes available. For the 2.6 release I have added text to the
>>>>>> Trade-offs section
>>>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Trade-offs>
>>>>>> to explain this last point, based on your feedback.
>>>>>>
>>>>>> Note that the Disruptor wait strategy is irrelevant to all this.
>>>>>> Application threads are *not *impacted by the wait strategy.
>>>>>>
>>>>>>
>>>>>>> Here we obviously get into the territory of people needing to
>>>>>>> understand the disruptor as well as your logging framework, but since you
>>>>>>> have a whole section labelled "Trade-offs" in which you draw attention to
>>>>>>> the improved throughput and latency profile under "Benefits," under
>>>>>>> "Drawbacks" it might be nice to mention these possible confounders. Or at
>>>>>>> least raise a bat signal to go and understand the tradeoffs for the
>>>>>>> disruptor (which is also regrettably poorly understood).
>>>>>>>
>>>>>>> It might also be helpful to explicitly call out the configuration
>>>>>>> used for your benchmarks,
>>>>>>>
>>>>>> Tests on the 2.6 performance page
>>>>>> <http://home.apache.org/~rpopma/log4j/2.6/performance.html> are
>>>>>> mostly done with JMH benchmarks where parameters are in the javadoc.
>>>>>> Tests on the Async Loggers page are partly with the new ResponseTimeTest
>>>>>>
>>>>>> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java>class
>>>>>> (params in the doc
>>>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Latency>)
>>>>>> and partly still shows results from the older PerfTestDriver
>>>>>> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTestDriver.java>
>>>>>> class. This last one has parameters in the code. You'll need to spend some
>>>>>> time to get familiar with it if you want to run it.
>>>>>>
>>>>>> and perhaps to run a comparison against some real software - github
>>>>>>> does not lack for applications using log4j! Unfortunately I bet this would
>>>>>>> result in a much less sexy graph.
>>>>>>>
>>>>>> Log4j 2 has had lock-free Async Loggers from its 2.0-beta5 release
>>>>>> <http://logging.apache.org/log4j/2.x/changes-report.html#a2.0-beta5>,
>>>>>> three years ago. If there are any serious performance drawbacks like you
>>>>>> seem to think there are I hope I would have heard of them. Fortunately the
>>>>>> opposite is true. People report very positive experiences
>>>>>> <http://tech.finn.no/2014/07/01/log4j2-in-production-making-it-fly/>.
>>>>>> People who did their own measurements reported it makes their logging as
>>>>>> fast as if it was switched off
>>>>>> <http://blogs.mulesoft.com/dev/mule-dev/mule-3-6-asynchronous-logging/>
>>>>>> .
>>>>>>
>>>>>>
>>>>>>> Finally, I really think people should (in your wiki page) explicitly
>>>>>>> be *discouraged* from using this part of your framework *unless
>>>>>>> they know they need it*. It's a fantastic piece of work for people
>>>>>>> who *do* need it.
>>>>>>>
>>>>>> Again, I think you are laboring under a misapprehension. I cannot
>>>>>> imagine a scenario where lock-free logging would be a bad thing. If you
>>>>>> think there is, please show evidence.
>>>>>>
>>>>>>
>>>>>>> But 99.99% of people would be better off with a logger that just
>>>>>>> avoids blocking threads when one is already in the process of logging.
>>>>>>>
>>>>>> Avoiding blocking is exactly what the Async Loggers are for. (So I
>>>>>> really think there is some misunderstanding somewhere.)
>>>>>> Based on your feedback, I've updated
>>>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html> the
>>>>>> side nav menu and page title for the 2.6 release to clarify that Async
>>>>>> Loggers are lock-free. I hope this will help avoid misunderstandings.
>>>>>>
>>>>>>
>>>>>>>
>>>>>>> (*It looks like you silently ignore misconfiguration, and default to
>>>>>>> timeout wait strategy also, which is probably going to surprise some people)
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> On 19 May 2016 at 00:34, Remko Popma <re...@gmail.com> wrote:
>>>>>>>
>>>>>>>> Benedict, thanks for your feedback!
>>>>>>>>
>>>>>>>> With regards to filtering, global filters are already considered
>>>>>>>> before the event is enqueued. Filters configured on the Logger and
>>>>>>>> AppenderRef are applied prior to enqueueing with mixed Sync/Async
>>>>>>>> <http://logging.apache.org/log4j/2.x/manual/async.html#MixedSync-Async>
>>>>>>>> Loggers but when all loggers are async
>>>>>>>> <http://logging.apache.org/log4j/2.x/manual/async.html#AllAsync>
>>>>>>>> these filters are applied by the background thread. We can probably improve
>>>>>>>> this, thanks for the suggestion!
>>>>>>>>
>>>>>>>> Your suggestion to run performance tests under lower loads is
>>>>>>>> reasonable and we will look at this for a future release.
>>>>>>>> I did experiment with this a little a while back and did see larger
>>>>>>>> response time pauses. Perhaps others with more experience can chime in.
>>>>>>>>
>>>>>>>> My understanding of how the Disruptor works is that enqueueing the
>>>>>>>> event is lock-free, so applications threads doing the logging should not
>>>>>>>> experience any context switches or suffer latency from Futex calls caused
>>>>>>>> by logging (regardless of the workload). The background thread is another
>>>>>>>> story. Under moderate to low workloads the background thread may (depending
>>>>>>>> on the wait policy) fall asleep and experience delays before waking up when
>>>>>>>> work arrives. However, if there are enough cores to serve all threads I
>>>>>>>> don't see how such background thread delays can impact (cause response time
>>>>>>>> pauses for) the application that is doing the logging. Please correct me if
>>>>>>>> my understanding is incorrect.
>>>>>>>>
>>>>>>>> My thinking is that using async loggers is good for reactive
>>>>>>>> applications that need to respond quickly to external events. It is
>>>>>>>> especially useful if the application needs to deal with occasional bursts
>>>>>>>> of work (and accompanied bursts of logging). This is where async loggers
>>>>>>>> can deliver value even if the normal workload is low.
>>>>>>>>
>>>>>>>> Remko
>>>>>>>>
>>>>>>>> On Wednesday, May 18, 2016 at 2:56:18 AM UTC+9, Benedict Elliott
>>>>>>>> Smith wrote:
>>>>>>>>>
>>>>>>>>> Regrettably it seems impossible (or at least very annoying) to
>>>>>>>>> send to both lists simultaneously...
>>>>>>>>>
>>>>>>>>> On 17 May 2016 at 18:55, Benedict Elliott Smith <
>>>>>>>>> bene...@apache.org> wrote:
>>>>>>>>>
>>>>>>>>>> Could I suggest that you run tests for latency and throughput
>>>>>>>>>> effects of using this in systems with only moderate-to-low numbers of
>>>>>>>>>> logging calls? (i.e. the vast majority of systems!)
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>>> It's very likely that in such systems messages will not reach a
>>>>>>>>>> velocity to keep the Dispatcher running, and so logging calls may often (or
>>>>>>>>>> always) involve a Futex call - which is not a trivial cost. There will
>>>>>>>>>> almost certainly be systems out there with anti-ideal characteristics -
>>>>>>>>>> logging just often enough that these costs materially impact throughput,
>>>>>>>>>> but not often enough that they suddenly disappear.
>>>>>>>>>>
>>>>>>>>>> Even though a majority of systems *do not need this*, because it
>>>>>>>>>> "async" and the new hotness, and there are no advertised downsides,
>>>>>>>>>> everyone will try to use it. It's up to those who know better to make sure
>>>>>>>>>> these people are informed it isn't a free lunch. Making sure all of the
>>>>>>>>>> caveats are reported on the advertising page would be a great start IMO.
>>>>>>>>>>
>>>>>>>>>> Might I also separately suggest you consider filtering events
>>>>>>>>>> prior to placing them on the queue for processing by the dispatcher? I've
>>>>>>>>>> only briefly glanced at the code, but it seems not to be the case currently.
>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> On 17 May 2016 at 18:33, Martin Thompson <mj...@gmail.com>
>>>>>>>>>>> wrote:
>>>>>>>>>>>
>>>>>>>>>>>> Hi Remko,
>>>>>>>>>>>>
>>>>>>>>>>>> I'd just like to say that it is a great service to the
>>>>>>>>>>>> community as a whole that someone is seriously looking at improving logging.
>>>>>>>>>>>>
>>>>>>>>>>>> If you keep it up you'll be putting folks like me out of a job
>>>>>>>>>>>> :)
>>>>>>>>>>>>
>>>>>>>>>>>> Martin...
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> On 17 May 2016 at 18:13, Remko Popma <re...@gmail.com>
>>>>>>>>>>>> wrote:
>>>>>>>>>>>>
>>>>>>>>>>>>> Hi all,
>>>>>>>>>>>>>
>>>>>>>>>>>>> First, my thanks to the many people who gave helpful advice
>>>>>>>>>>>>> and feedback on how to measure Log4j response time on this list some time
>>>>>>>>>>>>> ago.
>>>>>>>>>>>>>
>>>>>>>>>>>>> We're about to start the Log4j 2.6 release.
>>>>>>>>>>>>> If anyone is interested, a preview of the garbage-free logging
>>>>>>>>>>>>> manual page is here:
>>>>>>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>>>>>>>>>>>>> and a preview of the updated performance page is here:
>>>>>>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>>>>>>>>>>
>>>>>>>>>>>>> Feedback welcome!
>>>>>>>>>>>>>
>>>>>>>>>>>>> Remko
>>>>>>>>>>>>>
>>>>>>>>>>>>> --
>>>>>>>>>>>>> You received this message because you are subscribed to the
>>>>>>>>>>>>> Google Groups "mechanical-sympathy" group.
>>>>>>>>>>>>> To unsubscribe from this group and stop receiving emails from
>>>>>>>>>>>>> it, send an email to
>>>>>>>>>>>>> mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> --
>>>>>>>>>>>> You received this message because you are subscribed to the
>>>>>>>>>>>> Google Groups "mechanical-sympathy" group.
>>>>>>>>>>>> To unsubscribe from this group and stop receiving emails from
>>>>>>>>>>>> it, send an email to
>>>>>>>>>>>> mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>
>>>>>>> --
>>>>>> You received this message because you are subscribed to the Google
>>>>>> Groups "mechanical-sympathy" group.
>>>>>> To unsubscribe from this group and stop receiving emails from it,
>>>>>> send an email to mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>
>>>>>
>>>>>
>>>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
--
[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.
Re: Garbage-free Log4j docs preview
Posted by Mikael Ståldal <mi...@magine.com>.
> But I don't understand why users should only configure async logging in
rare cases? Synchronous logging also involves holding a lock. Log4j 2 makes
an effort to release this lock as soon as
> possible (locking only while copying a byte array from a thread-local
buffer to the I/O device), but as Martin pointed out, in addition to the
lock contention, other things may cause response time
> pauses when writing to the I/O device.
There is also another reason for using async logging, to protect the app
from errors and unpredictable response time from a network based appender.
However, for that the ArrayBlockingQueue based AsyncAppender is sufficient.
On Mon, May 23, 2016 at 2:38 PM, Remko Popma <re...@gmail.com> wrote:
>
>
> On Monday, May 23, 2016 at 2:47:05 AM UTC+9, Benedict Elliott Smith wrote:
>>
>> Your pride should be saved by your gracious recognition of the error :)
>>
>>
>> However this is the core of my point: you’re clearly an intelligent,
>> conscientious and talented developer, and yet you did not fully understand
>> these concerns. You are writing core infrastructure many people will
>> deploy, and a majority will understand it much much less well. So the very
>> best thing you can do is to educate them. Doubly so if you needed
>> educating yourself!
>>
> ;-)
>
>>
>> I would make it very clear that users should only consider asynchronous
>> logging if they are having performance problems caused by their logging.
>> Only with sub-millisecond latency requirements should async be considered,
>> and below 100 micros you are entering busy-spinning territory. Or if huge
>> message rates are being seen. The best default is a blocking strategy, as
>> this has the closest performance profile to synchronous, and will prevent
>> the many users who deploy this without needing it from suffering any major
>> ill-effect.
>>
> I think I missed a step here. You made it plausible that under low
> workload, the Disruptor may not be better than ArrayBlockingQueue.
> Understood.
>
> But I don't understand why users should only configure async logging in
> rare cases? Synchronous logging also involves holding a lock. Log4j 2 makes
> an effort to release this lock as soon as possible (locking only while
> copying a byte array from a thread-local buffer to the I/O device), but as
> Martin pointed out, in addition to the lock contention, other things may
> cause response time pauses when writing to the I/O device.
>
> So which is "better": holding a lock to signal a
> java.util.concurrent.locks.Condition, versus holding a lock to write a byte
> array to the I/O device? The latter sounds like it has more risk of latency
> spikes. So I'm not sure I agree with your assessment that async logging has
> more risk of major ill effects.
>
> Under low loads the upside of Async Loggers may not be as high as the
> graph suggests but I don't see any real downsides either. Please let me
> know if I'm missing something.
>
>
>>
>> I would also do a performance comparison with a real application.
>> Cassandra uses log4j, and the community has an easily utilised performance
>> tool. You could try both DEBUG and INFO level, and put up some graphs.
>> This would help users make a more realistic and informed decision.
>>
> I agree it may be interesting for users to see a case study of some sort
> with a real application. Can you point me to the tool you are referring to?
>
>
>>
>> This may all seem a little disappointing: to *reduce* the number of
>> people who might use your amazing new technology. But there will be
>> plenty, who both need it and do not and don't read or heed the warnings.
>>
> That's okay. It is garbage-free logging that is new in the 2.6 release,
> not the Async Loggers. The Disruptor-based Async Loggers have been used in
> the wild for about three years now. The response has generally been
> positive so I'm not panicking just yet.
> I do intend to follow up though and I take your point that under low load
> this technology may not give as much benefit as under high load. (Again,
> please correct me if there is a bigger problem and I'm missing any other
> downsides/risks.)
>
>
>>
>> Regarding improvements: In my opinion, a better algorithm for this
>> majority, of low-to-moderate traffic that is not extremely latency
>> sensitive, is semi-synchronous. By which I mean for the first log call in
>> a batch to take exclusive ownership of the output and to write its message
>> synchronously; any messages that arrive while it has ownership are passed
>> to the owner to persist, i.e. they are written asynchronously. To ensure
>> any thread’s ownership is brief, it would impose a time-limit, after which
>> a dedicated consumer could be started if the queue is still not exhausted.
>> This would have better than synchronous behaviour for low-to-moderate
>> traffic and scale gracefully to high traffic.
>>
> This is really interesting. It reminds me of one of the co-operative
> algorithms I read about in the Art of Multiprocessor Programming (I tried
> to look it up but could not find it last night).
>
> It may be an idea to enhance the Disruptor for lower workloads: I guess
> the question is whether it is possible to incorporate a cheap check before
> calling waitStrategy.signalAllWhenBlocking() in MultiProducerSequence, and
> avoid calling that method if another thread is already signalling the
> consumer thread.
> ...and it turns out this already exists and is called
> LiteBlockingWaitStrategy. Good stuff! Perhaps all that is needed is combine
> the TimeoutBlockingWaitStrategy with this one and we can improve things
> nicely for lower workloads.
>
> Does anyone on this list have any experience with
> LiteBlockingWaitStrategy? I see it was used in projectreactor.io, would
> be interested to hear how that worked, either on list of off-list.
>
>>
>>
>> On Sunday, 22 May 2016 16:40:21 UTC+1, Remko Popma wrote:
>>>
>>>
>>>
>>> On Sunday, May 22, 2016 at 11:08:37 PM UTC+9, Benedict Elliott Smith
>>> wrote:
>>>>
>>>> It's possible I'm missing some other aspect that insulates the
>>>> application thread from the disruptor, but from your message it seems to me
>>>> that you fall into the all-too-common category of people who do not fully
>>>> understand the semantics of the disruptor. Application threads (i.e.
>>>> disruptor producers) very much *are* affected by the wait strategy.
>>>> Under normal use, *if the disruptor consumer thread is employing a
>>>> blocking strategy, there will be futex call to unblock it when work is
>>>> provided*. i.e. whenever the queue transitions from empty to
>>>> non-empty, i.e. for most messages with low-to-medium logging rates.
>>>>
>>>> In this situation the enqueueing of a message is also* not lock free*,
>>>> as while futexes can in theory be lock-free, the JVM uses a lock to
>>>> synchronise access to the semaphore that controls its runnable state, so
>>>> all threads attempting to wake it up concurrently will compete for this
>>>> lock.
>>>>
>>>
>>> Well... Looks like you were right and I was wrong.
>>>
>>> Interesting. Apart from the dent in my pride here, this is actually good
>>> news. It means we can do better!
>>>
>>> So in the worst-case scenario Async Loggers/Disruptor with the blocking
>>> wait strategy give performance equivalent to AsyncAppender with a
>>> BlockingArrayQueue. We can expect Async Loggers with Disruptor to
>>> outperform AsyncAppender with BlockingArrayQueue when workloads are high or
>>> bursts of work keep the background thread busy for some time. At least this
>>> is my understanding now. Or did I miss something and are there cases where
>>> Async Loggers with Disruptor will perform worse than AsyncAppender with
>>> BlockingArrayQueue?
>>>
>>> In terms of how to improve, short-term we should probably look at using
>>> the PhasedBackoffWaitStrategy as the default, although there will always be
>>> workloads that "miss the window". The trade-off is increased CPU. We need
>>> to tread carefully here because users reporting high CPU is why we changed
>>> from the sleeping wait strategy to blocking. (The default in Log4j 2.6 will
>>> be timeout blocking wait to deal with a deadlock issue in Solaris.)
>>>
>>> Long-term we should probably explore other data structures.
>>>
>>> Exciting times. Thanks for correcting me!
>>>
>>>
>>>>
>>>> On 22 May 2016 at 15:07, Benedict Elliott Smith <be...@apache.org>
>>>> wrote:
>>>>
>>>>> It's possible I'm missing some other aspect that insulates the
>>>>> application thread from the disruptor, but from your message it seems to me
>>>>> that you fall into the all-too-common category of people who do not fully
>>>>> understand the semantics of the disruptor. Application threads (i.e.
>>>>> disruptor producers) very much *are* affected by the wait strategy.
>>>>> Under normal use, *if the disruptor consumer thread is employing a
>>>>> blocking strategy, there will be futex call to unblock it when work is
>>>>> provided*. i.e. whenever the queue transitions from empty to
>>>>> non-empty, i.e. for most messages with low-to-medium logging rates.
>>>>>
>>>>> In this situation the enqueueing of a message is also* not lock free*,
>>>>> as while futexes can in theory be lock-free, the JVM uses a lock to
>>>>> synchronise access to the semaphore that controls its runnable state, so
>>>>> all threads attempting to wake it up concurrently will compete for this
>>>>> lock.
>>>>>
>>>>>
>>>>>
>>>>> On 22 May 2016 at 14:42, Remko Popma <re...@gmail.com> wrote:
>>>>>
>>>>>>
>>>>>>
>>>>>> On Sunday, May 22, 2016 at 6:34:13 PM UTC+9, Benedict Elliott Smith
>>>>>> wrote:
>>>>>>>
>>>>>>> Hi Remko,
>>>>>>>
>>>>>>> I realise that I was looking at the old log4j code without realising
>>>>>>> it, in which there is always a futex involved.
>>>>>>>
>>>>>> Which class is this? Async Loggers in Log4j 2 have always been
>>>>>> lock-free. What may be confusing is that Log4j 2 also has an Async
>>>>>> *Appender*, which does not use the Disruptor but uses a JDK
>>>>>> BlockingArrayQueue. This appender is very similar to how Logback and Log4j
>>>>>> 1 do asynchronous logging. Async*Appender* (in Log4j 2, Log4j 1 and
>>>>>> Logback, they all use a blocking queue) is sensitive to lock contention and
>>>>>> does not scale with more threads.
>>>>>>
>>>>>>
>>>>>>>
>>>>>>> However the behaviour of the disruptor that backs the new code will
>>>>>>> depend on the wait strategy employed (and I'll note your default is a
>>>>>>> blocking strategy, for which my prior statement holds*).
>>>>>>>
>>>>>> Perhaps the key misunderstanding is here. I think I did not explain
>>>>>> it well in my previous message. Let me try again.
>>>>>>
>>>>>> Async Loggers use the Disruptor and are lock-free. This means that
>>>>>> multiple application threads can log concurrently and are not blocked by
>>>>>> each other. This is true for very low workloads, medium workloads and high
>>>>>> workloads.
>>>>>>
>>>>>> Only if an application logs messages at a very high rate for a long
>>>>>> period of time, or uses a slow appender, the Disruptor ringbuffer can fill
>>>>>> up and application threads will have to wait until a slot in the ringbuffer
>>>>>> becomes available. For the 2.6 release I have added text to the
>>>>>> Trade-offs section
>>>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Trade-offs>
>>>>>> to explain this last point, based on your feedback.
>>>>>>
>>>>>> Note that the Disruptor wait strategy is irrelevant to all this.
>>>>>> Application threads are *not *impacted by the wait strategy.
>>>>>>
>>>>>>
>>>>>>> Here we obviously get into the territory of people needing to
>>>>>>> understand the disruptor as well as your logging framework, but since you
>>>>>>> have a whole section labelled "Trade-offs" in which you draw attention to
>>>>>>> the improved throughput and latency profile under "Benefits," under
>>>>>>> "Drawbacks" it might be nice to mention these possible confounders. Or at
>>>>>>> least raise a bat signal to go and understand the tradeoffs for the
>>>>>>> disruptor (which is also regrettably poorly understood).
>>>>>>>
>>>>>>> It might also be helpful to explicitly call out the configuration
>>>>>>> used for your benchmarks,
>>>>>>>
>>>>>> Tests on the 2.6 performance page
>>>>>> <http://home.apache.org/~rpopma/log4j/2.6/performance.html> are
>>>>>> mostly done with JMH benchmarks where parameters are in the javadoc.
>>>>>> Tests on the Async Loggers page are partly with the new ResponseTimeTest
>>>>>>
>>>>>> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java>class
>>>>>> (params in the doc
>>>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Latency>)
>>>>>> and partly still shows results from the older PerfTestDriver
>>>>>> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTestDriver.java>
>>>>>> class. This last one has parameters in the code. You'll need to spend some
>>>>>> time to get familiar with it if you want to run it.
>>>>>>
>>>>>> and perhaps to run a comparison against some real software - github
>>>>>>> does not lack for applications using log4j! Unfortunately I bet this would
>>>>>>> result in a much less sexy graph.
>>>>>>>
>>>>>> Log4j 2 has had lock-free Async Loggers from its 2.0-beta5 release
>>>>>> <http://logging.apache.org/log4j/2.x/changes-report.html#a2.0-beta5>,
>>>>>> three years ago. If there are any serious performance drawbacks like you
>>>>>> seem to think there are I hope I would have heard of them. Fortunately the
>>>>>> opposite is true. People report very positive experiences
>>>>>> <http://tech.finn.no/2014/07/01/log4j2-in-production-making-it-fly/>.
>>>>>> People who did their own measurements reported it makes their logging as
>>>>>> fast as if it was switched off
>>>>>> <http://blogs.mulesoft.com/dev/mule-dev/mule-3-6-asynchronous-logging/>
>>>>>> .
>>>>>>
>>>>>>
>>>>>>> Finally, I really think people should (in your wiki page) explicitly
>>>>>>> be *discouraged* from using this part of your framework *unless
>>>>>>> they know they need it*. It's a fantastic piece of work for people
>>>>>>> who *do* need it.
>>>>>>>
>>>>>> Again, I think you are laboring under a misapprehension. I cannot
>>>>>> imagine a scenario where lock-free logging would be a bad thing. If you
>>>>>> think there is, please show evidence.
>>>>>>
>>>>>>
>>>>>>> But 99.99% of people would be better off with a logger that just
>>>>>>> avoids blocking threads when one is already in the process of logging.
>>>>>>>
>>>>>> Avoiding blocking is exactly what the Async Loggers are for. (So I
>>>>>> really think there is some misunderstanding somewhere.)
>>>>>> Based on your feedback, I've updated
>>>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html> the
>>>>>> side nav menu and page title for the 2.6 release to clarify that Async
>>>>>> Loggers are lock-free. I hope this will help avoid misunderstandings.
>>>>>>
>>>>>>
>>>>>>>
>>>>>>> (*It looks like you silently ignore misconfiguration, and default to
>>>>>>> timeout wait strategy also, which is probably going to surprise some people)
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> On 19 May 2016 at 00:34, Remko Popma <re...@gmail.com> wrote:
>>>>>>>
>>>>>>>> Benedict, thanks for your feedback!
>>>>>>>>
>>>>>>>> With regards to filtering, global filters are already considered
>>>>>>>> before the event is enqueued. Filters configured on the Logger and
>>>>>>>> AppenderRef are applied prior to enqueueing with mixed Sync/Async
>>>>>>>> <http://logging.apache.org/log4j/2.x/manual/async.html#MixedSync-Async>
>>>>>>>> Loggers but when all loggers are async
>>>>>>>> <http://logging.apache.org/log4j/2.x/manual/async.html#AllAsync>
>>>>>>>> these filters are applied by the background thread. We can probably improve
>>>>>>>> this, thanks for the suggestion!
>>>>>>>>
>>>>>>>> Your suggestion to run performance tests under lower loads is
>>>>>>>> reasonable and we will look at this for a future release.
>>>>>>>> I did experiment with this a little a while back and did see larger
>>>>>>>> response time pauses. Perhaps others with more experience can chime in.
>>>>>>>>
>>>>>>>> My understanding of how the Disruptor works is that enqueueing the
>>>>>>>> event is lock-free, so applications threads doing the logging should not
>>>>>>>> experience any context switches or suffer latency from Futex calls caused
>>>>>>>> by logging (regardless of the workload). The background thread is another
>>>>>>>> story. Under moderate to low workloads the background thread may (depending
>>>>>>>> on the wait policy) fall asleep and experience delays before waking up when
>>>>>>>> work arrives. However, if there are enough cores to serve all threads I
>>>>>>>> don't see how such background thread delays can impact (cause response time
>>>>>>>> pauses for) the application that is doing the logging. Please correct me if
>>>>>>>> my understanding is incorrect.
>>>>>>>>
>>>>>>>> My thinking is that using async loggers is good for reactive
>>>>>>>> applications that need to respond quickly to external events. It is
>>>>>>>> especially useful if the application needs to deal with occasional bursts
>>>>>>>> of work (and accompanied bursts of logging). This is where async loggers
>>>>>>>> can deliver value even if the normal workload is low.
>>>>>>>>
>>>>>>>> Remko
>>>>>>>>
>>>>>>>> On Wednesday, May 18, 2016 at 2:56:18 AM UTC+9, Benedict Elliott
>>>>>>>> Smith wrote:
>>>>>>>>>
>>>>>>>>> Regrettably it seems impossible (or at least very annoying) to
>>>>>>>>> send to both lists simultaneously...
>>>>>>>>>
>>>>>>>>> On 17 May 2016 at 18:55, Benedict Elliott Smith <
>>>>>>>>> bene...@apache.org> wrote:
>>>>>>>>>
>>>>>>>>>> Could I suggest that you run tests for latency and throughput
>>>>>>>>>> effects of using this in systems with only moderate-to-low numbers of
>>>>>>>>>> logging calls? (i.e. the vast majority of systems!)
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>>> It's very likely that in such systems messages will not reach a
>>>>>>>>>> velocity to keep the Dispatcher running, and so logging calls may often (or
>>>>>>>>>> always) involve a Futex call - which is not a trivial cost. There will
>>>>>>>>>> almost certainly be systems out there with anti-ideal characteristics -
>>>>>>>>>> logging just often enough that these costs materially impact throughput,
>>>>>>>>>> but not often enough that they suddenly disappear.
>>>>>>>>>>
>>>>>>>>>> Even though a majority of systems *do not need this*, because it
>>>>>>>>>> "async" and the new hotness, and there are no advertised downsides,
>>>>>>>>>> everyone will try to use it. It's up to those who know better to make sure
>>>>>>>>>> these people are informed it isn't a free lunch. Making sure all of the
>>>>>>>>>> caveats are reported on the advertising page would be a great start IMO.
>>>>>>>>>>
>>>>>>>>>> Might I also separately suggest you consider filtering events
>>>>>>>>>> prior to placing them on the queue for processing by the dispatcher? I've
>>>>>>>>>> only briefly glanced at the code, but it seems not to be the case currently.
>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> On 17 May 2016 at 18:33, Martin Thompson <mj...@gmail.com>
>>>>>>>>>>> wrote:
>>>>>>>>>>>
>>>>>>>>>>>> Hi Remko,
>>>>>>>>>>>>
>>>>>>>>>>>> I'd just like to say that it is a great service to the
>>>>>>>>>>>> community as a whole that someone is seriously looking at improving logging.
>>>>>>>>>>>>
>>>>>>>>>>>> If you keep it up you'll be putting folks like me out of a job
>>>>>>>>>>>> :)
>>>>>>>>>>>>
>>>>>>>>>>>> Martin...
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> On 17 May 2016 at 18:13, Remko Popma <re...@gmail.com>
>>>>>>>>>>>> wrote:
>>>>>>>>>>>>
>>>>>>>>>>>>> Hi all,
>>>>>>>>>>>>>
>>>>>>>>>>>>> First, my thanks to the many people who gave helpful advice
>>>>>>>>>>>>> and feedback on how to measure Log4j response time on this list some time
>>>>>>>>>>>>> ago.
>>>>>>>>>>>>>
>>>>>>>>>>>>> We're about to start the Log4j 2.6 release.
>>>>>>>>>>>>> If anyone is interested, a preview of the garbage-free logging
>>>>>>>>>>>>> manual page is here:
>>>>>>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>>>>>>>>>>>>> and a preview of the updated performance page is here:
>>>>>>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>>>>>>>>>>
>>>>>>>>>>>>> Feedback welcome!
>>>>>>>>>>>>>
>>>>>>>>>>>>> Remko
>>>>>>>>>>>>>
>>>>>>>>>>>>> --
>>>>>>>>>>>>> You received this message because you are subscribed to the
>>>>>>>>>>>>> Google Groups "mechanical-sympathy" group.
>>>>>>>>>>>>> To unsubscribe from this group and stop receiving emails from
>>>>>>>>>>>>> it, send an email to
>>>>>>>>>>>>> mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> --
>>>>>>>>>>>> You received this message because you are subscribed to the
>>>>>>>>>>>> Google Groups "mechanical-sympathy" group.
>>>>>>>>>>>> To unsubscribe from this group and stop receiving emails from
>>>>>>>>>>>> it, send an email to
>>>>>>>>>>>> mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>
>>>>>>> --
>>>>>> You received this message because you are subscribed to the Google
>>>>>> Groups "mechanical-sympathy" group.
>>>>>> To unsubscribe from this group and stop receiving emails from it,
>>>>>> send an email to mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>
>>>>>
>>>>>
>>>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
--
[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.
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
On Wednesday, May 25, 2016 at 3:25:00 AM UTC+9, Benedict Elliott Smith
wrote:
>
> There is a "major" downside for some users - as an example, imagine a user
> with a single core server that performs a high rate of logging, and does so
> once every 100us. This user is interested in throughput only. There is
> reasonable chance of a material slow down with an async appender. Perhaps
> as much as 10%; or more, dependent on kernel, vm, core count, core
> affinity and way in which the runnable status is transitioned - for old
> paravirtualised boxes running old linux kernels, we could be talking a much
> worse degradation.
>
Okay. I added some text to the trade-offs section for this.
>
> A similar calculus can be done for many cores, but the likely impact in
> throughput reduces as the involved application core count rises (for a
> fixed application log rate), or the likely cost of lock contention
> increases (for a fixed per-thread log rate), both of which mitigating the
> downside.
>
> The number of users facing a *major* downside is likely very low (and
> dependent on how you define "major"), but there are a range of scenarios
> that vary from a meaningful to an irrelevant downside.
>
> I understood your previous messages to mean that your argument against
>> async logging is that the producer thread needs to take a lock to wake up
>> the consumer thread
>
>
> The problem is not the taking of a lock to wake-up anybody, the problem is
> the *waking up*. LiteBlockingWaitStrategy still has to transition the
> runnable state of the consumer for every log message, and this is costly
> with or without contention. Semi-synchronous avoids this cost except when
> it is known to be helpful *and* can be amortized. The overall cost to
> the application will be lower than for async, even in fairly high traffic
> use cases.
>
> On 24 May 2016 at 18:22, Remko Popma <remko...@gmail.com <javascript:>>
> wrote:
>
>>
>>
>> On Tuesday, May 24, 2016 at 6:13:37 PM UTC+9, Benedict Elliott Smith
>> wrote:
>>>
>>> But "response time pauses" are only an issue if you are latency
>>> sensitive, which was one of my explicit criteria. Most users aren't
>>> latency sensitive.
>>>
>>> Holding a lock is not inherently expensive; in fact it is very cheap on
>>> the scale of things we are discussing. What is expensive is interacting
>>> with the scheduler, and "writing to an IO device" (typically just writing
>>> to the page cache, so actually not very expensive - again, unless you care
>>> about outlier latency). In one situation you do just one of these things;
>>> in the other you do both. The synchronous behaviour is worse if the lock
>>> is highly contended, but that is one of the other criteria: there is a
>>> performance/throughput bottleneck in the logging calls. The
>>> semi-synchronous behaviour would avoid this situation, leaving only latency
>>> sensitivity.
>>>
>> So to summarize, you are saying that for low workload situations, in
>> addition to synchronous and asynchronous logging, we should consider
>> another algorithm, which is semi-synchronous. This algorithm may not be
>> suitable for latency sensitive applications but has other desirable
>> properties.
>>
>>
>>> NB: There is another possible criteria not mentioned, of course: Having
>>> spare cores, and the logging work being more expensive than the scheduler
>>> interaction. I've not benchmarked log4j, but I'm pretty sure this is not
>>> the case for anything resembling a typical log message.
>>>
>>> The "LiteBlockingWaitStrategy" does not address this. In the majority
>>> of situations (i.e. a log message rate of < 1-10/ms, as a very rough bound)
>>> its behaviour would be extremely similar to any other blocking wait
>>> strategy, since at this rate you would *on average* expect only about
>>> one unpark to be inflight at once - with all the usual caveats of depending
>>> on overall system load etc etc.
>>>
>> This one I didn't get: I understood your previous messages to mean that
>> your argument against async logging is that the producer thread needs to
>> take a lock to wake up the consumer thread. My understanding is that an
>> uncontended lock is very fast. Taking a lock is only a problem if it is
>> contended. LiteBlockingWaitStrategy ensures the lock is not contended.
>> While not the only way, this is certainly one way to address the concern
>> you expressed against async logging.
>>
>> Semi-synchronous may be another way to solve the problem, and it may or
>> may not be better (we'd need more data on how it behaves in the field).
>>
>>
>>> Semi-synchronous is simply a producer transitioning to a consumer to
>>> process its own message, as waking up the consumer is costlier than doing
>>> so. When it finds work piling up, it decides the cost of waking up the
>>> consumer is no longer negative, and does so.
>>>
>>> I will also note that for most users these extra costs aren't
>>> particularly material either; as soon as your log rate goes down to <
>>> 0.1/ms, the extra costs start to become very small as a proportion of total
>>> work. So there's definitely no reason to panic. But these users are still
>>> not deriving the advertised benefits from async.
>>>
>> Ok, understood. So the main concern is that the advertised benefits may
>> not materialize under low loads. There are no other downsides or major ill
>> effects. Please correct me if I'm wrong. If there is a major downside I
>> would like to document it on the Log4j web site. (But please don't wait too
>> long, we'll start the release soon.)
>>
>>
>>
>>>
>>>
>>> On 23 May 2016 at 13:38, Remko Popma <re...@gmail.com> wrote:
>>>
>>>>
>>>>
>>>> On Monday, May 23, 2016 at 2:47:05 AM UTC+9, Benedict Elliott Smith
>>>> wrote:
>>>>>
>>>>> Your pride should be saved by your gracious recognition of the error :)
>>>>>
>>>>>
>>>>> However this is the core of my point: you’re clearly an intelligent,
>>>>> conscientious and talented developer, and yet you did not fully understand
>>>>> these concerns. You are writing core infrastructure many people will
>>>>> deploy, and a majority will understand it much much less well. So the very
>>>>> best thing you can do is to educate them. Doubly so if you needed
>>>>> educating yourself!
>>>>>
>>>> ;-)
>>>>
>>>>>
>>>>> I would make it very clear that users should only consider
>>>>> asynchronous logging if they are having performance problems caused by
>>>>> their logging. Only with sub-millisecond latency requirements should async
>>>>> be considered, and below 100 micros you are entering busy-spinning
>>>>> territory. Or if huge message rates are being seen. The best default is a
>>>>> blocking strategy, as this has the closest performance profile to
>>>>> synchronous, and will prevent the many users who deploy this without
>>>>> needing it from suffering any major ill-effect.
>>>>>
>>>> I think I missed a step here. You made it plausible that under low
>>>> workload, the Disruptor may not be better than ArrayBlockingQueue.
>>>> Understood.
>>>>
>>>> But I don't understand why users should only configure async logging in
>>>> rare cases? Synchronous logging also involves holding a lock. Log4j 2 makes
>>>> an effort to release this lock as soon as possible (locking only while
>>>> copying a byte array from a thread-local buffer to the I/O device), but as
>>>> Martin pointed out, in addition to the lock contention, other things may
>>>> cause response time pauses when writing to the I/O device.
>>>>
>>>> So which is "better": holding a lock to signal a
>>>> java.util.concurrent.locks.Condition, versus holding a lock to write a byte
>>>> array to the I/O device? The latter sounds like it has more risk of latency
>>>> spikes. So I'm not sure I agree with your assessment that async logging has
>>>> more risk of major ill effects.
>>>>
>>>> Under low loads the upside of Async Loggers may not be as high as the
>>>> graph suggests but I don't see any real downsides either. Please let me
>>>> know if I'm missing something.
>>>>
>>>>
>>>>>
>>>>> I would also do a performance comparison with a real application.
>>>>> Cassandra uses log4j, and the community has an easily utilised performance
>>>>> tool. You could try both DEBUG and INFO level, and put up some graphs.
>>>>> This would help users make a more realistic and informed decision.
>>>>>
>>>> I agree it may be interesting for users to see a case study of some
>>>> sort with a real application. Can you point me to the tool you are
>>>> referring to?
>>>>
>>>>
>>>>>
>>>>> This may all seem a little disappointing: to *reduce* the number of
>>>>> people who might use your amazing new technology. But there will be
>>>>> plenty, who both need it and do not and don't read or heed the warnings.
>>>>>
>>>> That's okay. It is garbage-free logging that is new in the 2.6 release,
>>>> not the Async Loggers. The Disruptor-based Async Loggers have been used in
>>>> the wild for about three years now. The response has generally been
>>>> positive so I'm not panicking just yet.
>>>> I do intend to follow up though and I take your point that under low
>>>> load this technology may not give as much benefit as under high load.
>>>> (Again, please correct me if there is a bigger problem and I'm missing any
>>>> other downsides/risks.)
>>>>
>>>>
>>>>>
>>>>> Regarding improvements: In my opinion, a better algorithm for this
>>>>> majority, of low-to-moderate traffic that is not extremely latency
>>>>> sensitive, is semi-synchronous. By which I mean for the first log call in
>>>>> a batch to take exclusive ownership of the output and to write its message
>>>>> synchronously; any messages that arrive while it has ownership are passed
>>>>> to the owner to persist, i.e. they are written asynchronously. To ensure
>>>>> any thread’s ownership is brief, it would impose a time-limit, after which
>>>>> a dedicated consumer could be started if the queue is still not exhausted.
>>>>> This would have better than synchronous behaviour for low-to-moderate
>>>>> traffic and scale gracefully to high traffic.
>>>>>
>>>> This is really interesting. It reminds me of one of the co-operative
>>>> algorithms I read about in the Art of Multiprocessor Programming (I tried
>>>> to look it up but could not find it last night).
>>>>
>>>> It may be an idea to enhance the Disruptor for lower workloads: I guess
>>>> the question is whether it is possible to incorporate a cheap check before
>>>> calling waitStrategy.signalAllWhenBlocking() in MultiProducerSequence, and
>>>> avoid calling that method if another thread is already signalling the
>>>> consumer thread.
>>>> ...and it turns out this already exists and is called
>>>> LiteBlockingWaitStrategy. Good stuff! Perhaps all that is needed is combine
>>>> the TimeoutBlockingWaitStrategy with this one and we can improve things
>>>> nicely for lower workloads.
>>>>
>>>> Does anyone on this list have any experience with
>>>> LiteBlockingWaitStrategy? I see it was used in projectreactor.io,
>>>> would be interested to hear how that worked, either on list of off-list.
>>>>
>>>>>
>>>>>
>>>>> On Sunday, 22 May 2016 16:40:21 UTC+1, Remko Popma wrote:
>>>>>>
>>>>>>
>>>>>>
>>>>>> On Sunday, May 22, 2016 at 11:08:37 PM UTC+9, Benedict Elliott Smith
>>>>>> wrote:
>>>>>>>
>>>>>>> It's possible I'm missing some other aspect that insulates the
>>>>>>> application thread from the disruptor, but from your message it seems to me
>>>>>>> that you fall into the all-too-common category of people who do not fully
>>>>>>> understand the semantics of the disruptor. Application threads (i.e.
>>>>>>> disruptor producers) very much *are* affected by the wait
>>>>>>> strategy. Under normal use, *if the disruptor consumer thread is
>>>>>>> employing a blocking strategy, there will be futex call to unblock it when
>>>>>>> work is provided*. i.e. whenever the queue transitions from empty
>>>>>>> to non-empty, i.e. for most messages with low-to-medium logging rates.
>>>>>>>
>>>>>>> In this situation the enqueueing of a message is also* not lock
>>>>>>> free*, as while futexes can in theory be lock-free, the JVM uses a
>>>>>>> lock to synchronise access to the semaphore that controls its runnable
>>>>>>> state, so all threads attempting to wake it up concurrently will compete
>>>>>>> for this lock.
>>>>>>>
>>>>>>
>>>>>> Well... Looks like you were right and I was wrong.
>>>>>>
>>>>>> Interesting. Apart from the dent in my pride here, this is actually
>>>>>> good news. It means we can do better!
>>>>>>
>>>>>> So in the worst-case scenario Async Loggers/Disruptor with the
>>>>>> blocking wait strategy give performance equivalent to AsyncAppender with a
>>>>>> BlockingArrayQueue. We can expect Async Loggers with Disruptor to
>>>>>> outperform AsyncAppender with BlockingArrayQueue when workloads are high or
>>>>>> bursts of work keep the background thread busy for some time. At least this
>>>>>> is my understanding now. Or did I miss something and are there cases where
>>>>>> Async Loggers with Disruptor will perform worse than AsyncAppender with
>>>>>> BlockingArrayQueue?
>>>>>>
>>>>>> In terms of how to improve, short-term we should probably look at
>>>>>> using the PhasedBackoffWaitStrategy as the default, although there will
>>>>>> always be workloads that "miss the window". The trade-off is increased CPU.
>>>>>> We need to tread carefully here because users reporting high CPU is why we
>>>>>> changed from the sleeping wait strategy to blocking. (The default in Log4j
>>>>>> 2.6 will be timeout blocking wait to deal with a deadlock issue in Solaris.)
>>>>>>
>>>>>> Long-term we should probably explore other data structures.
>>>>>>
>>>>>> Exciting times. Thanks for correcting me!
>>>>>>
>>>>>>
>>>>>>>
>>>>>>> On 22 May 2016 at 15:07, Benedict Elliott Smith <be...@apache.org>
>>>>>>> wrote:
>>>>>>>
>>>>>>>> It's possible I'm missing some other aspect that insulates the
>>>>>>>> application thread from the disruptor, but from your message it seems to me
>>>>>>>> that you fall into the all-too-common category of people who do not fully
>>>>>>>> understand the semantics of the disruptor. Application threads (i.e.
>>>>>>>> disruptor producers) very much *are* affected by the wait
>>>>>>>> strategy. Under normal use, *if the disruptor consumer thread is
>>>>>>>> employing a blocking strategy, there will be futex call to unblock it when
>>>>>>>> work is provided*. i.e. whenever the queue transitions from empty
>>>>>>>> to non-empty, i.e. for most messages with low-to-medium logging rates.
>>>>>>>>
>>>>>>>> In this situation the enqueueing of a message is also* not lock
>>>>>>>> free*, as while futexes can in theory be lock-free, the JVM uses a
>>>>>>>> lock to synchronise access to the semaphore that controls its runnable
>>>>>>>> state, so all threads attempting to wake it up concurrently will compete
>>>>>>>> for this lock.
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> On 22 May 2016 at 14:42, Remko Popma <re...@gmail.com> wrote:
>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> On Sunday, May 22, 2016 at 6:34:13 PM UTC+9, Benedict Elliott
>>>>>>>>> Smith wrote:
>>>>>>>>>>
>>>>>>>>>> Hi Remko,
>>>>>>>>>>
>>>>>>>>>> I realise that I was looking at the old log4j code without
>>>>>>>>>> realising it, in which there is always a futex involved.
>>>>>>>>>>
>>>>>>>>> Which class is this? Async Loggers in Log4j 2 have always been
>>>>>>>>> lock-free. What may be confusing is that Log4j 2 also has an Async
>>>>>>>>> *Appender*, which does not use the Disruptor but uses a JDK
>>>>>>>>> BlockingArrayQueue. This appender is very similar to how Logback and Log4j
>>>>>>>>> 1 do asynchronous logging. Async*Appender* (in Log4j 2, Log4j 1
>>>>>>>>> and Logback, they all use a blocking queue) is sensitive to lock contention
>>>>>>>>> and does not scale with more threads.
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> However the behaviour of the disruptor that backs the new code
>>>>>>>>>> will depend on the wait strategy employed (and I'll note your default is a
>>>>>>>>>> blocking strategy, for which my prior statement holds*).
>>>>>>>>>>
>>>>>>>>> Perhaps the key misunderstanding is here. I think I did not
>>>>>>>>> explain it well in my previous message. Let me try again.
>>>>>>>>>
>>>>>>>>> Async Loggers use the Disruptor and are lock-free. This means that
>>>>>>>>> multiple application threads can log concurrently and are not blocked by
>>>>>>>>> each other. This is true for very low workloads, medium workloads and high
>>>>>>>>> workloads.
>>>>>>>>>
>>>>>>>>> Only if an application logs messages at a very high rate for a
>>>>>>>>> long period of time, or uses a slow appender, the Disruptor ringbuffer can
>>>>>>>>> fill up and application threads will have to wait until a slot in the
>>>>>>>>> ringbuffer becomes available. For the 2.6 release I have added
>>>>>>>>> text to the Trade-offs section
>>>>>>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Trade-offs>
>>>>>>>>> to explain this last point, based on your feedback.
>>>>>>>>>
>>>>>>>>> Note that the Disruptor wait strategy is irrelevant to all this.
>>>>>>>>> Application threads are *not *impacted by the wait strategy.
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>> Here we obviously get into the territory of people needing to
>>>>>>>>>> understand the disruptor as well as your logging framework, but since you
>>>>>>>>>> have a whole section labelled "Trade-offs" in which you draw attention to
>>>>>>>>>> the improved throughput and latency profile under "Benefits," under
>>>>>>>>>> "Drawbacks" it might be nice to mention these possible confounders. Or at
>>>>>>>>>> least raise a bat signal to go and understand the tradeoffs for the
>>>>>>>>>> disruptor (which is also regrettably poorly understood).
>>>>>>>>>>
>>>>>>>>>> It might also be helpful to explicitly call out the configuration
>>>>>>>>>> used for your benchmarks,
>>>>>>>>>>
>>>>>>>>> Tests on the 2.6 performance page
>>>>>>>>> <http://home.apache.org/~rpopma/log4j/2.6/performance.html> are
>>>>>>>>> mostly done with JMH benchmarks where parameters are in the javadoc.
>>>>>>>>> Tests on the Async Loggers page are partly with the new ResponseTimeTest
>>>>>>>>>
>>>>>>>>> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java>class
>>>>>>>>> (params in the doc
>>>>>>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Latency>)
>>>>>>>>> and partly still shows results from the older PerfTestDriver
>>>>>>>>> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTestDriver.java>
>>>>>>>>> class. This last one has parameters in the code. You'll need to spend some
>>>>>>>>> time to get familiar with it if you want to run it.
>>>>>>>>>
>>>>>>>>> and perhaps to run a comparison against some real software -
>>>>>>>>>> github does not lack for applications using log4j! Unfortunately I bet
>>>>>>>>>> this would result in a much less sexy graph.
>>>>>>>>>>
>>>>>>>>> Log4j 2 has had lock-free Async Loggers from its 2.0-beta5 release
>>>>>>>>> <http://logging.apache.org/log4j/2.x/changes-report.html#a2.0-beta5>,
>>>>>>>>> three years ago. If there are any serious performance drawbacks like you
>>>>>>>>> seem to think there are I hope I would have heard of them. Fortunately the
>>>>>>>>> opposite is true. People report very positive experiences
>>>>>>>>> <http://tech.finn.no/2014/07/01/log4j2-in-production-making-it-fly/>.
>>>>>>>>> People who did their own measurements reported it makes their logging as
>>>>>>>>> fast as if it was switched off
>>>>>>>>> <http://blogs.mulesoft.com/dev/mule-dev/mule-3-6-asynchronous-logging/>
>>>>>>>>> .
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>> Finally, I really think people should (in your wiki page)
>>>>>>>>>> explicitly be *discouraged* from using this part of your
>>>>>>>>>> framework *unless they know they need it*. It's a fantastic
>>>>>>>>>> piece of work for people who *do* need it.
>>>>>>>>>>
>>>>>>>>> Again, I think you are laboring under a misapprehension. I cannot
>>>>>>>>> imagine a scenario where lock-free logging would be a bad thing. If you
>>>>>>>>> think there is, please show evidence.
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>> But 99.99% of people would be better off with a logger that just
>>>>>>>>>> avoids blocking threads when one is already in the process of logging.
>>>>>>>>>>
>>>>>>>>> Avoiding blocking is exactly what the Async Loggers are for. (So I
>>>>>>>>> really think there is some misunderstanding somewhere.)
>>>>>>>>> Based on your feedback, I've updated
>>>>>>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html> the
>>>>>>>>> side nav menu and page title for the 2.6 release to clarify that Async
>>>>>>>>> Loggers are lock-free. I hope this will help avoid misunderstandings.
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> (*It looks like you silently ignore misconfiguration, and default
>>>>>>>>>> to timeout wait strategy also, which is probably going to surprise some
>>>>>>>>>> people)
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> On 19 May 2016 at 00:34, Remko Popma <re...@gmail.com> wrote:
>>>>>>>>>>
>>>>>>>>>>> Benedict, thanks for your feedback!
>>>>>>>>>>>
>>>>>>>>>>> With regards to filtering, global filters are already considered
>>>>>>>>>>> before the event is enqueued. Filters configured on the Logger and
>>>>>>>>>>> AppenderRef are applied prior to enqueueing with mixed
>>>>>>>>>>> Sync/Async
>>>>>>>>>>> <http://logging.apache.org/log4j/2.x/manual/async.html#MixedSync-Async>
>>>>>>>>>>> Loggers but when all loggers are async
>>>>>>>>>>> <http://logging.apache.org/log4j/2.x/manual/async.html#AllAsync>
>>>>>>>>>>> these filters are applied by the background thread. We can probably improve
>>>>>>>>>>> this, thanks for the suggestion!
>>>>>>>>>>>
>>>>>>>>>>> Your suggestion to run performance tests under lower loads is
>>>>>>>>>>> reasonable and we will look at this for a future release.
>>>>>>>>>>> I did experiment with this a little a while back and did see
>>>>>>>>>>> larger response time pauses. Perhaps others with more experience can chime
>>>>>>>>>>> in.
>>>>>>>>>>>
>>>>>>>>>>> My understanding of how the Disruptor works is that enqueueing
>>>>>>>>>>> the event is lock-free, so applications threads doing the logging should
>>>>>>>>>>> not experience any context switches or suffer latency from Futex calls
>>>>>>>>>>> caused by logging (regardless of the workload). The background thread is
>>>>>>>>>>> another story. Under moderate to low workloads the background thread may
>>>>>>>>>>> (depending on the wait policy) fall asleep and experience delays before
>>>>>>>>>>> waking up when work arrives. However, if there are enough cores to serve
>>>>>>>>>>> all threads I don't see how such background thread delays can impact (cause
>>>>>>>>>>> response time pauses for) the application that is doing the logging. Please
>>>>>>>>>>> correct me if my understanding is incorrect.
>>>>>>>>>>>
>>>>>>>>>>> My thinking is that using async loggers is good for reactive
>>>>>>>>>>> applications that need to respond quickly to external events. It is
>>>>>>>>>>> especially useful if the application needs to deal with occasional bursts
>>>>>>>>>>> of work (and accompanied bursts of logging). This is where async loggers
>>>>>>>>>>> can deliver value even if the normal workload is low.
>>>>>>>>>>>
>>>>>>>>>>> Remko
>>>>>>>>>>>
>>>>>>>>>>> On Wednesday, May 18, 2016 at 2:56:18 AM UTC+9, Benedict Elliott
>>>>>>>>>>> Smith wrote:
>>>>>>>>>>>>
>>>>>>>>>>>> Regrettably it seems impossible (or at least very annoying) to
>>>>>>>>>>>> send to both lists simultaneously...
>>>>>>>>>>>>
>>>>>>>>>>>> On 17 May 2016 at 18:55, Benedict Elliott Smith <
>>>>>>>>>>>> bene...@apache.org> wrote:
>>>>>>>>>>>>
>>>>>>>>>>>>> Could I suggest that you run tests for latency and throughput
>>>>>>>>>>>>> effects of using this in systems with only moderate-to-low numbers of
>>>>>>>>>>>>> logging calls? (i.e. the vast majority of systems!)
>>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>> It's very likely that in such systems messages will not reach
>>>>>>>>>>>>> a velocity to keep the Dispatcher running, and so logging calls may often
>>>>>>>>>>>>> (or always) involve a Futex call - which is not a trivial cost. There will
>>>>>>>>>>>>> almost certainly be systems out there with anti-ideal characteristics -
>>>>>>>>>>>>> logging just often enough that these costs materially impact throughput,
>>>>>>>>>>>>> but not often enough that they suddenly disappear.
>>>>>>>>>>>>>
>>>>>>>>>>>>> Even though a majority of systems *do not need this*, because
>>>>>>>>>>>>> it "async" and the new hotness, and there are no advertised downsides,
>>>>>>>>>>>>> everyone will try to use it. It's up to those who know better to make sure
>>>>>>>>>>>>> these people are informed it isn't a free lunch. Making sure all of the
>>>>>>>>>>>>> caveats are reported on the advertising page would be a great start IMO.
>>>>>>>>>>>>>
>>>>>>>>>>>>> Might I also separately suggest you consider filtering events
>>>>>>>>>>>>> prior to placing them on the queue for processing by the dispatcher? I've
>>>>>>>>>>>>> only briefly glanced at the code, but it seems not to be the case currently.
>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> On 17 May 2016 at 18:33, Martin Thompson <mj...@gmail.com>
>>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Hi Remko,
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> I'd just like to say that it is a great service to the
>>>>>>>>>>>>>>> community as a whole that someone is seriously looking at improving logging.
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> If you keep it up you'll be putting folks like me out of a
>>>>>>>>>>>>>>> job :)
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Martin...
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> On 17 May 2016 at 18:13, Remko Popma <re...@gmail.com>
>>>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Hi all,
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> First, my thanks to the many people who gave helpful advice
>>>>>>>>>>>>>>>> and feedback on how to measure Log4j response time on this list some time
>>>>>>>>>>>>>>>> ago.
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> We're about to start the Log4j 2.6 release.
>>>>>>>>>>>>>>>> If anyone is interested, a preview of the garbage-free
>>>>>>>>>>>>>>>> logging manual page is here:
>>>>>>>>>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>>>>>>>>>>>>>>>> and a preview of the updated performance page is here:
>>>>>>>>>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Feedback welcome!
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Remko
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>> You received this message because you are subscribed to the
>>>>>>>>>>>>>>>> Google Groups "mechanical-sympathy" group.
>>>>>>>>>>>>>>>> To unsubscribe from this group and stop receiving emails
>>>>>>>>>>>>>>>> from it, send an email to
>>>>>>>>>>>>>>>> mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>>>>>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>> You received this message because you are subscribed to the
>>>>>>>>>>>>>>> Google Groups "mechanical-sympathy" group.
>>>>>>>>>>>>>>> To unsubscribe from this group and stop receiving emails
>>>>>>>>>>>>>>> from it, send an email to
>>>>>>>>>>>>>>> mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>>>>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>> --
>>>>>>>>> You received this message because you are subscribed to the Google
>>>>>>>>> Groups "mechanical-sympathy" group.
>>>>>>>>> To unsubscribe from this group and stop receiving emails from it,
>>>>>>>>> send an email to mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>> --
>>>> You received this message because you are subscribed to the Google
>>>> Groups "mechanical-sympathy" group.
>>>> To unsubscribe from this group and stop receiving emails from it, send
>>>> an email to mechanical-sympathy+unsubscribe@googlegroups.com.
>>>> For more options, visit https://groups.google.com/d/optout.
>>>>
>>>
>>>
>
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
On Tuesday, May 24, 2016 at 6:13:37 PM UTC+9, Benedict Elliott Smith wrote:
>
> But "response time pauses" are only an issue if you are latency sensitive,
> which was one of my explicit criteria. Most users aren't latency sensitive.
>
> Holding a lock is not inherently expensive; in fact it is very cheap on
> the scale of things we are discussing. What is expensive is interacting
> with the scheduler, and "writing to an IO device" (typically just writing
> to the page cache, so actually not very expensive - again, unless you care
> about outlier latency). In one situation you do just one of these things;
> in the other you do both. The synchronous behaviour is worse if the lock
> is highly contended, but that is one of the other criteria: there is a
> performance/throughput bottleneck in the logging calls. The
> semi-synchronous behaviour would avoid this situation, leaving only latency
> sensitivity.
>
So to summarize, you are saying that for low workload situations, in
addition to synchronous and asynchronous logging, we should consider
another algorithm, which is semi-synchronous. This algorithm may not be
suitable for latency sensitive applications but has other desirable
properties.
> NB: There is another possible criteria not mentioned, of course: Having
> spare cores, and the logging work being more expensive than the scheduler
> interaction. I've not benchmarked log4j, but I'm pretty sure this is not
> the case for anything resembling a typical log message.
>
> The "LiteBlockingWaitStrategy" does not address this. In the majority of
> situations (i.e. a log message rate of < 1-10/ms, as a very rough bound)
> its behaviour would be extremely similar to any other blocking wait
> strategy, since at this rate you would *on average* expect only about one
> unpark to be inflight at once - with all the usual caveats of depending on
> overall system load etc etc.
>
This one I didn't get: I understood your previous messages to mean that
your argument against async logging is that the producer thread needs to
take a lock to wake up the consumer thread. My understanding is that an
uncontended lock is very fast. Taking a lock is only a problem if it is
contended. LiteBlockingWaitStrategy ensures the lock is not contended.
While not the only way, this is certainly one way to address the concern
you expressed against async logging.
Semi-synchronous may be another way to solve the problem, and it may or may
not be better (we'd need more data on how it behaves in the field).
> Semi-synchronous is simply a producer transitioning to a consumer to
> process its own message, as waking up the consumer is costlier than doing
> so. When it finds work piling up, it decides the cost of waking up the
> consumer is no longer negative, and does so.
>
> I will also note that for most users these extra costs aren't particularly
> material either; as soon as your log rate goes down to < 0.1/ms, the extra
> costs start to become very small as a proportion of total work. So there's
> definitely no reason to panic. But these users are still not deriving the
> advertised benefits from async.
>
Ok, understood. So the main concern is that the advertised benefits may not
materialize under low loads. There are no other downsides or major ill
effects. Please correct me if I'm wrong. If there is a major downside I
would like to document it on the Log4j web site. (But please don't wait too
long, we'll start the release soon.)
>
>
> On 23 May 2016 at 13:38, Remko Popma <remko...@gmail.com <javascript:>>
> wrote:
>
>>
>>
>> On Monday, May 23, 2016 at 2:47:05 AM UTC+9, Benedict Elliott Smith wrote:
>>>
>>> Your pride should be saved by your gracious recognition of the error :)
>>>
>>>
>>> However this is the core of my point: you’re clearly an intelligent,
>>> conscientious and talented developer, and yet you did not fully understand
>>> these concerns. You are writing core infrastructure many people will
>>> deploy, and a majority will understand it much much less well. So the very
>>> best thing you can do is to educate them. Doubly so if you needed
>>> educating yourself!
>>>
>> ;-)
>>
>>>
>>> I would make it very clear that users should only consider asynchronous
>>> logging if they are having performance problems caused by their logging.
>>> Only with sub-millisecond latency requirements should async be considered,
>>> and below 100 micros you are entering busy-spinning territory. Or if huge
>>> message rates are being seen. The best default is a blocking strategy, as
>>> this has the closest performance profile to synchronous, and will prevent
>>> the many users who deploy this without needing it from suffering any major
>>> ill-effect.
>>>
>> I think I missed a step here. You made it plausible that under low
>> workload, the Disruptor may not be better than ArrayBlockingQueue.
>> Understood.
>>
>> But I don't understand why users should only configure async logging in
>> rare cases? Synchronous logging also involves holding a lock. Log4j 2 makes
>> an effort to release this lock as soon as possible (locking only while
>> copying a byte array from a thread-local buffer to the I/O device), but as
>> Martin pointed out, in addition to the lock contention, other things may
>> cause response time pauses when writing to the I/O device.
>>
>> So which is "better": holding a lock to signal a
>> java.util.concurrent.locks.Condition, versus holding a lock to write a byte
>> array to the I/O device? The latter sounds like it has more risk of latency
>> spikes. So I'm not sure I agree with your assessment that async logging has
>> more risk of major ill effects.
>>
>> Under low loads the upside of Async Loggers may not be as high as the
>> graph suggests but I don't see any real downsides either. Please let me
>> know if I'm missing something.
>>
>>
>>>
>>> I would also do a performance comparison with a real application.
>>> Cassandra uses log4j, and the community has an easily utilised performance
>>> tool. You could try both DEBUG and INFO level, and put up some graphs.
>>> This would help users make a more realistic and informed decision.
>>>
>> I agree it may be interesting for users to see a case study of some sort
>> with a real application. Can you point me to the tool you are referring to?
>>
>>
>>>
>>> This may all seem a little disappointing: to *reduce* the number of
>>> people who might use your amazing new technology. But there will be
>>> plenty, who both need it and do not and don't read or heed the warnings.
>>>
>> That's okay. It is garbage-free logging that is new in the 2.6 release,
>> not the Async Loggers. The Disruptor-based Async Loggers have been used in
>> the wild for about three years now. The response has generally been
>> positive so I'm not panicking just yet.
>> I do intend to follow up though and I take your point that under low load
>> this technology may not give as much benefit as under high load. (Again,
>> please correct me if there is a bigger problem and I'm missing any other
>> downsides/risks.)
>>
>>
>>>
>>> Regarding improvements: In my opinion, a better algorithm for this
>>> majority, of low-to-moderate traffic that is not extremely latency
>>> sensitive, is semi-synchronous. By which I mean for the first log call in
>>> a batch to take exclusive ownership of the output and to write its message
>>> synchronously; any messages that arrive while it has ownership are passed
>>> to the owner to persist, i.e. they are written asynchronously. To ensure
>>> any thread’s ownership is brief, it would impose a time-limit, after which
>>> a dedicated consumer could be started if the queue is still not exhausted.
>>> This would have better than synchronous behaviour for low-to-moderate
>>> traffic and scale gracefully to high traffic.
>>>
>> This is really interesting. It reminds me of one of the co-operative
>> algorithms I read about in the Art of Multiprocessor Programming (I tried
>> to look it up but could not find it last night).
>>
>> It may be an idea to enhance the Disruptor for lower workloads: I guess
>> the question is whether it is possible to incorporate a cheap check before
>> calling waitStrategy.signalAllWhenBlocking() in MultiProducerSequence, and
>> avoid calling that method if another thread is already signalling the
>> consumer thread.
>> ...and it turns out this already exists and is called
>> LiteBlockingWaitStrategy. Good stuff! Perhaps all that is needed is combine
>> the TimeoutBlockingWaitStrategy with this one and we can improve things
>> nicely for lower workloads.
>>
>> Does anyone on this list have any experience with
>> LiteBlockingWaitStrategy? I see it was used in projectreactor.io, would
>> be interested to hear how that worked, either on list of off-list.
>>
>>>
>>>
>>> On Sunday, 22 May 2016 16:40:21 UTC+1, Remko Popma wrote:
>>>>
>>>>
>>>>
>>>> On Sunday, May 22, 2016 at 11:08:37 PM UTC+9, Benedict Elliott Smith
>>>> wrote:
>>>>>
>>>>> It's possible I'm missing some other aspect that insulates the
>>>>> application thread from the disruptor, but from your message it seems to me
>>>>> that you fall into the all-too-common category of people who do not fully
>>>>> understand the semantics of the disruptor. Application threads (i.e.
>>>>> disruptor producers) very much *are* affected by the wait strategy.
>>>>> Under normal use, *if the disruptor consumer thread is employing a
>>>>> blocking strategy, there will be futex call to unblock it when work is
>>>>> provided*. i.e. whenever the queue transitions from empty to
>>>>> non-empty, i.e. for most messages with low-to-medium logging rates.
>>>>>
>>>>> In this situation the enqueueing of a message is also* not lock free*,
>>>>> as while futexes can in theory be lock-free, the JVM uses a lock to
>>>>> synchronise access to the semaphore that controls its runnable state, so
>>>>> all threads attempting to wake it up concurrently will compete for this
>>>>> lock.
>>>>>
>>>>
>>>> Well... Looks like you were right and I was wrong.
>>>>
>>>> Interesting. Apart from the dent in my pride here, this is actually
>>>> good news. It means we can do better!
>>>>
>>>> So in the worst-case scenario Async Loggers/Disruptor with the blocking
>>>> wait strategy give performance equivalent to AsyncAppender with a
>>>> BlockingArrayQueue. We can expect Async Loggers with Disruptor to
>>>> outperform AsyncAppender with BlockingArrayQueue when workloads are high or
>>>> bursts of work keep the background thread busy for some time. At least this
>>>> is my understanding now. Or did I miss something and are there cases where
>>>> Async Loggers with Disruptor will perform worse than AsyncAppender with
>>>> BlockingArrayQueue?
>>>>
>>>> In terms of how to improve, short-term we should probably look at using
>>>> the PhasedBackoffWaitStrategy as the default, although there will always be
>>>> workloads that "miss the window". The trade-off is increased CPU. We need
>>>> to tread carefully here because users reporting high CPU is why we changed
>>>> from the sleeping wait strategy to blocking. (The default in Log4j 2.6 will
>>>> be timeout blocking wait to deal with a deadlock issue in Solaris.)
>>>>
>>>> Long-term we should probably explore other data structures.
>>>>
>>>> Exciting times. Thanks for correcting me!
>>>>
>>>>
>>>>>
>>>>> On 22 May 2016 at 15:07, Benedict Elliott Smith <be...@apache.org>
>>>>> wrote:
>>>>>
>>>>>> It's possible I'm missing some other aspect that insulates the
>>>>>> application thread from the disruptor, but from your message it seems to me
>>>>>> that you fall into the all-too-common category of people who do not fully
>>>>>> understand the semantics of the disruptor. Application threads (i.e.
>>>>>> disruptor producers) very much *are* affected by the wait strategy.
>>>>>> Under normal use, *if the disruptor consumer thread is employing a
>>>>>> blocking strategy, there will be futex call to unblock it when work is
>>>>>> provided*. i.e. whenever the queue transitions from empty to
>>>>>> non-empty, i.e. for most messages with low-to-medium logging rates.
>>>>>>
>>>>>> In this situation the enqueueing of a message is also* not lock free*,
>>>>>> as while futexes can in theory be lock-free, the JVM uses a lock to
>>>>>> synchronise access to the semaphore that controls its runnable state, so
>>>>>> all threads attempting to wake it up concurrently will compete for this
>>>>>> lock.
>>>>>>
>>>>>>
>>>>>>
>>>>>> On 22 May 2016 at 14:42, Remko Popma <re...@gmail.com> wrote:
>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> On Sunday, May 22, 2016 at 6:34:13 PM UTC+9, Benedict Elliott Smith
>>>>>>> wrote:
>>>>>>>>
>>>>>>>> Hi Remko,
>>>>>>>>
>>>>>>>> I realise that I was looking at the old log4j code without
>>>>>>>> realising it, in which there is always a futex involved.
>>>>>>>>
>>>>>>> Which class is this? Async Loggers in Log4j 2 have always been
>>>>>>> lock-free. What may be confusing is that Log4j 2 also has an Async
>>>>>>> *Appender*, which does not use the Disruptor but uses a JDK
>>>>>>> BlockingArrayQueue. This appender is very similar to how Logback and Log4j
>>>>>>> 1 do asynchronous logging. Async*Appender* (in Log4j 2, Log4j 1 and
>>>>>>> Logback, they all use a blocking queue) is sensitive to lock contention and
>>>>>>> does not scale with more threads.
>>>>>>>
>>>>>>>
>>>>>>>>
>>>>>>>> However the behaviour of the disruptor that backs the new code will
>>>>>>>> depend on the wait strategy employed (and I'll note your default is a
>>>>>>>> blocking strategy, for which my prior statement holds*).
>>>>>>>>
>>>>>>> Perhaps the key misunderstanding is here. I think I did not explain
>>>>>>> it well in my previous message. Let me try again.
>>>>>>>
>>>>>>> Async Loggers use the Disruptor and are lock-free. This means that
>>>>>>> multiple application threads can log concurrently and are not blocked by
>>>>>>> each other. This is true for very low workloads, medium workloads and high
>>>>>>> workloads.
>>>>>>>
>>>>>>> Only if an application logs messages at a very high rate for a long
>>>>>>> period of time, or uses a slow appender, the Disruptor ringbuffer can fill
>>>>>>> up and application threads will have to wait until a slot in the ringbuffer
>>>>>>> becomes available. For the 2.6 release I have added text to the
>>>>>>> Trade-offs section
>>>>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Trade-offs>
>>>>>>> to explain this last point, based on your feedback.
>>>>>>>
>>>>>>> Note that the Disruptor wait strategy is irrelevant to all this.
>>>>>>> Application threads are *not *impacted by the wait strategy.
>>>>>>>
>>>>>>>
>>>>>>>> Here we obviously get into the territory of people needing to
>>>>>>>> understand the disruptor as well as your logging framework, but since you
>>>>>>>> have a whole section labelled "Trade-offs" in which you draw attention to
>>>>>>>> the improved throughput and latency profile under "Benefits," under
>>>>>>>> "Drawbacks" it might be nice to mention these possible confounders. Or at
>>>>>>>> least raise a bat signal to go and understand the tradeoffs for the
>>>>>>>> disruptor (which is also regrettably poorly understood).
>>>>>>>>
>>>>>>>> It might also be helpful to explicitly call out the configuration
>>>>>>>> used for your benchmarks,
>>>>>>>>
>>>>>>> Tests on the 2.6 performance page
>>>>>>> <http://home.apache.org/~rpopma/log4j/2.6/performance.html> are
>>>>>>> mostly done with JMH benchmarks where parameters are in the javadoc.
>>>>>>> Tests on the Async Loggers page are partly with the new ResponseTimeTest
>>>>>>>
>>>>>>> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java>class
>>>>>>> (params in the doc
>>>>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Latency>)
>>>>>>> and partly still shows results from the older PerfTestDriver
>>>>>>> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTestDriver.java>
>>>>>>> class. This last one has parameters in the code. You'll need to spend some
>>>>>>> time to get familiar with it if you want to run it.
>>>>>>>
>>>>>>> and perhaps to run a comparison against some real software - github
>>>>>>>> does not lack for applications using log4j! Unfortunately I bet this would
>>>>>>>> result in a much less sexy graph.
>>>>>>>>
>>>>>>> Log4j 2 has had lock-free Async Loggers from its 2.0-beta5 release
>>>>>>> <http://logging.apache.org/log4j/2.x/changes-report.html#a2.0-beta5>,
>>>>>>> three years ago. If there are any serious performance drawbacks like you
>>>>>>> seem to think there are I hope I would have heard of them. Fortunately the
>>>>>>> opposite is true. People report very positive experiences
>>>>>>> <http://tech.finn.no/2014/07/01/log4j2-in-production-making-it-fly/>.
>>>>>>> People who did their own measurements reported it makes their logging as
>>>>>>> fast as if it was switched off
>>>>>>> <http://blogs.mulesoft.com/dev/mule-dev/mule-3-6-asynchronous-logging/>
>>>>>>> .
>>>>>>>
>>>>>>>
>>>>>>>> Finally, I really think people should (in your wiki page)
>>>>>>>> explicitly be *discouraged* from using this part of your framework *unless
>>>>>>>> they know they need it*. It's a fantastic piece of work for
>>>>>>>> people who *do* need it.
>>>>>>>>
>>>>>>> Again, I think you are laboring under a misapprehension. I cannot
>>>>>>> imagine a scenario where lock-free logging would be a bad thing. If you
>>>>>>> think there is, please show evidence.
>>>>>>>
>>>>>>>
>>>>>>>> But 99.99% of people would be better off with a logger that just
>>>>>>>> avoids blocking threads when one is already in the process of logging.
>>>>>>>>
>>>>>>> Avoiding blocking is exactly what the Async Loggers are for. (So I
>>>>>>> really think there is some misunderstanding somewhere.)
>>>>>>> Based on your feedback, I've updated
>>>>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html> the
>>>>>>> side nav menu and page title for the 2.6 release to clarify that Async
>>>>>>> Loggers are lock-free. I hope this will help avoid misunderstandings.
>>>>>>>
>>>>>>>
>>>>>>>>
>>>>>>>> (*It looks like you silently ignore misconfiguration, and default
>>>>>>>> to timeout wait strategy also, which is probably going to surprise some
>>>>>>>> people)
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> On 19 May 2016 at 00:34, Remko Popma <re...@gmail.com> wrote:
>>>>>>>>
>>>>>>>>> Benedict, thanks for your feedback!
>>>>>>>>>
>>>>>>>>> With regards to filtering, global filters are already considered
>>>>>>>>> before the event is enqueued. Filters configured on the Logger and
>>>>>>>>> AppenderRef are applied prior to enqueueing with mixed Sync/Async
>>>>>>>>> <http://logging.apache.org/log4j/2.x/manual/async.html#MixedSync-Async>
>>>>>>>>> Loggers but when all loggers are async
>>>>>>>>> <http://logging.apache.org/log4j/2.x/manual/async.html#AllAsync>
>>>>>>>>> these filters are applied by the background thread. We can probably improve
>>>>>>>>> this, thanks for the suggestion!
>>>>>>>>>
>>>>>>>>> Your suggestion to run performance tests under lower loads is
>>>>>>>>> reasonable and we will look at this for a future release.
>>>>>>>>> I did experiment with this a little a while back and did see
>>>>>>>>> larger response time pauses. Perhaps others with more experience can chime
>>>>>>>>> in.
>>>>>>>>>
>>>>>>>>> My understanding of how the Disruptor works is that enqueueing the
>>>>>>>>> event is lock-free, so applications threads doing the logging should not
>>>>>>>>> experience any context switches or suffer latency from Futex calls caused
>>>>>>>>> by logging (regardless of the workload). The background thread is another
>>>>>>>>> story. Under moderate to low workloads the background thread may (depending
>>>>>>>>> on the wait policy) fall asleep and experience delays before waking up when
>>>>>>>>> work arrives. However, if there are enough cores to serve all threads I
>>>>>>>>> don't see how such background thread delays can impact (cause response time
>>>>>>>>> pauses for) the application that is doing the logging. Please correct me if
>>>>>>>>> my understanding is incorrect.
>>>>>>>>>
>>>>>>>>> My thinking is that using async loggers is good for reactive
>>>>>>>>> applications that need to respond quickly to external events. It is
>>>>>>>>> especially useful if the application needs to deal with occasional bursts
>>>>>>>>> of work (and accompanied bursts of logging). This is where async loggers
>>>>>>>>> can deliver value even if the normal workload is low.
>>>>>>>>>
>>>>>>>>> Remko
>>>>>>>>>
>>>>>>>>> On Wednesday, May 18, 2016 at 2:56:18 AM UTC+9, Benedict Elliott
>>>>>>>>> Smith wrote:
>>>>>>>>>>
>>>>>>>>>> Regrettably it seems impossible (or at least very annoying) to
>>>>>>>>>> send to both lists simultaneously...
>>>>>>>>>>
>>>>>>>>>> On 17 May 2016 at 18:55, Benedict Elliott Smith <
>>>>>>>>>> bene...@apache.org> wrote:
>>>>>>>>>>
>>>>>>>>>>> Could I suggest that you run tests for latency and throughput
>>>>>>>>>>> effects of using this in systems with only moderate-to-low numbers of
>>>>>>>>>>> logging calls? (i.e. the vast majority of systems!)
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>> It's very likely that in such systems messages will not reach a
>>>>>>>>>>> velocity to keep the Dispatcher running, and so logging calls may often (or
>>>>>>>>>>> always) involve a Futex call - which is not a trivial cost. There will
>>>>>>>>>>> almost certainly be systems out there with anti-ideal characteristics -
>>>>>>>>>>> logging just often enough that these costs materially impact throughput,
>>>>>>>>>>> but not often enough that they suddenly disappear.
>>>>>>>>>>>
>>>>>>>>>>> Even though a majority of systems *do not need this*, because
>>>>>>>>>>> it "async" and the new hotness, and there are no advertised downsides,
>>>>>>>>>>> everyone will try to use it. It's up to those who know better to make sure
>>>>>>>>>>> these people are informed it isn't a free lunch. Making sure all of the
>>>>>>>>>>> caveats are reported on the advertising page would be a great start IMO.
>>>>>>>>>>>
>>>>>>>>>>> Might I also separately suggest you consider filtering events
>>>>>>>>>>> prior to placing them on the queue for processing by the dispatcher? I've
>>>>>>>>>>> only briefly glanced at the code, but it seems not to be the case currently.
>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> On 17 May 2016 at 18:33, Martin Thompson <mj...@gmail.com>
>>>>>>>>>>>> wrote:
>>>>>>>>>>>>
>>>>>>>>>>>>> Hi Remko,
>>>>>>>>>>>>>
>>>>>>>>>>>>> I'd just like to say that it is a great service to the
>>>>>>>>>>>>> community as a whole that someone is seriously looking at improving logging.
>>>>>>>>>>>>>
>>>>>>>>>>>>> If you keep it up you'll be putting folks like me out of a job
>>>>>>>>>>>>> :)
>>>>>>>>>>>>>
>>>>>>>>>>>>> Martin...
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>> On 17 May 2016 at 18:13, Remko Popma <re...@gmail.com>
>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>
>>>>>>>>>>>>>> Hi all,
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> First, my thanks to the many people who gave helpful advice
>>>>>>>>>>>>>> and feedback on how to measure Log4j response time on this list some time
>>>>>>>>>>>>>> ago.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> We're about to start the Log4j 2.6 release.
>>>>>>>>>>>>>> If anyone is interested, a preview of the garbage-free
>>>>>>>>>>>>>> logging manual page is here:
>>>>>>>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>>>>>>>>>>>>>> and a preview of the updated performance page is here:
>>>>>>>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> Feedback welcome!
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> Remko
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> --
>>>>>>>>>>>>>> You received this message because you are subscribed to the
>>>>>>>>>>>>>> Google Groups "mechanical-sympathy" group.
>>>>>>>>>>>>>> To unsubscribe from this group and stop receiving emails from
>>>>>>>>>>>>>> it, send an email to
>>>>>>>>>>>>>> mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>>>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>> --
>>>>>>>>>>>>> You received this message because you are subscribed to the
>>>>>>>>>>>>> Google Groups "mechanical-sympathy" group.
>>>>>>>>>>>>> To unsubscribe from this group and stop receiving emails from
>>>>>>>>>>>>> it, send an email to
>>>>>>>>>>>>> mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>> --
>>>>>>> You received this message because you are subscribed to the Google
>>>>>>> Groups "mechanical-sympathy" group.
>>>>>>> To unsubscribe from this group and stop receiving emails from it,
>>>>>>> send an email to mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>
>>>>>>
>>>>>>
>>>>> --
>> You received this message because you are subscribed to the Google Groups
>> "mechanical-sympathy" group.
>> To unsubscribe from this group and stop receiving emails from it, send an
>> email to mechanical-sympathy+unsubscribe@googlegroups.com <javascript:>.
>> For more options, visit https://groups.google.com/d/optout.
>>
>
>
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
On Monday, May 23, 2016 at 2:47:05 AM UTC+9, Benedict Elliott Smith wrote:
>
> Your pride should be saved by your gracious recognition of the error :)
>
>
> However this is the core of my point: you’re clearly an intelligent,
> conscientious and talented developer, and yet you did not fully understand
> these concerns. You are writing core infrastructure many people will
> deploy, and a majority will understand it much much less well. So the very
> best thing you can do is to educate them. Doubly so if you needed
> educating yourself!
>
;-)
>
> I would make it very clear that users should only consider asynchronous
> logging if they are having performance problems caused by their logging.
> Only with sub-millisecond latency requirements should async be considered,
> and below 100 micros you are entering busy-spinning territory. Or if huge
> message rates are being seen. The best default is a blocking strategy, as
> this has the closest performance profile to synchronous, and will prevent
> the many users who deploy this without needing it from suffering any major
> ill-effect.
>
I think I missed a step here. You made it plausible that under low
workload, the Disruptor may not be better than ArrayBlockingQueue.
Understood.
But I don't understand why users should only configure async logging in
rare cases? Synchronous logging also involves holding a lock. Log4j 2 makes
an effort to release this lock as soon as possible (locking only while
copying a byte array from a thread-local buffer to the I/O device), but as
Martin pointed out, in addition to the lock contention, other things may
cause response time pauses when writing to the I/O device.
So which is "better": holding a lock to signal a
java.util.concurrent.locks.Condition, versus holding a lock to write a byte
array to the I/O device? The latter sounds like it has more risk of latency
spikes. So I'm not sure I agree with your assessment that async logging has
more risk of major ill effects.
Under low loads the upside of Async Loggers may not be as high as the graph
suggests but I don't see any real downsides either. Please let me know if
I'm missing something.
>
> I would also do a performance comparison with a real application.
> Cassandra uses log4j, and the community has an easily utilised performance
> tool. You could try both DEBUG and INFO level, and put up some graphs.
> This would help users make a more realistic and informed decision.
>
I agree it may be interesting for users to see a case study of some sort
with a real application. Can you point me to the tool you are referring to?
>
> This may all seem a little disappointing: to *reduce* the number of
> people who might use your amazing new technology. But there will be
> plenty, who both need it and do not and don't read or heed the warnings.
>
That's okay. It is garbage-free logging that is new in the 2.6 release, not
the Async Loggers. The Disruptor-based Async Loggers have been used in the
wild for about three years now. The response has generally been positive so
I'm not panicking just yet.
I do intend to follow up though and I take your point that under low load
this technology may not give as much benefit as under high load. (Again,
please correct me if there is a bigger problem and I'm missing any other
downsides/risks.)
>
> Regarding improvements: In my opinion, a better algorithm for this
> majority, of low-to-moderate traffic that is not extremely latency
> sensitive, is semi-synchronous. By which I mean for the first log call in
> a batch to take exclusive ownership of the output and to write its message
> synchronously; any messages that arrive while it has ownership are passed
> to the owner to persist, i.e. they are written asynchronously. To ensure
> any thread’s ownership is brief, it would impose a time-limit, after which
> a dedicated consumer could be started if the queue is still not exhausted.
> This would have better than synchronous behaviour for low-to-moderate
> traffic and scale gracefully to high traffic.
>
This is really interesting. It reminds me of one of the co-operative
algorithms I read about in the Art of Multiprocessor Programming (I tried
to look it up but could not find it last night).
It may be an idea to enhance the Disruptor for lower workloads: I guess the
question is whether it is possible to incorporate a cheap check before
calling waitStrategy.signalAllWhenBlocking() in MultiProducerSequence, and
avoid calling that method if another thread is already signalling the
consumer thread.
...and it turns out this already exists and is called
LiteBlockingWaitStrategy. Good stuff! Perhaps all that is needed is combine
the TimeoutBlockingWaitStrategy with this one and we can improve things
nicely for lower workloads.
Does anyone on this list have any experience with LiteBlockingWaitStrategy?
I see it was used in projectreactor.io, would be interested to hear how
that worked, either on list of off-list.
>
>
> On Sunday, 22 May 2016 16:40:21 UTC+1, Remko Popma wrote:
>>
>>
>>
>> On Sunday, May 22, 2016 at 11:08:37 PM UTC+9, Benedict Elliott Smith
>> wrote:
>>>
>>> It's possible I'm missing some other aspect that insulates the
>>> application thread from the disruptor, but from your message it seems to me
>>> that you fall into the all-too-common category of people who do not fully
>>> understand the semantics of the disruptor. Application threads (i.e.
>>> disruptor producers) very much *are* affected by the wait strategy.
>>> Under normal use, *if the disruptor consumer thread is employing a
>>> blocking strategy, there will be futex call to unblock it when work is
>>> provided*. i.e. whenever the queue transitions from empty to
>>> non-empty, i.e. for most messages with low-to-medium logging rates.
>>>
>>> In this situation the enqueueing of a message is also* not lock free*,
>>> as while futexes can in theory be lock-free, the JVM uses a lock to
>>> synchronise access to the semaphore that controls its runnable state, so
>>> all threads attempting to wake it up concurrently will compete for this
>>> lock.
>>>
>>
>> Well... Looks like you were right and I was wrong.
>>
>> Interesting. Apart from the dent in my pride here, this is actually good
>> news. It means we can do better!
>>
>> So in the worst-case scenario Async Loggers/Disruptor with the blocking
>> wait strategy give performance equivalent to AsyncAppender with a
>> BlockingArrayQueue. We can expect Async Loggers with Disruptor to
>> outperform AsyncAppender with BlockingArrayQueue when workloads are high or
>> bursts of work keep the background thread busy for some time. At least this
>> is my understanding now. Or did I miss something and are there cases where
>> Async Loggers with Disruptor will perform worse than AsyncAppender with
>> BlockingArrayQueue?
>>
>> In terms of how to improve, short-term we should probably look at using
>> the PhasedBackoffWaitStrategy as the default, although there will always be
>> workloads that "miss the window". The trade-off is increased CPU. We need
>> to tread carefully here because users reporting high CPU is why we changed
>> from the sleeping wait strategy to blocking. (The default in Log4j 2.6 will
>> be timeout blocking wait to deal with a deadlock issue in Solaris.)
>>
>> Long-term we should probably explore other data structures.
>>
>> Exciting times. Thanks for correcting me!
>>
>>
>>>
>>> On 22 May 2016 at 15:07, Benedict Elliott Smith <be...@apache.org>
>>> wrote:
>>>
>>>> It's possible I'm missing some other aspect that insulates the
>>>> application thread from the disruptor, but from your message it seems to me
>>>> that you fall into the all-too-common category of people who do not fully
>>>> understand the semantics of the disruptor. Application threads (i.e.
>>>> disruptor producers) very much *are* affected by the wait strategy.
>>>> Under normal use, *if the disruptor consumer thread is employing a
>>>> blocking strategy, there will be futex call to unblock it when work is
>>>> provided*. i.e. whenever the queue transitions from empty to
>>>> non-empty, i.e. for most messages with low-to-medium logging rates.
>>>>
>>>> In this situation the enqueueing of a message is also* not lock free*,
>>>> as while futexes can in theory be lock-free, the JVM uses a lock to
>>>> synchronise access to the semaphore that controls its runnable state, so
>>>> all threads attempting to wake it up concurrently will compete for this
>>>> lock.
>>>>
>>>>
>>>>
>>>> On 22 May 2016 at 14:42, Remko Popma <re...@gmail.com> wrote:
>>>>
>>>>>
>>>>>
>>>>> On Sunday, May 22, 2016 at 6:34:13 PM UTC+9, Benedict Elliott Smith
>>>>> wrote:
>>>>>>
>>>>>> Hi Remko,
>>>>>>
>>>>>> I realise that I was looking at the old log4j code without realising
>>>>>> it, in which there is always a futex involved.
>>>>>>
>>>>> Which class is this? Async Loggers in Log4j 2 have always been
>>>>> lock-free. What may be confusing is that Log4j 2 also has an Async
>>>>> *Appender*, which does not use the Disruptor but uses a JDK
>>>>> BlockingArrayQueue. This appender is very similar to how Logback and Log4j
>>>>> 1 do asynchronous logging. Async*Appender* (in Log4j 2, Log4j 1 and
>>>>> Logback, they all use a blocking queue) is sensitive to lock contention and
>>>>> does not scale with more threads.
>>>>>
>>>>>
>>>>>>
>>>>>> However the behaviour of the disruptor that backs the new code will
>>>>>> depend on the wait strategy employed (and I'll note your default is a
>>>>>> blocking strategy, for which my prior statement holds*).
>>>>>>
>>>>> Perhaps the key misunderstanding is here. I think I did not explain it
>>>>> well in my previous message. Let me try again.
>>>>>
>>>>> Async Loggers use the Disruptor and are lock-free. This means that
>>>>> multiple application threads can log concurrently and are not blocked by
>>>>> each other. This is true for very low workloads, medium workloads and high
>>>>> workloads.
>>>>>
>>>>> Only if an application logs messages at a very high rate for a long
>>>>> period of time, or uses a slow appender, the Disruptor ringbuffer can fill
>>>>> up and application threads will have to wait until a slot in the ringbuffer
>>>>> becomes available. For the 2.6 release I have added text to the
>>>>> Trade-offs section
>>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Trade-offs>
>>>>> to explain this last point, based on your feedback.
>>>>>
>>>>> Note that the Disruptor wait strategy is irrelevant to all this.
>>>>> Application threads are *not *impacted by the wait strategy.
>>>>>
>>>>>
>>>>>> Here we obviously get into the territory of people needing to
>>>>>> understand the disruptor as well as your logging framework, but since you
>>>>>> have a whole section labelled "Trade-offs" in which you draw attention to
>>>>>> the improved throughput and latency profile under "Benefits," under
>>>>>> "Drawbacks" it might be nice to mention these possible confounders. Or at
>>>>>> least raise a bat signal to go and understand the tradeoffs for the
>>>>>> disruptor (which is also regrettably poorly understood).
>>>>>>
>>>>>> It might also be helpful to explicitly call out the configuration
>>>>>> used for your benchmarks,
>>>>>>
>>>>> Tests on the 2.6 performance page
>>>>> <http://home.apache.org/~rpopma/log4j/2.6/performance.html> are
>>>>> mostly done with JMH benchmarks where parameters are in the javadoc.
>>>>> Tests on the Async Loggers page are partly with the new ResponseTimeTest
>>>>>
>>>>> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java>class
>>>>> (params in the doc
>>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Latency>)
>>>>> and partly still shows results from the older PerfTestDriver
>>>>> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTestDriver.java>
>>>>> class. This last one has parameters in the code. You'll need to spend some
>>>>> time to get familiar with it if you want to run it.
>>>>>
>>>>> and perhaps to run a comparison against some real software - github
>>>>>> does not lack for applications using log4j! Unfortunately I bet this would
>>>>>> result in a much less sexy graph.
>>>>>>
>>>>> Log4j 2 has had lock-free Async Loggers from its 2.0-beta5 release
>>>>> <http://logging.apache.org/log4j/2.x/changes-report.html#a2.0-beta5>,
>>>>> three years ago. If there are any serious performance drawbacks like you
>>>>> seem to think there are I hope I would have heard of them. Fortunately the
>>>>> opposite is true. People report very positive experiences
>>>>> <http://tech.finn.no/2014/07/01/log4j2-in-production-making-it-fly/>.
>>>>> People who did their own measurements reported it makes their logging as
>>>>> fast as if it was switched off
>>>>> <http://blogs.mulesoft.com/dev/mule-dev/mule-3-6-asynchronous-logging/>
>>>>> .
>>>>>
>>>>>
>>>>>> Finally, I really think people should (in your wiki page) explicitly
>>>>>> be *discouraged* from using this part of your framework *unless they
>>>>>> know they need it*. It's a fantastic piece of work for people who
>>>>>> *do* need it.
>>>>>>
>>>>> Again, I think you are laboring under a misapprehension. I cannot
>>>>> imagine a scenario where lock-free logging would be a bad thing. If you
>>>>> think there is, please show evidence.
>>>>>
>>>>>
>>>>>> But 99.99% of people would be better off with a logger that just
>>>>>> avoids blocking threads when one is already in the process of logging.
>>>>>>
>>>>> Avoiding blocking is exactly what the Async Loggers are for. (So I
>>>>> really think there is some misunderstanding somewhere.)
>>>>> Based on your feedback, I've updated
>>>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html> the side
>>>>> nav menu and page title for the 2.6 release to clarify that Async Loggers
>>>>> are lock-free. I hope this will help avoid misunderstandings.
>>>>>
>>>>>
>>>>>>
>>>>>> (*It looks like you silently ignore misconfiguration, and default to
>>>>>> timeout wait strategy also, which is probably going to surprise some people)
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> On 19 May 2016 at 00:34, Remko Popma <re...@gmail.com> wrote:
>>>>>>
>>>>>>> Benedict, thanks for your feedback!
>>>>>>>
>>>>>>> With regards to filtering, global filters are already considered
>>>>>>> before the event is enqueued. Filters configured on the Logger and
>>>>>>> AppenderRef are applied prior to enqueueing with mixed Sync/Async
>>>>>>> <http://logging.apache.org/log4j/2.x/manual/async.html#MixedSync-Async>
>>>>>>> Loggers but when all loggers are async
>>>>>>> <http://logging.apache.org/log4j/2.x/manual/async.html#AllAsync>
>>>>>>> these filters are applied by the background thread. We can probably improve
>>>>>>> this, thanks for the suggestion!
>>>>>>>
>>>>>>> Your suggestion to run performance tests under lower loads is
>>>>>>> reasonable and we will look at this for a future release.
>>>>>>> I did experiment with this a little a while back and did see larger
>>>>>>> response time pauses. Perhaps others with more experience can chime in.
>>>>>>>
>>>>>>> My understanding of how the Disruptor works is that enqueueing the
>>>>>>> event is lock-free, so applications threads doing the logging should not
>>>>>>> experience any context switches or suffer latency from Futex calls caused
>>>>>>> by logging (regardless of the workload). The background thread is another
>>>>>>> story. Under moderate to low workloads the background thread may (depending
>>>>>>> on the wait policy) fall asleep and experience delays before waking up when
>>>>>>> work arrives. However, if there are enough cores to serve all threads I
>>>>>>> don't see how such background thread delays can impact (cause response time
>>>>>>> pauses for) the application that is doing the logging. Please correct me if
>>>>>>> my understanding is incorrect.
>>>>>>>
>>>>>>> My thinking is that using async loggers is good for reactive
>>>>>>> applications that need to respond quickly to external events. It is
>>>>>>> especially useful if the application needs to deal with occasional bursts
>>>>>>> of work (and accompanied bursts of logging). This is where async loggers
>>>>>>> can deliver value even if the normal workload is low.
>>>>>>>
>>>>>>> Remko
>>>>>>>
>>>>>>> On Wednesday, May 18, 2016 at 2:56:18 AM UTC+9, Benedict Elliott
>>>>>>> Smith wrote:
>>>>>>>>
>>>>>>>> Regrettably it seems impossible (or at least very annoying) to send
>>>>>>>> to both lists simultaneously...
>>>>>>>>
>>>>>>>> On 17 May 2016 at 18:55, Benedict Elliott Smith <bene...@apache.org
>>>>>>>> > wrote:
>>>>>>>>
>>>>>>>>> Could I suggest that you run tests for latency and throughput
>>>>>>>>> effects of using this in systems with only moderate-to-low numbers of
>>>>>>>>> logging calls? (i.e. the vast majority of systems!)
>>>>>>>>>
>>>>>>>>
>>>>>>>>> It's very likely that in such systems messages will not reach a
>>>>>>>>> velocity to keep the Dispatcher running, and so logging calls may often (or
>>>>>>>>> always) involve a Futex call - which is not a trivial cost. There will
>>>>>>>>> almost certainly be systems out there with anti-ideal characteristics -
>>>>>>>>> logging just often enough that these costs materially impact throughput,
>>>>>>>>> but not often enough that they suddenly disappear.
>>>>>>>>>
>>>>>>>>> Even though a majority of systems *do not need this*, because it
>>>>>>>>> "async" and the new hotness, and there are no advertised downsides,
>>>>>>>>> everyone will try to use it. It's up to those who know better to make sure
>>>>>>>>> these people are informed it isn't a free lunch. Making sure all of the
>>>>>>>>> caveats are reported on the advertising page would be a great start IMO.
>>>>>>>>>
>>>>>>>>> Might I also separately suggest you consider filtering events
>>>>>>>>> prior to placing them on the queue for processing by the dispatcher? I've
>>>>>>>>> only briefly glanced at the code, but it seems not to be the case currently.
>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> On 17 May 2016 at 18:33, Martin Thompson <mj...@gmail.com>
>>>>>>>>>> wrote:
>>>>>>>>>>
>>>>>>>>>>> Hi Remko,
>>>>>>>>>>>
>>>>>>>>>>> I'd just like to say that it is a great service to the community
>>>>>>>>>>> as a whole that someone is seriously looking at improving logging.
>>>>>>>>>>>
>>>>>>>>>>> If you keep it up you'll be putting folks like me out of a job :)
>>>>>>>>>>>
>>>>>>>>>>> Martin...
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> On 17 May 2016 at 18:13, Remko Popma <re...@gmail.com> wrote:
>>>>>>>>>>>
>>>>>>>>>>>> Hi all,
>>>>>>>>>>>>
>>>>>>>>>>>> First, my thanks to the many people who gave helpful advice and
>>>>>>>>>>>> feedback on how to measure Log4j response time on this list some time ago.
>>>>>>>>>>>>
>>>>>>>>>>>> We're about to start the Log4j 2.6 release.
>>>>>>>>>>>> If anyone is interested, a preview of the garbage-free logging
>>>>>>>>>>>> manual page is here:
>>>>>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>>>>>>>>>>>> and a preview of the updated performance page is here:
>>>>>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>>>>>>>>>
>>>>>>>>>>>> Feedback welcome!
>>>>>>>>>>>>
>>>>>>>>>>>> Remko
>>>>>>>>>>>>
>>>>>>>>>>>> --
>>>>>>>>>>>> You received this message because you are subscribed to the
>>>>>>>>>>>> Google Groups "mechanical-sympathy" group.
>>>>>>>>>>>> To unsubscribe from this group and stop receiving emails from
>>>>>>>>>>>> it, send an email to
>>>>>>>>>>>> mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> --
>>>>>>>>>>> You received this message because you are subscribed to the
>>>>>>>>>>> Google Groups "mechanical-sympathy" group.
>>>>>>>>>>> To unsubscribe from this group and stop receiving emails from
>>>>>>>>>>> it, send an email to
>>>>>>>>>>> mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>> --
>>>>> You received this message because you are subscribed to the Google
>>>>> Groups "mechanical-sympathy" group.
>>>>> To unsubscribe from this group and stop receiving emails from it, send
>>>>> an email to mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>
>>>>
>>>>
>>>
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
On Sunday, May 22, 2016 at 11:08:37 PM UTC+9, Benedict Elliott Smith wrote:
>
> It's possible I'm missing some other aspect that insulates the application
> thread from the disruptor, but from your message it seems to me that you
> fall into the all-too-common category of people who do not fully understand
> the semantics of the disruptor. Application threads (i.e. disruptor
> producers) very much *are* affected by the wait strategy. Under normal
> use, *if the disruptor consumer thread is employing a blocking strategy,
> there will be futex call to unblock it when work is provided*. i.e.
> whenever the queue transitions from empty to non-empty, i.e. for most
> messages with low-to-medium logging rates.
>
> In this situation the enqueueing of a message is also* not lock free*, as
> while futexes can in theory be lock-free, the JVM uses a lock to
> synchronise access to the semaphore that controls its runnable state, so
> all threads attempting to wake it up concurrently will compete for this
> lock.
>
Well... Looks like you were right and I was wrong.
Interesting. Apart from the dent in my pride here, this is actually good
news. It means we can do better!
So in the worst-case scenario Async Loggers/Disruptor with the blocking
wait strategy give performance equivalent to AsyncAppender with a
BlockingArrayQueue. We can expect Async Loggers with Disruptor to
outperform AsyncAppender with BlockingArrayQueue when workloads are high or
bursts of work keep the background thread busy for some time. At least this
is my understanding now. Or did I miss something and are there cases where
Async Loggers with Disruptor will perform worse than AsyncAppender with
BlockingArrayQueue?
In terms of how to improve, short-term we should probably look at using
the PhasedBackoffWaitStrategy as the default, although there will always be
workloads that "miss the window". The trade-off is increased CPU. We need
to tread carefully here because users reporting high CPU is why we changed
from the sleeping wait strategy to blocking. (The default in Log4j 2.6 will
be timeout blocking wait to deal with a deadlock issue in Solaris.)
Long-term we should probably explore other data structures.
Exciting times. Thanks for correcting me!
>
> On 22 May 2016 at 15:07, Benedict Elliott Smith <bene...@apache.org
> <javascript:>> wrote:
>
>> It's possible I'm missing some other aspect that insulates the
>> application thread from the disruptor, but from your message it seems to me
>> that you fall into the all-too-common category of people who do not fully
>> understand the semantics of the disruptor. Application threads (i.e.
>> disruptor producers) very much *are* affected by the wait strategy.
>> Under normal use, *if the disruptor consumer thread is employing a
>> blocking strategy, there will be futex call to unblock it when work is
>> provided*. i.e. whenever the queue transitions from empty to non-empty,
>> i.e. for most messages with low-to-medium logging rates.
>>
>> In this situation the enqueueing of a message is also* not lock free*,
>> as while futexes can in theory be lock-free, the JVM uses a lock to
>> synchronise access to the semaphore that controls its runnable state, so
>> all threads attempting to wake it up concurrently will compete for this
>> lock.
>>
>>
>>
>> On 22 May 2016 at 14:42, Remko Popma <remko...@gmail.com <javascript:>>
>> wrote:
>>
>>>
>>>
>>> On Sunday, May 22, 2016 at 6:34:13 PM UTC+9, Benedict Elliott Smith
>>> wrote:
>>>>
>>>> Hi Remko,
>>>>
>>>> I realise that I was looking at the old log4j code without realising
>>>> it, in which there is always a futex involved.
>>>>
>>> Which class is this? Async Loggers in Log4j 2 have always been
>>> lock-free. What may be confusing is that Log4j 2 also has an Async
>>> *Appender*, which does not use the Disruptor but uses a JDK
>>> BlockingArrayQueue. This appender is very similar to how Logback and Log4j
>>> 1 do asynchronous logging. Async*Appender* (in Log4j 2, Log4j 1 and
>>> Logback, they all use a blocking queue) is sensitive to lock contention and
>>> does not scale with more threads.
>>>
>>>
>>>>
>>>> However the behaviour of the disruptor that backs the new code will
>>>> depend on the wait strategy employed (and I'll note your default is a
>>>> blocking strategy, for which my prior statement holds*).
>>>>
>>> Perhaps the key misunderstanding is here. I think I did not explain it
>>> well in my previous message. Let me try again.
>>>
>>> Async Loggers use the Disruptor and are lock-free. This means that
>>> multiple application threads can log concurrently and are not blocked by
>>> each other. This is true for very low workloads, medium workloads and high
>>> workloads.
>>>
>>> Only if an application logs messages at a very high rate for a long
>>> period of time, or uses a slow appender, the Disruptor ringbuffer can fill
>>> up and application threads will have to wait until a slot in the ringbuffer
>>> becomes available. For the 2.6 release I have added text to the
>>> Trade-offs section
>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Trade-offs>
>>> to explain this last point, based on your feedback.
>>>
>>> Note that the Disruptor wait strategy is irrelevant to all this.
>>> Application threads are *not *impacted by the wait strategy.
>>>
>>>
>>>> Here we obviously get into the territory of people needing to
>>>> understand the disruptor as well as your logging framework, but since you
>>>> have a whole section labelled "Trade-offs" in which you draw attention to
>>>> the improved throughput and latency profile under "Benefits," under
>>>> "Drawbacks" it might be nice to mention these possible confounders. Or at
>>>> least raise a bat signal to go and understand the tradeoffs for the
>>>> disruptor (which is also regrettably poorly understood).
>>>>
>>>> It might also be helpful to explicitly call out the configuration used
>>>> for your benchmarks,
>>>>
>>> Tests on the 2.6 performance page
>>> <http://home.apache.org/~rpopma/log4j/2.6/performance.html> are mostly
>>> done with JMH benchmarks where parameters are in the javadoc.
>>> Tests on the Async Loggers page are partly with the new ResponseTimeTest
>>>
>>> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java>class
>>> (params in the doc
>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Latency>)
>>> and partly still shows results from the older PerfTestDriver
>>> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTestDriver.java>
>>> class. This last one has parameters in the code. You'll need to spend some
>>> time to get familiar with it if you want to run it.
>>>
>>> and perhaps to run a comparison against some real software - github does
>>>> not lack for applications using log4j! Unfortunately I bet this would
>>>> result in a much less sexy graph.
>>>>
>>> Log4j 2 has had lock-free Async Loggers from its 2.0-beta5 release
>>> <http://logging.apache.org/log4j/2.x/changes-report.html#a2.0-beta5>,
>>> three years ago. If there are any serious performance drawbacks like you
>>> seem to think there are I hope I would have heard of them. Fortunately the
>>> opposite is true. People report very positive experiences
>>> <http://tech.finn.no/2014/07/01/log4j2-in-production-making-it-fly/>.
>>> People who did their own measurements reported it makes their logging as
>>> fast as if it was switched off
>>> <http://blogs.mulesoft.com/dev/mule-dev/mule-3-6-asynchronous-logging/>.
>>>
>>>
>>>> Finally, I really think people should (in your wiki page) explicitly be
>>>> *discouraged* from using this part of your framework *unless they know
>>>> they need it*. It's a fantastic piece of work for people who *do* need
>>>> it.
>>>>
>>> Again, I think you are laboring under a misapprehension. I cannot
>>> imagine a scenario where lock-free logging would be a bad thing. If you
>>> think there is, please show evidence.
>>>
>>>
>>>> But 99.99% of people would be better off with a logger that just avoids
>>>> blocking threads when one is already in the process of logging.
>>>>
>>> Avoiding blocking is exactly what the Async Loggers are for. (So I
>>> really think there is some misunderstanding somewhere.)
>>> Based on your feedback, I've updated
>>> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html> the side
>>> nav menu and page title for the 2.6 release to clarify that Async Loggers
>>> are lock-free. I hope this will help avoid misunderstandings.
>>>
>>>
>>>>
>>>> (*It looks like you silently ignore misconfiguration, and default to
>>>> timeout wait strategy also, which is probably going to surprise some people)
>>>>
>>>>
>>>>
>>>>
>>>>
>>>> On 19 May 2016 at 00:34, Remko Popma <re...@gmail.com> wrote:
>>>>
>>>>> Benedict, thanks for your feedback!
>>>>>
>>>>> With regards to filtering, global filters are already considered
>>>>> before the event is enqueued. Filters configured on the Logger and
>>>>> AppenderRef are applied prior to enqueueing with mixed Sync/Async
>>>>> <http://logging.apache.org/log4j/2.x/manual/async.html#MixedSync-Async>
>>>>> Loggers but when all loggers are async
>>>>> <http://logging.apache.org/log4j/2.x/manual/async.html#AllAsync>
>>>>> these filters are applied by the background thread. We can probably improve
>>>>> this, thanks for the suggestion!
>>>>>
>>>>> Your suggestion to run performance tests under lower loads is
>>>>> reasonable and we will look at this for a future release.
>>>>> I did experiment with this a little a while back and did see larger
>>>>> response time pauses. Perhaps others with more experience can chime in.
>>>>>
>>>>> My understanding of how the Disruptor works is that enqueueing the
>>>>> event is lock-free, so applications threads doing the logging should not
>>>>> experience any context switches or suffer latency from Futex calls caused
>>>>> by logging (regardless of the workload). The background thread is another
>>>>> story. Under moderate to low workloads the background thread may (depending
>>>>> on the wait policy) fall asleep and experience delays before waking up when
>>>>> work arrives. However, if there are enough cores to serve all threads I
>>>>> don't see how such background thread delays can impact (cause response time
>>>>> pauses for) the application that is doing the logging. Please correct me if
>>>>> my understanding is incorrect.
>>>>>
>>>>> My thinking is that using async loggers is good for reactive
>>>>> applications that need to respond quickly to external events. It is
>>>>> especially useful if the application needs to deal with occasional bursts
>>>>> of work (and accompanied bursts of logging). This is where async loggers
>>>>> can deliver value even if the normal workload is low.
>>>>>
>>>>> Remko
>>>>>
>>>>> On Wednesday, May 18, 2016 at 2:56:18 AM UTC+9, Benedict Elliott Smith
>>>>> wrote:
>>>>>>
>>>>>> Regrettably it seems impossible (or at least very annoying) to send
>>>>>> to both lists simultaneously...
>>>>>>
>>>>>> On 17 May 2016 at 18:55, Benedict Elliott Smith <be...@apache.org>
>>>>>> wrote:
>>>>>>
>>>>>>> Could I suggest that you run tests for latency and throughput
>>>>>>> effects of using this in systems with only moderate-to-low numbers of
>>>>>>> logging calls? (i.e. the vast majority of systems!)
>>>>>>>
>>>>>>
>>>>>>> It's very likely that in such systems messages will not reach a
>>>>>>> velocity to keep the Dispatcher running, and so logging calls may often (or
>>>>>>> always) involve a Futex call - which is not a trivial cost. There will
>>>>>>> almost certainly be systems out there with anti-ideal characteristics -
>>>>>>> logging just often enough that these costs materially impact throughput,
>>>>>>> but not often enough that they suddenly disappear.
>>>>>>>
>>>>>>> Even though a majority of systems *do not need this*, because it
>>>>>>> "async" and the new hotness, and there are no advertised downsides,
>>>>>>> everyone will try to use it. It's up to those who know better to make sure
>>>>>>> these people are informed it isn't a free lunch. Making sure all of the
>>>>>>> caveats are reported on the advertising page would be a great start IMO.
>>>>>>>
>>>>>>> Might I also separately suggest you consider filtering events prior
>>>>>>> to placing them on the queue for processing by the dispatcher? I've only
>>>>>>> briefly glanced at the code, but it seems not to be the case currently.
>>>>>>>
>>>>>>>>
>>>>>>>> On 17 May 2016 at 18:33, Martin Thompson <mj...@gmail.com> wrote:
>>>>>>>>
>>>>>>>>> Hi Remko,
>>>>>>>>>
>>>>>>>>> I'd just like to say that it is a great service to the community
>>>>>>>>> as a whole that someone is seriously looking at improving logging.
>>>>>>>>>
>>>>>>>>> If you keep it up you'll be putting folks like me out of a job :)
>>>>>>>>>
>>>>>>>>> Martin...
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> On 17 May 2016 at 18:13, Remko Popma <re...@gmail.com> wrote:
>>>>>>>>>
>>>>>>>>>> Hi all,
>>>>>>>>>>
>>>>>>>>>> First, my thanks to the many people who gave helpful advice and
>>>>>>>>>> feedback on how to measure Log4j response time on this list some time ago.
>>>>>>>>>>
>>>>>>>>>> We're about to start the Log4j 2.6 release.
>>>>>>>>>> If anyone is interested, a preview of the garbage-free logging
>>>>>>>>>> manual page is here:
>>>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>>>>>>>>>> and a preview of the updated performance page is here:
>>>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>>>>>>>
>>>>>>>>>> Feedback welcome!
>>>>>>>>>>
>>>>>>>>>> Remko
>>>>>>>>>>
>>>>>>>>>> --
>>>>>>>>>> You received this message because you are subscribed to the
>>>>>>>>>> Google Groups "mechanical-sympathy" group.
>>>>>>>>>> To unsubscribe from this group and stop receiving emails from it,
>>>>>>>>>> send an email to mechanical-sympathy+unsubscribe@googlegroups.com
>>>>>>>>>> .
>>>>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>> --
>>>>>>>>> You received this message because you are subscribed to the Google
>>>>>>>>> Groups "mechanical-sympathy" group.
>>>>>>>>> To unsubscribe from this group and stop receiving emails from it,
>>>>>>>>> send an email to mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>
>>>> --
>>> You received this message because you are subscribed to the Google
>>> Groups "mechanical-sympathy" group.
>>> To unsubscribe from this group and stop receiving emails from it, send
>>> an email to mechanical-sympathy+unsubscribe@googlegroups.com
>>> <javascript:>.
>>> For more options, visit https://groups.google.com/d/optout.
>>>
>>
>>
>
Re: Garbage-free Log4j docs preview
Posted by Benedict Elliott Smith <be...@apache.org>.
It's possible I'm missing some other aspect that insulates the application
thread from the disruptor, but from your message it seems to me that you
fall into the all-too-common category of people who do not fully understand
the semantics of the disruptor. Application threads (i.e. disruptor
producers) very much *are* affected by the wait strategy. Under normal
use, *if the disruptor consumer thread is employing a blocking strategy,
there will be futex call to unblock it when work is provided*. i.e.
whenever the queue transitions from empty to non-empty, i.e. for most
messages with low-to-medium logging rates.
In this situation the enqueueing of a message is also* not lock free*, as
while futexes can in theory be lock-free, the JVM uses a lock to
synchronise access to the semaphore that controls its runnable state, so
all threads attempting to wake it up concurrently will compete for this
lock.
On 22 May 2016 at 14:42, Remko Popma <re...@gmail.com> wrote:
>
>
> On Sunday, May 22, 2016 at 6:34:13 PM UTC+9, Benedict Elliott Smith wrote:
>>
>> Hi Remko,
>>
>> I realise that I was looking at the old log4j code without realising it,
>> in which there is always a futex involved.
>>
> Which class is this? Async Loggers in Log4j 2 have always been lock-free.
> What may be confusing is that Log4j 2 also has an Async*Appender*, which
> does not use the Disruptor but uses a JDK BlockingArrayQueue. This appender
> is very similar to how Logback and Log4j 1 do asynchronous logging. Async
> *Appender* (in Log4j 2, Log4j 1 and Logback, they all use a blocking
> queue) is sensitive to lock contention and does not scale with more threads.
>
>
>>
>> However the behaviour of the disruptor that backs the new code will
>> depend on the wait strategy employed (and I'll note your default is a
>> blocking strategy, for which my prior statement holds*).
>>
> Perhaps the key misunderstanding is here. I think I did not explain it
> well in my previous message. Let me try again.
>
> Async Loggers use the Disruptor and are lock-free. This means that
> multiple application threads can log concurrently and are not blocked by
> each other. This is true for very low workloads, medium workloads and high
> workloads.
>
> Only if an application logs messages at a very high rate for a long period
> of time, or uses a slow appender, the Disruptor ringbuffer can fill up and
> application threads will have to wait until a slot in the ringbuffer
> becomes available. For the 2.6 release I have added text to the
> Trade-offs section
> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Trade-offs>
> to explain this last point, based on your feedback.
>
> Note that the Disruptor wait strategy is irrelevant to all this.
> Application threads are *not *impacted by the wait strategy.
>
>
>> Here we obviously get into the territory of people needing to understand
>> the disruptor as well as your logging framework, but since you have a whole
>> section labelled "Trade-offs" in which you draw attention to the improved
>> throughput and latency profile under "Benefits," under "Drawbacks" it might
>> be nice to mention these possible confounders. Or at least raise a bat
>> signal to go and understand the tradeoffs for the disruptor (which is also
>> regrettably poorly understood).
>>
>> It might also be helpful to explicitly call out the configuration used
>> for your benchmarks,
>>
> Tests on the 2.6 performance page
> <http://home.apache.org/~rpopma/log4j/2.6/performance.html> are mostly
> done with JMH benchmarks where parameters are in the javadoc.
> Tests on the Async Loggers page are partly with the new ResponseTimeTest
> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java>class
> (params in the doc
> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Latency>) and
> partly still shows results from the older PerfTestDriver
> <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTestDriver.java>
> class. This last one has parameters in the code. You'll need to spend some
> time to get familiar with it if you want to run it.
>
> and perhaps to run a comparison against some real software - github does
>> not lack for applications using log4j! Unfortunately I bet this would
>> result in a much less sexy graph.
>>
> Log4j 2 has had lock-free Async Loggers from its 2.0-beta5 release
> <http://logging.apache.org/log4j/2.x/changes-report.html#a2.0-beta5>,
> three years ago. If there are any serious performance drawbacks like you
> seem to think there are I hope I would have heard of them. Fortunately the
> opposite is true. People report very positive experiences
> <http://tech.finn.no/2014/07/01/log4j2-in-production-making-it-fly/>.
> People who did their own measurements reported it makes their logging as
> fast as if it was switched off
> <http://blogs.mulesoft.com/dev/mule-dev/mule-3-6-asynchronous-logging/>.
>
>
>> Finally, I really think people should (in your wiki page) explicitly be
>> *discouraged* from using this part of your framework *unless they know
>> they need it*. It's a fantastic piece of work for people who *do* need
>> it.
>>
> Again, I think you are laboring under a misapprehension. I cannot imagine
> a scenario where lock-free logging would be a bad thing. If you think there
> is, please show evidence.
>
>
>> But 99.99% of people would be better off with a logger that just avoids
>> blocking threads when one is already in the process of logging.
>>
> Avoiding blocking is exactly what the Async Loggers are for. (So I really
> think there is some misunderstanding somewhere.)
> Based on your feedback, I've updated
> <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html> the side nav
> menu and page title for the 2.6 release to clarify that Async Loggers are
> lock-free. I hope this will help avoid misunderstandings.
>
>
>>
>> (*It looks like you silently ignore misconfiguration, and default to
>> timeout wait strategy also, which is probably going to surprise some people)
>>
>>
>>
>>
>>
>> On 19 May 2016 at 00:34, Remko Popma <re...@gmail.com> wrote:
>>
>>> Benedict, thanks for your feedback!
>>>
>>> With regards to filtering, global filters are already considered before
>>> the event is enqueued. Filters configured on the Logger and AppenderRef are
>>> applied prior to enqueueing with mixed Sync/Async
>>> <http://logging.apache.org/log4j/2.x/manual/async.html#MixedSync-Async>
>>> Loggers but when all loggers are async
>>> <http://logging.apache.org/log4j/2.x/manual/async.html#AllAsync> these
>>> filters are applied by the background thread. We can probably improve this,
>>> thanks for the suggestion!
>>>
>>> Your suggestion to run performance tests under lower loads is reasonable
>>> and we will look at this for a future release.
>>> I did experiment with this a little a while back and did see larger
>>> response time pauses. Perhaps others with more experience can chime in.
>>>
>>> My understanding of how the Disruptor works is that enqueueing the event
>>> is lock-free, so applications threads doing the logging should not
>>> experience any context switches or suffer latency from Futex calls caused
>>> by logging (regardless of the workload). The background thread is another
>>> story. Under moderate to low workloads the background thread may (depending
>>> on the wait policy) fall asleep and experience delays before waking up when
>>> work arrives. However, if there are enough cores to serve all threads I
>>> don't see how such background thread delays can impact (cause response time
>>> pauses for) the application that is doing the logging. Please correct me if
>>> my understanding is incorrect.
>>>
>>> My thinking is that using async loggers is good for reactive
>>> applications that need to respond quickly to external events. It is
>>> especially useful if the application needs to deal with occasional bursts
>>> of work (and accompanied bursts of logging). This is where async loggers
>>> can deliver value even if the normal workload is low.
>>>
>>> Remko
>>>
>>> On Wednesday, May 18, 2016 at 2:56:18 AM UTC+9, Benedict Elliott Smith
>>> wrote:
>>>>
>>>> Regrettably it seems impossible (or at least very annoying) to send to
>>>> both lists simultaneously...
>>>>
>>>> On 17 May 2016 at 18:55, Benedict Elliott Smith <be...@apache.org>
>>>> wrote:
>>>>
>>>>> Could I suggest that you run tests for latency and throughput effects
>>>>> of using this in systems with only moderate-to-low numbers of logging
>>>>> calls? (i.e. the vast majority of systems!)
>>>>>
>>>>
>>>>> It's very likely that in such systems messages will not reach a
>>>>> velocity to keep the Dispatcher running, and so logging calls may often (or
>>>>> always) involve a Futex call - which is not a trivial cost. There will
>>>>> almost certainly be systems out there with anti-ideal characteristics -
>>>>> logging just often enough that these costs materially impact throughput,
>>>>> but not often enough that they suddenly disappear.
>>>>>
>>>>> Even though a majority of systems *do not need this*, because it
>>>>> "async" and the new hotness, and there are no advertised downsides,
>>>>> everyone will try to use it. It's up to those who know better to make sure
>>>>> these people are informed it isn't a free lunch. Making sure all of the
>>>>> caveats are reported on the advertising page would be a great start IMO.
>>>>>
>>>>> Might I also separately suggest you consider filtering events prior to
>>>>> placing them on the queue for processing by the dispatcher? I've only
>>>>> briefly glanced at the code, but it seems not to be the case currently.
>>>>>
>>>>>>
>>>>>> On 17 May 2016 at 18:33, Martin Thompson <mj...@gmail.com> wrote:
>>>>>>
>>>>>>> Hi Remko,
>>>>>>>
>>>>>>> I'd just like to say that it is a great service to the community as
>>>>>>> a whole that someone is seriously looking at improving logging.
>>>>>>>
>>>>>>> If you keep it up you'll be putting folks like me out of a job :)
>>>>>>>
>>>>>>> Martin...
>>>>>>>
>>>>>>>
>>>>>>> On 17 May 2016 at 18:13, Remko Popma <re...@gmail.com> wrote:
>>>>>>>
>>>>>>>> Hi all,
>>>>>>>>
>>>>>>>> First, my thanks to the many people who gave helpful advice and
>>>>>>>> feedback on how to measure Log4j response time on this list some time ago.
>>>>>>>>
>>>>>>>> We're about to start the Log4j 2.6 release.
>>>>>>>> If anyone is interested, a preview of the garbage-free logging
>>>>>>>> manual page is here:
>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>>>>>>>> and a preview of the updated performance page is here:
>>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>>>>>
>>>>>>>> Feedback welcome!
>>>>>>>>
>>>>>>>> Remko
>>>>>>>>
>>>>>>>> --
>>>>>>>> You received this message because you are subscribed to the Google
>>>>>>>> Groups "mechanical-sympathy" group.
>>>>>>>> To unsubscribe from this group and stop receiving emails from it,
>>>>>>>> send an email to mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>>
>>>>>>>
>>>>>>> --
>>>>>>> You received this message because you are subscribed to the Google
>>>>>>> Groups "mechanical-sympathy" group.
>>>>>>> To unsubscribe from this group and stop receiving emails from it,
>>>>>>> send an email to mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>
>>>>>>
>>>>>>
>>>>>
>>>>
>> --
> You received this message because you are subscribed to the Google Groups
> "mechanical-sympathy" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to mechanical-sympathy+unsubscribe@googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.
>
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
On Sunday, May 22, 2016 at 6:34:13 PM UTC+9, Benedict Elliott Smith wrote:
>
> Hi Remko,
>
> I realise that I was looking at the old log4j code without realising it,
> in which there is always a futex involved.
>
Which class is this? Async Loggers in Log4j 2 have always been lock-free.
What may be confusing is that Log4j 2 also has an Async*Appender*, which
does not use the Disruptor but uses a JDK BlockingArrayQueue. This appender
is very similar to how Logback and Log4j 1 do asynchronous logging. Async
*Appender* (in Log4j 2, Log4j 1 and Logback, they all use a blocking queue)
is sensitive to lock contention and does not scale with more threads.
>
> However the behaviour of the disruptor that backs the new code will depend
> on the wait strategy employed (and I'll note your default is a blocking
> strategy, for which my prior statement holds*).
>
Perhaps the key misunderstanding is here. I think I did not explain it well
in my previous message. Let me try again.
Async Loggers use the Disruptor and are lock-free. This means that multiple
application threads can log concurrently and are not blocked by each other.
This is true for very low workloads, medium workloads and high workloads.
Only if an application logs messages at a very high rate for a long period
of time, or uses a slow appender, the Disruptor ringbuffer can fill up and
application threads will have to wait until a slot in the ringbuffer
becomes available. For the 2.6 release I have added text to the Trade-offs
section
<http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Trade-offs> to
explain this last point, based on your feedback.
Note that the Disruptor wait strategy is irrelevant to all this.
Application threads are *not *impacted by the wait strategy.
> Here we obviously get into the territory of people needing to understand
> the disruptor as well as your logging framework, but since you have a whole
> section labelled "Trade-offs" in which you draw attention to the improved
> throughput and latency profile under "Benefits," under "Drawbacks" it might
> be nice to mention these possible confounders. Or at least raise a bat
> signal to go and understand the tradeoffs for the disruptor (which is also
> regrettably poorly understood).
>
> It might also be helpful to explicitly call out the configuration used for
> your benchmarks,
>
Tests on the 2.6 performance page
<http://home.apache.org/~rpopma/log4j/2.6/performance.html> are mostly done
with JMH benchmarks where parameters are in the javadoc.
Tests on the Async Loggers page are partly with the new ResponseTimeTest
<https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java>class
(params in the doc
<http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Latency>) and
partly still shows results from the older PerfTestDriver
<https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTestDriver.java>
class. This last one has parameters in the code. You'll need to spend some
time to get familiar with it if you want to run it.
and perhaps to run a comparison against some real software - github does
> not lack for applications using log4j! Unfortunately I bet this would
> result in a much less sexy graph.
>
Log4j 2 has had lock-free Async Loggers from its 2.0-beta5 release
<http://logging.apache.org/log4j/2.x/changes-report.html#a2.0-beta5>, three
years ago. If there are any serious performance drawbacks like you seem to
think there are I hope I would have heard of them. Fortunately the opposite
is true. People report very positive experiences
<http://tech.finn.no/2014/07/01/log4j2-in-production-making-it-fly/>.
People who did their own measurements reported it makes their logging as
fast as if it was switched off
<http://blogs.mulesoft.com/dev/mule-dev/mule-3-6-asynchronous-logging/>.
> Finally, I really think people should (in your wiki page) explicitly be
> *discouraged* from using this part of your framework *unless they know
> they need it*. It's a fantastic piece of work for people who *do* need
> it.
>
Again, I think you are laboring under a misapprehension. I cannot imagine a
scenario where lock-free logging would be a bad thing. If you think there
is, please show evidence.
> But 99.99% of people would be better off with a logger that just avoids
> blocking threads when one is already in the process of logging.
>
Avoiding blocking is exactly what the Async Loggers are for. (So I really
think there is some misunderstanding somewhere.)
Based on your feedback, I've updated
<http://home.apache.org/~rpopma/log4j/2.6/manual/async.html> the side nav
menu and page title for the 2.6 release to clarify that Async Loggers are
lock-free. I hope this will help avoid misunderstandings.
>
> (*It looks like you silently ignore misconfiguration, and default to
> timeout wait strategy also, which is probably going to surprise some people)
>
>
>
>
>
> On 19 May 2016 at 00:34, Remko Popma <remko...@gmail.com <javascript:>>
> wrote:
>
>> Benedict, thanks for your feedback!
>>
>> With regards to filtering, global filters are already considered before
>> the event is enqueued. Filters configured on the Logger and AppenderRef are
>> applied prior to enqueueing with mixed Sync/Async
>> <http://logging.apache.org/log4j/2.x/manual/async.html#MixedSync-Async>
>> Loggers but when all loggers are async
>> <http://logging.apache.org/log4j/2.x/manual/async.html#AllAsync> these
>> filters are applied by the background thread. We can probably improve this,
>> thanks for the suggestion!
>>
>> Your suggestion to run performance tests under lower loads is reasonable
>> and we will look at this for a future release.
>> I did experiment with this a little a while back and did see larger
>> response time pauses. Perhaps others with more experience can chime in.
>>
>> My understanding of how the Disruptor works is that enqueueing the event
>> is lock-free, so applications threads doing the logging should not
>> experience any context switches or suffer latency from Futex calls caused
>> by logging (regardless of the workload). The background thread is another
>> story. Under moderate to low workloads the background thread may (depending
>> on the wait policy) fall asleep and experience delays before waking up when
>> work arrives. However, if there are enough cores to serve all threads I
>> don't see how such background thread delays can impact (cause response time
>> pauses for) the application that is doing the logging. Please correct me if
>> my understanding is incorrect.
>>
>> My thinking is that using async loggers is good for reactive applications
>> that need to respond quickly to external events. It is especially useful if
>> the application needs to deal with occasional bursts of work (and
>> accompanied bursts of logging). This is where async loggers can deliver
>> value even if the normal workload is low.
>>
>> Remko
>>
>> On Wednesday, May 18, 2016 at 2:56:18 AM UTC+9, Benedict Elliott Smith
>> wrote:
>>>
>>> Regrettably it seems impossible (or at least very annoying) to send to
>>> both lists simultaneously...
>>>
>>> On 17 May 2016 at 18:55, Benedict Elliott Smith <be...@apache.org>
>>> wrote:
>>>
>>>> Could I suggest that you run tests for latency and throughput effects
>>>> of using this in systems with only moderate-to-low numbers of logging
>>>> calls? (i.e. the vast majority of systems!)
>>>>
>>>
>>>> It's very likely that in such systems messages will not reach a
>>>> velocity to keep the Dispatcher running, and so logging calls may often (or
>>>> always) involve a Futex call - which is not a trivial cost. There will
>>>> almost certainly be systems out there with anti-ideal characteristics -
>>>> logging just often enough that these costs materially impact throughput,
>>>> but not often enough that they suddenly disappear.
>>>>
>>>> Even though a majority of systems *do not need this*, because it
>>>> "async" and the new hotness, and there are no advertised downsides,
>>>> everyone will try to use it. It's up to those who know better to make sure
>>>> these people are informed it isn't a free lunch. Making sure all of the
>>>> caveats are reported on the advertising page would be a great start IMO.
>>>>
>>>> Might I also separately suggest you consider filtering events prior to
>>>> placing them on the queue for processing by the dispatcher? I've only
>>>> briefly glanced at the code, but it seems not to be the case currently.
>>>>
>>>>>
>>>>> On 17 May 2016 at 18:33, Martin Thompson <mj...@gmail.com> wrote:
>>>>>
>>>>>> Hi Remko,
>>>>>>
>>>>>> I'd just like to say that it is a great service to the community as a
>>>>>> whole that someone is seriously looking at improving logging.
>>>>>>
>>>>>> If you keep it up you'll be putting folks like me out of a job :)
>>>>>>
>>>>>> Martin...
>>>>>>
>>>>>>
>>>>>> On 17 May 2016 at 18:13, Remko Popma <re...@gmail.com> wrote:
>>>>>>
>>>>>>> Hi all,
>>>>>>>
>>>>>>> First, my thanks to the many people who gave helpful advice and
>>>>>>> feedback on how to measure Log4j response time on this list some time ago.
>>>>>>>
>>>>>>> We're about to start the Log4j 2.6 release.
>>>>>>> If anyone is interested, a preview of the garbage-free logging
>>>>>>> manual page is here:
>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>>>>>>> and a preview of the updated performance page is here:
>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>>>>
>>>>>>> Feedback welcome!
>>>>>>>
>>>>>>> Remko
>>>>>>>
>>>>>>> --
>>>>>>> You received this message because you are subscribed to the Google
>>>>>>> Groups "mechanical-sympathy" group.
>>>>>>> To unsubscribe from this group and stop receiving emails from it,
>>>>>>> send an email to mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>>
>>>>>>
>>>>>> --
>>>>>> You received this message because you are subscribed to the Google
>>>>>> Groups "mechanical-sympathy" group.
>>>>>> To unsubscribe from this group and stop receiving emails from it,
>>>>>> send an email to mechanical-sympathy+unsubscribe@googlegroups.com.
>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>
>>>>>
>>>>>
>>>>
>>>
>
Re: Garbage-free Log4j docs preview
Posted by Remko Popma <re...@gmail.com>.
Benedict, thanks for your feedback!
With regards to filtering, global filters are already considered before the
event is enqueued. Filters configured on the Logger and AppenderRef are
applied prior to enqueueing with mixed Sync/Async
<http://logging.apache.org/log4j/2.x/manual/async.html#MixedSync-Async>
Loggers but when all loggers are async
<http://logging.apache.org/log4j/2.x/manual/async.html#AllAsync> these
filters are applied by the background thread. We can probably improve this,
thanks for the suggestion!
Your suggestion to run performance tests under lower loads is reasonable
and we will look at this for a future release.
I did experiment with this a little a while back and did see larger
response time pauses. Perhaps others with more experience can chime in.
My understanding of how the Disruptor works is that enqueueing the event is
lock-free, so applications threads doing the logging should not experience
any context switches or suffer latency from Futex calls caused by logging
(regardless of the workload). The background thread is another story. Under
moderate to low workloads the background thread may (depending on the wait
policy) fall asleep and experience delays before waking up when work
arrives. However, if there are enough cores to serve all threads I don't
see how such background thread delays can impact (cause response time
pauses for) the application that is doing the logging. Please correct me if
my understanding is incorrect.
My thinking is that using async loggers is good for reactive applications
that need to respond quickly to external events. It is especially useful if
the application needs to deal with occasional bursts of work (and
accompanied bursts of logging). This is where async loggers can deliver
value even if the normal workload is low.
Remko
On Wednesday, May 18, 2016 at 2:56:18 AM UTC+9, Benedict Elliott Smith
wrote:
>
> Regrettably it seems impossible (or at least very annoying) to send to
> both lists simultaneously...
>
> On 17 May 2016 at 18:55, Benedict Elliott Smith <bene...@apache.org
> <javascript:>> wrote:
>
>> Could I suggest that you run tests for latency and throughput effects of
>> using this in systems with only moderate-to-low numbers of logging calls?
>> (i.e. the vast majority of systems!)
>>
>
>> It's very likely that in such systems messages will not reach a velocity
>> to keep the Dispatcher running, and so logging calls may often (or always)
>> involve a Futex call - which is not a trivial cost. There will almost
>> certainly be systems out there with anti-ideal characteristics - logging
>> just often enough that these costs materially impact throughput, but not
>> often enough that they suddenly disappear.
>>
>> Even though a majority of systems *do not need this*, because it "async"
>> and the new hotness, and there are no advertised downsides, everyone will
>> try to use it. It's up to those who know better to make sure these people
>> are informed it isn't a free lunch. Making sure all of the caveats are
>> reported on the advertising page would be a great start IMO.
>>
>> Might I also separately suggest you consider filtering events prior to
>> placing them on the queue for processing by the dispatcher? I've only
>> briefly glanced at the code, but it seems not to be the case currently.
>>
>>>
>>> On 17 May 2016 at 18:33, Martin Thompson <mjp...@gmail.com <javascript:>
>>> > wrote:
>>>
>>>> Hi Remko,
>>>>
>>>> I'd just like to say that it is a great service to the community as a
>>>> whole that someone is seriously looking at improving logging.
>>>>
>>>> If you keep it up you'll be putting folks like me out of a job :)
>>>>
>>>> Martin...
>>>>
>>>>
>>>> On 17 May 2016 at 18:13, Remko Popma <remko...@gmail.com <javascript:>>
>>>> wrote:
>>>>
>>>>> Hi all,
>>>>>
>>>>> First, my thanks to the many people who gave helpful advice and
>>>>> feedback on how to measure Log4j response time on this list some time ago.
>>>>>
>>>>> We're about to start the Log4j 2.6 release.
>>>>> If anyone is interested, a preview of the garbage-free logging manual
>>>>> page is here:
>>>>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>>>>> and a preview of the updated performance page is here:
>>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>>>
>>>>> Feedback welcome!
>>>>>
>>>>> Remko
>>>>>
>>>>> --
>>>>> You received this message because you are subscribed to the Google
>>>>> Groups "mechanical-sympathy" group.
>>>>> To unsubscribe from this group and stop receiving emails from it, send
>>>>> an email to mechanical-sympathy+unsubscribe@googlegroups.com
>>>>> <javascript:>.
>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>
>>>>
>>>> --
>>>> You received this message because you are subscribed to the Google
>>>> Groups "mechanical-sympathy" group.
>>>> To unsubscribe from this group and stop receiving emails from it, send
>>>> an email to mechanical-sympathy+unsubscribe@googlegroups.com
>>>> <javascript:>.
>>>> For more options, visit https://groups.google.com/d/optout.
>>>>
>>>
>>>
>>
>
Re: Garbage-free Log4j docs preview
Posted by Benedict Elliott Smith <be...@apache.org>.
Could I suggest that you run tests for latency and throughput effects of
using this in systems with only moderate-to-low numbers of logging calls?
(i.e. the vast majority of systems!)
It's very likely that in such systems messages will not reach a velocity to
keep the Dispatcher running, and so logging calls may often (or always)
involve a Futex call - which is not a trivial cost. There will almost
certainly be systems out there with anti-ideal characteristics - logging
just often enough that these costs materially impact throughput, but not
often enough that they suddenly disappear.
Even though a majority of systems *do not need this*, because it "async"
and the new hotness, and there are no advertised downsides, everyone will
try to use it. It's up to those who know better to make sure these people
are informed it isn't a free lunch. Making sure all of the caveats are
reported on the advertising page would be a great start IMO.
Might I also separately suggest you consider filtering events prior to
placing them on the queue for processing by the dispatcher? I've only
briefly glanced at the code, but it seems not to be the case currently.
On 17 May 2016 at 18:50, Benedict Elliott Smith <_...@belliottsmith.com> wrote:
> Could I suggest that you run tests for latency and throughput effects of
> using this in systems with only moderate-to-low numbers of logging calls?
> (i.e. the vast majority of systems!)
>
> It's very likely that in such systems messages will not reach a velocity
> to keep the Dispatcher running, and so logging calls may often (or always)
> involve a Futex call - which is not a trivial cost. There will almost
> certainly be systems out there with anti-ideal characteristics - logging
> just often enough that these costs materially impact throughput, but not
> often enough that they suddenly disappear.
>
> Even though a majority of systems *do not need this*, because it "async"
> and the new hotness, and there are no advertised downsides, everyone will
> try to use it. It's up to those who know better to make sure these people
> are informed it isn't a free lunch. Making sure all of the caveats are
> reported on the advertising page would be a great start IMO.
>
> Might I also separately suggest you consider filtering events prior to
> placing them on the queue for processing by the dispatcher? I've only
> briefly glanced at the code, but it seems not to be the case currently.
>
> On 17 May 2016 at 18:33, Martin Thompson <mj...@gmail.com> wrote:
>
>> Hi Remko,
>>
>> I'd just like to say that it is a great service to the community as a
>> whole that someone is seriously looking at improving logging.
>>
>> If you keep it up you'll be putting folks like me out of a job :)
>>
>> Martin...
>>
>>
>> On 17 May 2016 at 18:13, Remko Popma <re...@gmail.com> wrote:
>>
>>> Hi all,
>>>
>>> First, my thanks to the many people who gave helpful advice and feedback
>>> on how to measure Log4j response time on this list some time ago.
>>>
>>> We're about to start the Log4j 2.6 release.
>>> If anyone is interested, a preview of the garbage-free logging manual
>>> page is here:
>>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html
>>> and a preview of the updated performance page is here:
>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html
>>>
>>> Feedback welcome!
>>>
>>> Remko
>>>
>>> --
>>> You received this message because you are subscribed to the Google
>>> Groups "mechanical-sympathy" group.
>>> To unsubscribe from this group and stop receiving emails from it, send
>>> an email to mechanical-sympathy+unsubscribe@googlegroups.com.
>>> For more options, visit https://groups.google.com/d/optout.
>>>
>>
>> --
>> You received this message because you are subscribed to the Google Groups
>> "mechanical-sympathy" group.
>> To unsubscribe from this group and stop receiving emails from it, send an
>> email to mechanical-sympathy+unsubscribe@googlegroups.com.
>> For more options, visit https://groups.google.com/d/optout.
>>
>
>