[jira] Issue Comment Edited: (LOG4NET-201) Add asynchronous logging behavior

["Ron Grabowski (JIRA)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/LOG4NET-201?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12676124#action_12676124 ] 

ron edited comment on LOG4NET-201 at 2/23/09 3:47 PM:
----------------------------------------------------------------

In a nutshell, I think the extension point for async logging is at the appender level. When I first saw your code I tried to implement a custom ILoggerFactory (one that returned an extended Logger with a Synchronous property) and pass that into the Hiearchy constructor. It kind of worked but then I started thinking about things like locking the queue each time a new message appeared as opposed to batch up 100 messages and dispatching those at the same time, how an unexpected threading issue could bring down a particular logger or possibly the entire Hiearchy, etc. I found myself wanting to customize the behavior a little bit here and there depending on what application I would be using it in. By placing such logic in a custom appender you lesson the amount of changes to the core library and can more easily back port your changes to older versions of log4net. You also have more freedom to create a base async appender and extend it with new functionality or create entirely new functionality if the defaults aren't good enough without having to mess with the much more low level Logger and to some extent ILoggerFactory.

Your proposal of:

<root async="true">
 <appender-ref ref="MyFileAppender" />
 <appender-ref ref="MyAdoNetAppender" />
</root>

would be changed to:

<root>
 <appender-ref ref="AsyncForwardingAppender" />
</root>

where the appender could have all sorts of other options like UseThreadPool, UseCustomThreadPool, etc. and whose configurations could be much better defined by the existing xml processor:

 <appender name="AsyncForwardingAppender" type="...">
  <useThreadPool value="false">
  <threadPool>
   <threadCountMatchesAppenderCount value="true" />
   <dispatchMode value="concurrent" />
  </threadPool>
  <fixFlag value="All" />
  <maxQueuedItems value="500" />
  <forceFlushOn value="WARN" />
  <asyncEnabled value="true" />
  <flushBufferInterval value="60000" />  
  <appender-ref ref="MyFileAppender" />
  <appender-ref ref="MyAdoNetAppender" />
 <appender />

If you extended AppenderSkeleton you could take advantage of things like IErrorHandler and Filters. Current log4net users could immediately take advantage of a robust async appender that itself queues items then dispatches them to one or more attached appenders. In fact a "poor man's" async appender already exists...put a BufferingForwardingAppender in front of this AsyncAppender:

http://svn.apache.org/viewvc/logging/log4net/trunk/examples/net/1.0/Appenders/SampleAppendersApp/cs/src/Appender/

and you can happily batch process buffered entries using the ThreadPool. 

Here's another example of very high performant buffering async appender for Sql Server:

http://rhino-tools.svn.sourceforge.net/viewvc/rhino-tools/trunk/commons/Rhino.Commons/Logging/

Those extensions occurred without having to change the library itself.

A good async forwarding appender would allow async functionality to automatically be added to all the existing appenders like EventLogAppender, LocalSysLogAppender, FileAppender, etc.

If you want to go crazy with the async stuff I suppose you could dispatch the LoggingEvent immediately after it was created/Fixed so the routing stuff occurs on a different thread which also dispatches the messages to the appenders. I'd think about creating a custom ILoggerRepository at that point...maybe a simple shim that handles the initial LoggingEvent creation and threading then delegates to an existing Hiearchy under the covers.

      was (Author: ron):
    In a nutshell, I think the extension point for async logging is at the appender level. When I first saw your code I tried to implement a custom ILoggerFactory (one that returned an extended Logger with a Synchronous property) and pass that into the Hiearchy constructor. It kind of worked but then I started thinking about things like locking the queue each time a new message appeared as opposed to batch up 100 messages and dispatching those at the same time, how an unexpected threading issue could bring down a particular logger or possibly the entire Hiearchy, etc. 
I found myself wanting to customize the behavior a little bit here and there depending on what application I would be using it in. By placing such logic in a custom appender you lesson the amount of changes to the core library and can more easily back port your changes to older versions of log4net. You also have more freedom to create a base async appender and extend it with new functionality or create entirely new functionality if the defaults aren't good enough without having to mess with the much more low level Logger and to some extent ILoggerFactory.

Your proposal of:

<root async="true">
 <appender-ref ref="MyFileAppender" />
 <appender-ref ref="MyAdoNetAppender" />
</root>

would be changed to:

<root>
 <appender-ref ref="AsyncForwardingAppender" />
</logger>

where the appender could have all sorts of other options like UseThreadPool, UseCustomThreadPool, etc. and whose configurations could be much better defined by the existing xml processor:

 <appender name="AsyncForwardingAppender" type="...">
  <useThreadPool value="false">
  <threadPool>
   <threadCountMatchesAppenderCount value="true" />
   <dispatchMode value="concurrent" />
  </threadPool>
  <fixFlag value="All" />
  <maxQueuedItems value="500" />
  <forceFlushOn value="WARN" />
  <asyncEnabled value="true" />
  <flushBufferInterval value="60000" />  
  <appender-ref ref="MyFileAppender" />
  <appender-ref ref="MyAdoNetAppender" />
 <appender />

If you extended AppenderSkeleton you could take advantage of things like IErrorHandler and Filters. Current log4net users could immediately take advantage of a robust async appending that itself queues items them dispatches them to one or more attached appenders. In fact a "poor man's" async appender already exists...put a BufferingForwardingAppender in front of this AsyncAppender:

http://svn.apache.org/viewvc/logging/log4net/trunk/examples/net/1.0/Appenders/SampleAppendersApp/cs/src/Appender/

and you can happily batch process buffered entries using the ThreadPool. 

Here's another example of very high performant buffering async appender for Sql Server:

http://rhino-tools.svn.sourceforge.net/viewvc/rhino-tools/trunk/commons/Rhino.Commons/Logging/

Those extensions occurred without having to change the library itself.

A good async forwarding appender would allow async functionality to automatically be added to all the existing appenders like EventLogAppender, LocalSysLogAppender, FileAppender, etc.

If you want to go crazy with the async stuff I suppose you could dispatch the LoggingEvent immediately after it was created/Fixed so the routing stuff occurs on a different thread which also dispatches the messages to the appenders. I'd think about creating a custom ILoggerRepository at that point.
  
> Add asynchronous logging behavior
> ---------------------------------
>
>                 Key: LOG4NET-201
>                 URL: https://issues.apache.org/jira/browse/LOG4NET-201
>             Project: Log4net
>          Issue Type: New Feature
>          Components: Core
>         Environment: All
>            Reporter: Jason
>         Attachments: log4net_trunk.zip
>
>
> This issue was first discussed in an e-mail conversation which I'll paste here:
> -------------------------------------------------
> Hi Ron,
> I'll open a JIRA ticket for this issue.  
> I've only looked at log4net briefly (an hour before I started coding - needed a quick solution), so I'm happy to hear your input.  
> My less knowledgeable inputs:
> * For the hierarchy level vs the logger level, I agree that the hierarchy level seems better.  I didn't realize anything about the 'hierarchy' until later today.  I only added the asynchronous behavior to the logger because I mistakenly thought that was the highest level.
> * I also realized that FixFlags.All would be slow by comparison to a partial 'Fix', but I hadn't yet figured out which fields were relevant.  I'm still fuzzy on this as I'm not sure how to tell which fields are required - maybe inferred from the log level?  This seems to be a big issue with the async behavior since it could potentially introduce more harm than good in the current implementation.
> * ThreadSafeBlockingQueue - I'd seen mention of IBulkAppenders but didn't know anymore than what I could infer from the names.  I'm guessing these receive a collection of inputs.  The TSBQueue could certainly be modified.  I was going to create it with generics but I'm guessing log4net doesn't use generics to provide backwards compatibility?
> I'm interested to hear about your other solution since you seem to understand the overall design well.  For now I need to get my application running on top of what I have, but I might be able to lend a hand on this issue going forward.
> Jason
> On 2/17/09, Ron Grabowski wrote:
> > 
> > The best place to put your code would be on a new JIRA ticket and make sure
> > to grant the ok to include into a ASF project.
> > 
> > I've been thinking about a feature like this but I wanted to get the
> > remaining tickets for the next version closed out (before 4.0 comes out!!!).
> > My original plan was to Fix the events then dispatch them to another worker
> > thread as soon as they arrived so the code would return to the caller as
> > soon as possible. I was thinking more on the ILoggerRepository (Hiearchy)
> > level as opposed to an individual Logger. The Logger level definietly offers
> > more control but part of me things that people would be ok with either all
> > loggers being sync (how it is today) or all-async...allowing them to change
> > on a per Logger level might be too confusing ??? Plus if there's a Thread
> > per Logger and there are a lot of Loggers won't there be a lot of Threads
> > running? I suppose that's why you added a property on a per logger basis to
> > control which specific loggers were async.
> > 
> > ThreadSafeBlockingQueue.Dequeue(Queue) could dequeue the
> > items into LoggingEvent[] to allow IBulkAppenders to better handle the
> > items.
> > 
> > When ForcedLogSub is called with FixFlags.All I think a StackTrace is
> > capture (slow) even if none of the attached appenders use location
> > information. Maybe add some checks to AddAppender to make a FixFlags that is
> > All - LocationInfo.
> > 
> > Its late, I have another solution that I'll write about tomorrow.
> > 
> > ________________________________
> > From: Jason Aubrey 
> > Sent: Tuesday, February 17, 2009 12:13:26 PM
> > Subject: Commit access requested for an asynchronous logging addition
> > 
> > Hi,
> > 
> > I just added a property to my working copy called 'Synchronous'.  It's
> > 'true' by default to maintain the current behavior.  When 'false' the logger
> > will queue log events in a thread safe queue that's serviced by a worker
> > thread.  
> >  
> > The goal of asynchronous logging is to reduce the amount of time incurred by
> > logging on the primary thread.  This can be useful in applications such as
> > in financial trading where time is quite literally money.  It's realized
> > that a data integrity risk is introduced by logging asynchronously, but this
> > is a known and acceptable risk.  I added the synchronous option within the
> > logger instead of the appenders because the behavior should apply to all
> > appenders.
> >  
> > The new/modified files are attached within log4net_trunk.zip.  I don't
> > currently have commit access but I can commit the code if granted access. 
> > There are unit tests for the new code.
> > 
> > Jason Aubrey
> >  

-- 
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.