On 2016-11-03 22:06, Joe wrote:
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.
You are right about this. Locking must be avoided where ever it is
possible. Unless populating caches altogether with locking is faster
than recalculating things on every run. The former is probably the case
for the formatters. The AbsoluteTimeDateFormatter is a good example for
that. It has to update the formatted date/time string only once in a
while which is way less frequent than the frequency of generated log
events and for all log events in between it can reuse the cached string
representation.
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:dpsen...@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 <jocular...@hotmail.com
<mailto:jocular...@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:dpsen...@apache.org
<mailto:dpsen...@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
