logging-log4net-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Joe <Jocular...@hotmail.com>
Subject RE: AsyncAppenderSkeleton
Date Thu, 03 Nov 2016 21:06:17 GMT
OK I understand the point about potential corruption when a derived class is writing logging
events in a non-atomic way, which is probably typical of most appenders.

However I don’t understand your point about event formatters – are there any formatters
that aren’t thread safe?  It doesn’t seem to be an unreasonable restriction to require
writers of formatters / layout implementations to be thread-safe.

I looked at the implementation of AbsoluteTimeDateFormatter, which uses a static buffer internally.
 It seems to be thread-safe, but if I understood the code correctly, it seems to have a superfluous
lock on s_lastTimeBuf, since it is only ever accessed when the current thread is already holding
a lock on s_lastTimeStrings.   Also it seems to me that any performance gains achieved by
reusing a static buffer could easily be cancelled out by the overhead of holding locks if
an application does a lot of concurrent logging from multiple threads.  Perhaps a better implementation
would be to use a ThreadStatic buffer, which I think would give the same result without locking.

As for an async appender: I still think the best approach is to write a new base class AsyncAppenderSkeleton,
that doesn’t inherit from either BufferingAppenderSkeleton or AppenderSkeleton.  I’ll
give it some more thought and post again to justify this opinion soon(ish).



From: Dominik Psenner [mailto:dpsenner@gmail.com]
Sent: 03 November 2016 00:14
To: Log4NET Dev
Subject: Re: AsyncAppenderSkeleton

As far as I can recall, log4net logs to an appender in the thread that the log event was created
on unless there is buffering of log events in between (BufferingAppenderSkeleton). This in
general means that multiple threads write content to an appender at the same time and that
in turn means that there is a chance that log events get mixed up.

Think of two threads A and B that try to write to the same sink at the same time. Thread A
begins to write the timestamp of his log event and gets interrupted. B wakes up and writes
another timestamp. Now there are two timestamps after each other and the outcome is not two
distinct log messages but garbage.

And the issues can go even further. What if the event formatter populates a (not thread safe)
local cache while processing log events? The outcome is unpredictable. I can imagine that
back then it was decided to better be safe than sorry. A pessimistic lock fixes this issue
for good at the cost of performance.

Writing this down today in 2016, one major question jumps into my mind: why is locking not
left up to the appender or a event formatter? There are appenders out there that append log
events to sinks that can handle concurrency very well (databases for example). It would definitely
result in more locks; more locks cost more and thus a single (outer) lock is better.

Still, today I would not bother about locking and rather configure a buffering appender and
let that appender append events into another appender that must not care about locking because
the buffering appender already does. If one knows that locking/buffering is not needed because
his application does no multithreading at all, he could still configure the other appender
all alone.

2016-11-02 20:55 GMT+01:00 Joe <JocularJoe@hotmail.com<mailto:JocularJoe@hotmail.com>>:
I’m trying to understand what locking is necessary in AppenderSkeleton and its derived classes.
 There is a lock(this) in AppenderSkeleton’s DoAppend and Close methods, which ensure that
the appender can’t be closed while an Append is in progress.   Implementing Append in a
derived class is easier, because the lock ensures it can never be called concurrently by more
than one thread.

That’s all fairly clear, but I don’t understand the comment in the AppenderSkeleton.DoAppend
method:

       // This lock is absolutely critical for correct formatting
       // of the message in a multi-threaded environment.  Without
       // this, the message may be broken up into elements from
       // multiple thread contexts (like get the wrong thread ID).

The lock is clearly necessary for the above reasons, but I don’t see what race condition
could cause a message to be “broken up into elements from multiple thread contexts”?

Can you throw any light on that?



From: Dominik Psenner [mailto:dpsenner@apache.org<mailto:dpsenner@apache.org>]
Sent: 31 October 2016 15:31
To: log4net-dev@logging.apache.org<mailto:log4net-dev@logging.apache.org>
Subject: Re: AsyncAppenderSkeleton


See inlines.
On 2016-10-31 11:30, Joe wrote:
Hi Dominik,

