Behavior and default config for JULI AsyncFileHandler

[Rainer Jung <ra...@kippdata.de>]

Since Tomcat 8 our JULI config uses AsyncFileHandler by default.

The default config of AsyncFileHandler allows log records to be dropped 
once the log queue gets full. I'd say this is not a sane default and 
suggest that we switch the default to the "block logging thread until 
there's again space in the queue" option. Of course that will mean 
Tomcat threads start to hang in logging once the queue gets full. But 
simply throwing away log messages should be an explicit choice of an 
admin and not our release default IMHO.

I suggest to switch defaults to OVERFLOW_DROP_FLUSH (and also to rename 
that constant to OVERFLOW_DROP_WAIT).

Then there's currently a config setting 
org.apache.juli.AsyncLoggerPollInterval which controls how long the 
thread that polls the queue blocks waiting for the next log record to 
show up in the queue. If the timeout fires, it immediately starts to 
poll again. I don't really understand, why this should be configurable. 
IMHO the only reason for this poll timeout would be to allow the polling 
thread to stop. For instance if JULI needs to get unloaded, e.g. when 
being embedded or in a per webapp use, then an endless blocking poller 
thread might not be good. But in fact although the thread has a "run" 
flag which could control stopping it, the flag is never set to false! 
The thread is marked as daemon though.

I suggest to remove the system property 
org.apache.juli.AsyncLoggerPollInterval.

I suggest to also orderly shut down the thread during 
ClassLoaderogManager shutdown. Since the thread is static, that would 
mean making the "run" flag volatile, letting AsyncFileHandler count it's 
non-closed instances and set "run" to false in the close() method when 
the last instance is closed. Alternatively one could make the queue and 
the polling thread non-global but per instance and shut the thread down 
in close(). I would find the latter easier and also more plausible. 
Don't know what good reason there is to share the queue and the thread.

Comments?

Thanks and regards,

Rainer

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org

Re: Behavior and default config for JULI AsyncFileHandler

[Konstantin Kolinko <kn...@gmail.com>]

2014-12-01 14:01 GMT+03:00 Mark Thomas <ma...@apache.org>:
> On 29/11/2014 16:49, Rainer Jung wrote:
>> Since Tomcat 8 our JULI config uses AsyncFileHandler by default.
>>
>> The default config of AsyncFileHandler allows log records to be dropped
>> once the log queue gets full. I'd say this is not a sane default and
>> suggest that we switch the default to the "block logging thread until
>> there's again space in the queue" option. Of course that will mean
>> Tomcat threads start to hang in logging once the queue gets full. But
>> simply throwing away log messages should be an explicit choice of an
>> admin and not our release default IMHO.
>>
>> I suggest to switch defaults to OVERFLOW_DROP_FLUSH (and also to rename
>> that constant to OVERFLOW_DROP_WAIT).
>
> +1 but I'd rename it to OVERFLOW_BLOCK since a) nothing gets dropped and
> b) block is more explicit as to what will happen.

Maybe keep the "drop" default, but add a counter of how many log
statements were dropped and log it when possible?

I think the current default of "drop" is protection against single
point of failure. Though I think "drop current" has the same effect
and will work faster. If there is a single thread that polls that
queue and it dies or is stuck at I/O (misbehaving hardware, network
drives, or whatever) then several request processing threads may stuck
waiting on this queue. Background processing may stuck waiting for
some events generated by request processing threads to be logged.

>> Then there's currently a config setting
>> org.apache.juli.AsyncLoggerPollInterval which controls how long the
>> thread that polls the queue blocks waiting for the next log record to
>> show up in the queue. If the timeout fires, it immediately starts to
>> poll again. I don't really understand, why this should be configurable.
>> IMHO the only reason for this poll timeout would be to allow the polling
>> thread to stop. For instance if JULI needs to get unloaded, e.g. when
>> being embedded or in a per webapp use, then an endless blocking poller
>> thread might not be good. But in fact although the thread has a "run"
>> flag which could control stopping it, the flag is never set to false!
>> The thread is marked as daemon though.
>>
>> I suggest to remove the system property
>> org.apache.juli.AsyncLoggerPollInterval.
>
> +1

What do you propose? Hard-code it as 1 second or as infinite wait?

When this property is configurable one can experiment with setting
this property to some high value.

Maybe use this loop to perform some house-keeping? E.g. periodical
flush. (I moved the topic of periodical flush to the end of this
e-mail, as it is a separate topic).   If this loop does some work
besides polling the queue then I think it is better to have a
configurable a timeout.

