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: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