Thanks for the feedback

> Please note also that MSMQ sounds like a MS only service and that would in turn mean
that the .net core variant would no longer be able to benefit from the AsyncAppenderSkeleton.
To me this outlines a path that we would not like to walk on

I don’t see the problem here.

I’m proposing that we could implement the queue as a separate class implementing a suitable
interface (ILoggingEventQueue, IAppenderQueue or whatever – I’m with Philip Karlton on
naming).    The default implementation would be an in-memory queue, would not depend on MSMQ
and would be available for .net core etc.


Sorry, my fault, the sentence was TL;DR it's entirety. I had it read it as "The default implementation
could be MSMQ". ;-) Thanks for the clarification.

Then there could be an alternate implementation with a persistent queue using MSMQ, or users
could provide their own custom implementations using some other persistent queueing technology
if they wish.

The alternative of a persistent queue is useful to reduce the risk of (probably the last and
therefore most important) logging events being lost when an application crashes: with a persistent
queue they could be picked up again from the queue when the application restarts, or by an
independent utility.


> This sounds mostly like the BufferingAppenderSkeleton, which only misses the background
worker thread to send the buffer.

I’m not convinced that BufferingAppenderSkeleton is a good candidate.  For example:

- Locking is problematic.  The appender would need to lock(this) while it is forwarding logging
events to the sink (BufferingAppenderSkeleton.SendBuffer).  This could hold the lock for an
extended period (e.g. due to a communication timeout).  Therefore DoAppend should not lock(this)
while enqueueing logging events or we’ll be unnecessarily blocking the calling application.
 This is one of the main reasons I want to implement my own DoEvents rather than deriving
from AppenderSkeleton.

If the implementation requires lock(this) to work, the implementation is broken. The queue
itself has to be thread safe. Hence, a true async appender should block the calling application
only to fix a few logging event properties that would otherwise be lost (i.e. stacktrace or
thread information).

- I see the buffering and triggering logic being implemented in a pluggable ILoggingEventQueue.
  By default, there would be no buffering, except what is implicit in the fact that events
may be enqueued faster than they can be dequeued.  I.e. whenever the background thread detects
events in the queue, by default it processes all available events immediately, in blocks whose
maximum size is a configurable SendBufferSize.    A custom queue implementation could implement
triggering logic akin to BufferingAppenderSkeleton, e.g. wait for a timeout defined by TimeEvaluator
if there are fewer than SendBufferSize events in the queue.

A async appender working in async mode always buffers, by definition. If it wouldn't buffer,
there would be nothing that a background thread could work on and it would block the calling
application.


> System.Threading.Task.Run().

The TPL could be one way of implementing the queue, though I’m not convinced that it adds
much value.   The custom implementation I did recently didn’t use TPL, and that would be
my starting point.  This also means it would be compatible with .NET 3.5.

If .net 3.5 is a target for async logging, then the implementation cannot use the System.Threading.Tasks
namespace. Otherwise I would build upon the default task scheduler implementation or provide
a custom task scheduler implementation that derives from System.Threading.Tasks.TaskScheduler
and let all logging tasks run on that task scheduler.

  I found having a single background thread made it easier to implement things like flushing.

Mileage may vary but to me, this is not the case.

   Flush was implemented to:
- return true immediately if the queue is empty and all events have been successfully sent
to the sink.
- return false immediately if the last attempt to send events to the sink failed.
- else wait for the background thread to set a ManualResetEvent when it’s finished processing
all events in the queue.

That could read as:

bool Flush() {
return await Task.Run(() => {
  return doFlush();
});
}

or:

bool Flush() {
 Task<bool> task = Task.Run() => {
  return doFlush();
});
 task.Wait();
 return task.Result;
}

or even:

Task<bool> FlushAsync() {
  return Task.Run() => {
  return doFlush();
});
}


> The default implementation should probably be able to operate asynchronously or synchronously
and change mode of operation based on a configuration flag "Asynchronous=True"

That’s exactly what I had in mind.

Cheers



--
Dominik Psenner
Mime
View raw message