>> I suggest to also orderly shut down the thread during
>> ClassLoaderogManager shutdown. Since the thread is static, that would
>> mean making the "run" flag volatile, letting AsyncFileHandler count it's
>> non-closed instances and set "run" to false in the close() method when
>> the last instance is closed.
>>
>> Alternatively one could make the queue and
>> the polling thread non-global but per instance and shut the thread down
>> in close(). I would find the latter easier and also more plausible.
>> Don't know what good reason there is to share the queue and the thread.
>>
>> Comments?
>
> Per instance makes more sense to me. Global, per JVM instances are the
> sort of things that have caused problems with some of the more
> interesting use cases (e.g. embedding) so if we have an opportunity to
> remove one then let's do so.

1). I think that if there are any events in the queue that are
targeted to this logger one has to wait for a while for those to be
flushed before actually closing it.

2) I like the idea of a counter, but shutting down the thread in
close() means that open() needs to start a thread when the count is
increased back from 0.

I suspect that open() can be triggered by application code. Starting a
global thread from there needs some special processing to do not cause
a memory leak (via Thread.contextClassLoader and
Thread.inheritedAccessControlContext)

I think the current approach in theory already suffers from this
memory leak issue. Tomcat 8 is saved by the fact that the default
configuration has several global AsyncFileHandlers. If there were none
declared globally, the first one may be created by webapp code.

3) A single global Thread makes sense to me. I do not expect many
info/error/warn log statements to keep many threads busy.

Make it configurable?


Do not forget that one can also use the good old FileHandler.  If
there are not many log statements the FileHandler is enough.

On periodical flush:
====
A feature that I miss in FileHandler is periodical flush() of file
handlers. It is one reason why buffering cannot be enabled there.

For comparison, an AccessLogValve can cache entries and flushes them
when performing background processing on Tomcat's background
processing thread. Thus recent entries are guaranteed to appear in the
log after some delay.

If I enable buffering in FileHandler, there is no time guarantee when
the entries will appear in the file. A flush is performed only when
buffer overflows or when the handler is closed.

A similar but smaller issue is with rotation of log files. Rotation is
performed only when a log event arrives. If there are no log events
coming, the old log file is kept open.

Best regards,
Konstantin Kolinko

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org

Re: Behavior and default config for JULI AsyncFileHandler

[Mark Thomas <ma...@apache.org>]

On 29/11/2014 16:49, Rainer Jung wrote:
> Since Tomcat 8 our JULI config uses AsyncFileHandler by default.
> 
> The default config of AsyncFileHandler allows log records to be dropped
> once the log queue gets full. I'd say this is not a sane default and
> suggest that we switch the default to the "block logging thread until
> there's again space in the queue" option. Of course that will mean
> Tomcat threads start to hang in logging once the queue gets full. But
> simply throwing away log messages should be an explicit choice of an
> admin and not our release default IMHO.
> 
> I suggest to switch defaults to OVERFLOW_DROP_FLUSH (and also to rename
> that constant to OVERFLOW_DROP_WAIT).

+1 but I'd rename it to OVERFLOW_BLOCK since a) nothing gets dropped and
b) block is more explicit as to what will happen.

> Then there's currently a config setting
> org.apache.juli.AsyncLoggerPollInterval which controls how long the
> thread that polls the queue blocks waiting for the next log record to
> show up in the queue. If the timeout fires, it immediately starts to
> poll again. I don't really understand, why this should be configurable.
> IMHO the only reason for this poll timeout would be to allow the polling
> thread to stop. For instance if JULI needs to get unloaded, e.g. when
> being embedded or in a per webapp use, then an endless blocking poller
> thread might not be good. But in fact although the thread has a "run"
> flag which could control stopping it, the flag is never set to false!
> The thread is marked as daemon though.
> 
> I suggest to remove the system property
> org.apache.juli.AsyncLoggerPollInterval.

+1

> I suggest to also orderly shut down the thread during
> ClassLoaderogManager shutdown. Since the thread is static, that would
> mean making the "run" flag volatile, letting AsyncFileHandler count it's
> non-closed instances and set "run" to false in the close() method when
> the last instance is closed. Alternatively one could make the queue and
> the polling thread non-global but per instance and shut the thread down
> in close(). I would find the latter easier and also more plausible.
> Don't know what good reason there is to share the queue and the thread.
> 
> Comments?

Per instance makes more sense to me. Global, per JVM instances are the
sort of things that have caused problems with some of the more
interesting use cases (e.g. embedding) so if we have an opportunity to
remove one then let's do so.

Mark

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org