Re: RollingFileAppender maxDelayMillis?

[Benjamin Jaton]

Thanks a lot for the explanation, much clearer now.

Here is the JIRA: https://issues.apache.org/jira/browse/LOG4J2-1197

On Tue, Nov 10, 2015 at 11:39 PM, Remko Popma  wrote:

> On Wed, Nov 11, 2015 at 2:34 PM, Benjamin Jaton 
> wrote:
>
> > On Tue, Nov 10, 2015 at 6:13 PM, Remko Popma 
> > wrote:
> >
> > > To check my understanding: the problem is that with bufferedIO=true the
> > > buffer contains log events that you want to see, but the buffer is only
> > > flushed to disk when it is full (which is not frequent enough); is that
> > > correct?
> > >
> >
> > Yes that is correct.
> > Typical scenario is when the server is not in production, so almost no
> > traffic except for the request manually triggered by the operator,
> usually
> > in order to debug something.
> >
> >
> > > If you use AsyncAppender or Async Loggers, the buffer will be flushed
> > when
> > > the queue is empty. This results in efficient IO (lumping together IO
> > > operations where possible), but at the same time your log file always
> > > reflects the most recent message.
> > >
> >
> > So I have a dumb question. What's the difference between bufferedIO and
> > AsyncAppender?
> > Isn't bufferedIO a kind of asynchronous treatment of the log messages?
> I'm
> > sorry I'm a bit confused.
> >
>
> No problem at all. BufferedIO is not asynchronous. The difference between
> bufferedIO and Async Appenders/Loggers is that the async stuff deals with a
> queue of log event objects and happens further upstream, where bufferedIO
> deals with a byte[] array buffer and happens further downstream.
>
> When you use Async Appenders/Loggers, each time your application logs
> something a Log Event object is added to a queue. A background thread takes
> these events off the queue, asks the Layout to turn the event into a byte[]
> array and uses the Appender to send these bytes to their destination.
>
> Without Async Appenders/Loggers, there is no queue, and this work happens
> in your application thread (the Layout turns the event into a byte[] array
> and the Appender sends these bytes to their destination).
>
> When the configuration has bufferedIO="true", the Appender will save up the
> byte[] arrays for multiple log events together in an in-memory buffer first
> instead of writing each byte[] array to its destination immediately,
> to reduce the number of expensive I/O operations. As you noticed, this
> sometimes results in data sitting in this in-memory buffer for a long time.
>
> Now, with Async Appenders/Loggers, we can use what Martin Thompson calls
> "smart
> batching
> ":
> when
> the background thread processes a log event, it checks if the queue is now
> empty (no further log events are in the pipeline to be processed) and if it
> is, it will also call Appender.flush() in addition to the above.
>
>
>
> > >
> > > For synchronous buffered logging, I can see how a smarter flushing
> > > mechanism would be useful.
> > >
> > > Question is, what would trigger the check (whether the buffer needs to
> be
> > > flushed)?
> > >
> > > Easiest is to check with each log event, but if no new event arrives
> you
> > > still end up with a stale buffer. Better than nothing, but not great.
> > >
> > > An alternative is to check periodically from a background thread and
> > flush
> > > if the buffer is non-empty. This probably gives the best results but is
> > > fairly complex to implement.
> > >
> >
> > That was what I had in mind but I don't know the complexity.
> >
> >
> > >
> > > I need to think about this a bit more, but for now I would suggest
> using
> > > async logging. It may be a good idea to create a Jira ticket for this.
> > >
> >
> > OK I will create a Jira for this.
> >
> >
> > >
> > > Remko
> > >
> > > > On 2015/11/11, at 5:16, Gary Gregory  wrote:
> > > >
> > > > And more generally, can all appenders benefit from such a setting?
> > > >
> > > > Gary
> > > >
> > > > On Tue, Nov 10, 2015 at 11:04 AM, Benjamin Jaton <
> > > benjamin.ja...@gmail.com>
> > > > wrote:
> > > >
> > > >> Hi,
> > > >>
> > > >> I am wondering if it would make sense to have a maxDelayMillis
> > parameter
> > > >> for the RollingFileAppender (like FlumeAppender).
> > > >>
> > > >> Use case:
> > > >> You have a web server access log, you produce an HTTP request and
> > > expect to
> > > >> see it (and the response) in the access logs right away-ish (or at
> > least
> > > >> control how much you have to wait).
> > > >>
> > > >> Thoughts?
> > > >> Ben
> > > >>
> > > >
> > > >
> > > >
> > > > --
> > > > E-Mail: garydgreg...@gmail.com | ggreg...@apache.org
> > > > Java Persistence with Hibernate, Second Edition
> > > > 
> > > > JUnit in Action, Second Edition 
> > > > Spring Batch in Action 
> > > > Blog: 

Re: RollingFileAppender maxDelayMillis?

[Gary Gregory]

And more generally, can all appenders benefit from such a setting?

Gary

On Tue, Nov 10, 2015 at 11:04 AM, Benjamin Jaton 
wrote:

