New Implementation: Logger-level Filtering

[Brett Birschbach <br...@nsighttel.com>]

One of my favorite features of log4j is the ability to filter log messages. 
This gives you great control over the logging produced by code written by
someone other than yourself.  However, I believe an improvement can be made
in the implementation of filters to make them much more efficient, better
promoting their use.  

Below I have outlined what I feel is the inefficiency of the current log4j
filtering implemenation, as well as my solution.  As mentioned below, my
solution to the problem adds virtually 0 overhead to users who do not filter
their logging, but provides performance gains for those who do.  

If the developers of log4j are interested, I would love to submit the code
for possible integration into the log4j library.

Please comment.
Thanks!
-Brett Birschbach


Problem
-------
Lets say we have 100 logger classes and 2 appenders (one file, one console)
used by our program (such as a server).  Of the 100 Logger classes, one of
the classes logs messages that we want to pass through a filter.  Using
default log4j, we put our filter at the appender level.  Since we have two
appenders, we will need to add our filter to both of them if we wish to
filter the class for all logs.  Since our filter is at the appender level,
every single logged message, regardless of the Logger class, must pass
through the filter.  In addition, since we have 2 appenders, we must execute
the filter twice for each message.  This seems inefficient.

A more efficient way to filter a single logger class would be to add a
filter directly to that logger.  Thus, instead of filtering the output from
all 100 logger classes, we would only need to filter the output from our 1
specific logger.  Furthermore, since the filtering would be performed prior
to the event being sent to appenders, the filter would only need to be
executed once for all appenders, instead of once per appender as with
default log4j.  

Lets say in our example we log 100 messages, one with each logger class.
Using default log4j, each message is filtered once for each appender. This
results in 100 x 2 = 200 executions of the filter.  To be fair, the first
lines of code in the filter SHOULD check the Logger class, thus preventing
the entire filter from executing for the 99 logger classes
that we do not want to filter, but this is still 198 unnecessary function
calls/string checks.  Using the concept of a Logger filter, however, we
would filter only the 1 message from the specific logger class that we wish
to filter, and then that message would be sent to both appenders.  Thus, we
go from 200 filter calls to 1.

Solution
--------
Since log4j does not implement filters at the logger level, I have
downloaded the source and implemented the functionality myself.  The code
necessarily adds a slight overhead to the logging of unfiltered messages. 
Using a worst case scenario test of logging from a logger class that has 9
ancestors defined in log4j.xml, making it 10 deep in the logger hierarchy,
and using an appender that does nothing with a logging event but throw it
out, I experienced a less than 15% drop in performance in unfiltered log
messages.  In reality, most loggers would only have 1 to 3 ancestors defined
in log4j.xml, reducing this performance drop to likely 5-8% at worst. Most
importantly, when using an actual appender that writes out to a resource,
such as a file, this performance drop becomes negligible due to the time it
takes to actually write the log statement to the resource.  Though there is
a (minimal) performance hit on non-filtered statements, that loss is easily
regained by use of a single logger-level filter vs. an appender-level
filter.

I implemented logger filters as an "opt-in" system where a configuration
setting in the log4j.xml file must be set.  For programs using log4j with my
new filtering implementation, but have no need for logging filters at all,
they can leave this attribute out as it will default to false.  With logger
level filters disabled, any minimal overhead added by my new filtering code
will be avoided with the exception of a boolean check and an extra function
call, putting performance virtually identical to the current log4j
implementation.

As stated before, the use of a single logger level filter will in most cases
easily regain the lost performance due to extra overhead and instead
increase logging performance.  As logger filters and/or appenders are added
to the log configuration, the performance delta is extremely small using my
implementation, making filtering very efficient.  By contrast, the default
log4j appender level filter solution has an extremely high performance delta
per filter or (filtered) appender.


-- 
View this message in context: http://www.nabble.com/New-Implementation%3A-Logger-level-Filtering-tf3784606.html#a10702970
Sent from the Log4j - Users mailing list archive at Nabble.com.


---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org

Re: New Implementation: Logger-level Filtering

[Brett Birschbach <br...@nsighttel.com>]

As far as I know, log4j does not have a "ForwardingAppender" concept. 
However, implementing it is relatively trivial.  I actually rolled my own a
few months back trying to solve the problem of over filtering.  

In the end, a logger level filter still makes configuration MUCH more
straight forward, as well as providing a performance benefit.  Allow me to
explain the complexity and lower efficiency of the "ForwardingAppender"
approach:

=============================================================
A simple configuration is like you would expect:

  <appender name="ROOT_APPENDER"
class="com.XXXXXXXXX.log4j.appender.ForwardingAppender">
     <appender-ref ref="FILEAPPENDER"/>
     <appender-ref ref="CONSOLEAPPENDER"/>
  </appender>
  <appender name="MY_FILTERED_APPENDER"/>
class="com.XXXXXXXXX.log4j.appender.ForwardingAppender">     
     <filter class="com.XXXXXXXXX.log4j.MyFilterForXYZDOSTUFF"/>
     <appender-ref ref="ROOT_APPENDER"/>
  </appender>

  <logger name="com.xyz.dostuff" additivity="false">
     <appender-ref ref="MY_FILTERED_APPENDER"/>
  </logger>
  <root>
      <appender-ref ref="ROOT_APPENDER"/>
  </root>

On the surface the solution looks good.  However, let's say I want to add
another appender for all classes in com.xyz

  <logger name="com.xyz" additivity="true">
     <appender-ref ref="XYZFILE"/>
  </logger>

Since, to prevent duplicate log entries, additivity="false" for
com.xyz.dostuff, if I want the output from com.xyz.dostuff to go to XYZFILE
appender as well (since it is a subclass of com.xyz), now I need to add the
appender to com.xyz AND com.xyz.dostuff:

 <logger name="com.xyz" additivity="true">
     <appender-ref ref="NEW_COM_XYZ_APPENDER"/>
 </logger>
 <logger name="com.xyz.dostuff" additivity="false">
     <appender-ref ref="NEW_COM_XYZ_APPENDER"/>
     <appender-ref ref="MY_FILTERED_APPENDER"/>
 </logger>

Not only am I duplicating appender references and creating ever increasing
complexity, but more importantly I have the same problems as originally.  I
have to filter both MY_FILTERED_APPENDER and NEW_COM_XYZ_APPENDER.  Instead
of just filtering log messages once, I have to filter them twice, once for
each appender.  Furthermore, instead of simply filtering log events from the
com.xyz.dostuff package, as I was before, now I am filtering all logging
events from all com.xyz.* packages due to filtering NEW_COM_XYZ_APPENDER.
===========================================================

As I state before, a Logger filter is still simpler and more efficient.




Ron Grabowski wrote:
> 
> 
> In log4net we have a ForwardingAppender that takes a message and fowards
> it to one or more other appenders. To solve the problem of not having to
> apply filters twice I'd put a ForwardingAppender infront of the two other
> appenders. If the message passed through the filters on the
> FowardingAppender the message would be sent to the registered appenders
> (in your example that would be a file and console). Is there something
> equivalent to a ForwardingAppender in log4j?
> 
> 


-- 
View this message in context: http://www.nabble.com/New-Implementation%3A-Logger-level-Filtering-tf3784606.html#a10795743
Sent from the Log4j - Users mailing list archive at Nabble.com.


---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org