> Hi,
>
> I am wondering if it would make sense to have a maxDelayMillis parameter
> for the RollingFileAppender (like FlumeAppender).
>
> Use case:
> You have a web server access log, you produce an HTTP request and expect to
> see it (and the response) in the access logs right away-ish (or at least
> control how much you have to wait).
>
> Thoughts?
> Ben
>



-- 
E-Mail: garydgreg...@gmail.com | ggreg...@apache.org
Java Persistence with Hibernate, Second Edition

JUnit in Action, Second Edition 
Spring Batch in Action 
Blog: http://garygregory.wordpress.com
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory

Re: RollingFileAppender maxDelayMillis?

[Remko Popma]

To check my understanding: the problem is that with bufferedIO=true the buffer 
contains log events that you want to see, but the buffer is only flushed to 
disk when it is full (which is not frequent enough); is that correct?

If you use AsyncAppender or Async Loggers, the buffer will be flushed when the 
queue is empty. This results in efficient IO (lumping together IO operations 
where possible), but at the same time your log file always reflects the most 
recent message. 

For synchronous buffered logging, I can see how a smarter flushing mechanism 
would be useful. 

Question is, what would trigger the check (whether the buffer needs to be 
flushed)? 

Easiest is to check with each log event, but if no new event arrives you still 
end up with a stale buffer. Better than nothing, but not great. 

An alternative is to check periodically from a background thread and flush if 
the buffer is non-empty. This probably gives the best results but is fairly 
complex to implement. 

I need to think about this a bit more, but for now I would suggest using async 
logging. It may be a good idea to create a Jira ticket for this. 

Remko 

> On 2015/11/11, at 5:16, Gary Gregory  wrote:
> 
> And more generally, can all appenders benefit from such a setting?
> 
> Gary
> 
> On Tue, Nov 10, 2015 at 11:04 AM, Benjamin Jaton 
> wrote:
> 
>> Hi,
>> 
>> I am wondering if it would make sense to have a maxDelayMillis parameter
>> for the RollingFileAppender (like FlumeAppender).
>> 
>> Use case:
>> You have a web server access log, you produce an HTTP request and expect to
>> see it (and the response) in the access logs right away-ish (or at least
>> control how much you have to wait).
>> 
>> Thoughts?
>> Ben
>> 
> 
> 
> 
> -- 
> E-Mail: garydgreg...@gmail.com | ggreg...@apache.org
> Java Persistence with Hibernate, Second Edition
> 
> JUnit in Action, Second Edition 
> Spring Batch in Action 
> Blog: http://garygregory.wordpress.com
> Home: http://garygregory.com/
> Tweet! http://twitter.com/GaryGregory

-
To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-user-h...@logging.apache.org

Re: RollingFileAppender maxDelayMillis?

[Remko Popma]

On Wed, Nov 11, 2015 at 2:34 PM, Benjamin Jaton 
wrote:

> On Tue, Nov 10, 2015 at 6:13 PM, Remko Popma 
> wrote:
>
> > To check my understanding: the problem is that with bufferedIO=true the
> > buffer contains log events that you want to see, but the buffer is only
> > flushed to disk when it is full (which is not frequent enough); is that
> > correct?
> >
>
> Yes that is correct.
> Typical scenario is when the server is not in production, so almost no
> traffic except for the request manually triggered by the operator, usually
> in order to debug something.
>
>
> > If you use AsyncAppender or Async Loggers, the buffer will be flushed
> when
> > the queue is empty. This results in efficient IO (lumping together IO
> > operations where possible), but at the same time your log file always
> > reflects the most recent message.
> >
>
> So I have a dumb question. What's the difference between bufferedIO and
> AsyncAppender?
> Isn't bufferedIO a kind of asynchronous treatment of the log messages? I'm
> sorry I'm a bit confused.
>

No problem at all. BufferedIO is not asynchronous. The difference between
bufferedIO and Async Appenders/Loggers is that the async stuff deals with a
queue of log event objects and happens further upstream, where bufferedIO
deals with a byte[] array buffer and happens further downstream.

When you use Async Appenders/Loggers, each time your application logs
something a Log Event object is added to a queue. A background thread takes
these events off the queue, asks the Layout to turn the event into a byte[]
array and uses the Appender to send these bytes to their destination.

Without Async Appenders/Loggers, there is no queue, and this work happens
in your application thread (the Layout turns the event into a byte[] array
and the Appender sends these bytes to their destination).

When the configuration has bufferedIO="true", the Appender will save up the
byte[] arrays for multiple log events together in an in-memory buffer first
instead of writing each byte[] array to its destination immediately,
to reduce the number of expensive I/O operations. As you noticed, this
sometimes results in data sitting in this in-memory buffer for a long time.

Now, with Async Appenders/Loggers, we can use what Martin Thompson calls "smart
batching
": when
the background thread processes a log event, it checks if the queue is now
empty (no further log events are in the pipeline to be processed) and if it
is, it will also call Appender.flush() in addition to the above.



> >
> > For synchronous buffered logging, I can see how a smarter flushing
> > mechanism would be useful.
> >
> > Question is, what would trigger the check (whether the buffer needs to be
> > flushed)?
> >
> > Easiest is to check with each log event, but if no new event arrives you
> > still end up with a stale buffer. Better than nothing, but not great.
> >
> > An alternative is to check periodically from a background thread and
> flush
> > if the buffer is non-empty. This probably gives the best results but is
> > fairly complex to implement.
> >
>
> That was what I had in mind but I don't know the complexity.
>
>
> >
> > I need to think about this a bit more, but for now I would suggest using
> > async logging. It may be a good idea to create a Jira ticket for this.
> >
>
> OK I will create a Jira for this.
>
>
> >
> > Remko
> >
> > > On 2015/11/11, at 5:16, Gary Gregory  wrote:
> > >
> > > And more generally, can all appenders benefit from such a setting?
> > >
> > > Gary
> > >
> > > On Tue, Nov 10, 2015 at 11:04 AM, Benjamin Jaton <
> > benjamin.ja...@gmail.com>
> > > wrote:
> > >
> > >> Hi,
> > >>
> > >> I am wondering if it would make sense to have a maxDelayMillis
> parameter
> > >> for the RollingFileAppender (like FlumeAppender).
> > >>
> > >> Use case:
> > >> You have a web server access log, you produce an HTTP request and
> > expect to
> > >> see it (and the response) in the access logs right away-ish (or at
> least
> > >> control how much you have to wait).
> > >>
> > >> Thoughts?
> > >> Ben
> > >>
> > >
> > >
> > >
> > > --
> > > E-Mail: garydgreg...@gmail.com | ggreg...@apache.org
> > > Java Persistence with Hibernate, Second Edition
> > > 
> > > JUnit in Action, Second Edition 
> > > Spring Batch in Action 
> > > Blog: http://garygregory.wordpress.com
> > > Home: http://garygregory.com/
> > > Tweet! http://twitter.com/GaryGregory
> >
> > -
> > To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
> > For additional commands, e-mail: log4j-user-h...@logging.apache.org
> >
> >
>

Re: RollingFileAppender maxDelayMillis?

[Benjamin Jaton]

On Tue, Nov 10, 2015 at 6:13 PM, Remko Popma  wrote:

> To check my understanding: the problem is that with bufferedIO=true the
> buffer contains log events that you want to see, but the buffer is only
> flushed to disk when it is full (which is not frequent enough); is that
> correct?
>

Yes that is correct.
Typical scenario is when the server is not in production, so almost no
traffic except for the request manually triggered by the operator, usually
in order to debug something.


> If you use AsyncAppender or Async Loggers, the buffer will be flushed when
> the queue is empty. This results in efficient IO (lumping together IO
> operations where possible), but at the same time your log file always
> reflects the most recent message.
>

So I have a dumb question. What's the difference between bufferedIO and
AsyncAppender?
Isn't bufferedIO a kind of asynchronous treatment of the log messages? I'm
sorry I'm a bit confused.


>
> For synchronous buffered logging, I can see how a smarter flushing
> mechanism would be useful.
>
> Question is, what would trigger the check (whether the buffer needs to be
> flushed)?
>
> Easiest is to check with each log event, but if no new event arrives you
> still end up with a stale buffer. Better than nothing, but not great.
>
> An alternative is to check periodically from a background thread and flush
> if the buffer is non-empty. This probably gives the best results but is
> fairly complex to implement.
>

That was what I had in mind but I don't know the complexity.


>
> I need to think about this a bit more, but for now I would suggest using
> async logging. It may be a good idea to create a Jira ticket for this.
>

OK I will create a Jira for this.


>
> Remko
>
> > On 2015/11/11, at 5:16, Gary Gregory  wrote:
> >
> > And more generally, can all appenders benefit from such a setting?
> >
> > Gary
> >
> > On Tue, Nov 10, 2015 at 11:04 AM, Benjamin Jaton <
> benjamin.ja...@gmail.com>
> > wrote:
> >
> >> Hi,
> >>
> >> I am wondering if it would make sense to have a maxDelayMillis parameter
> >> for the RollingFileAppender (like FlumeAppender).
> >>
> >> Use case:
> >> You have a web server access log, you produce an HTTP request and
> expect to
> >> see it (and the response) in the access logs right away-ish (or at least
> >> control how much you have to wait).
> >>
> >> Thoughts?
> >> Ben
> >>
> >
> >
> >
> > --
> > E-Mail: garydgreg...@gmail.com | ggreg...@apache.org
> > Java Persistence with Hibernate, Second Edition
> > 
> > JUnit in Action, Second Edition 
> > Spring Batch in Action 
> > Blog: http://garygregory.wordpress.com
> > Home: http://garygregory.com/
> > Tweet! http://twitter.com/GaryGregory
>
> -
> To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
> For additional commands, e-mail: log4j-user-h...@logging.apache.org
>
>