c# - log4net BufferingForwardingAppender performance issue -

edit 2 : have solved problem (see answer below) please note problem potentially affects appenders decorated bufferingforwardingappender appenders inheriting bufferingappenderskeleton (respectively : adonetappender, remotingappender, smtpappender , smtppickupdirappender) *

i doing basic benchs of log4net , tried decorate rollingfileappender bufferingforwardingappender.

i experience terrible performance going through bufferingforwardingappender instead of directly through rollingfileappender , don't reason.

here configuration:

<appender name="rollinglogfileappender" type="log4net.appender.rollingfileappender">   <file value="c:\" />   <appendtofile value="false" />   <rollingstyle value="composite" />   <datepattern value="'.'mmdd-hh'.log'" />   <maxsizerollbackups value="168" />   <staticlogfilename value="false" />   <layout type="log4net.layout.patternlayout">           <conversionpattern value="%date [%thread] %-5level %logger - %message%newline" />   </layout> </appender>  <appender name="bufferingforwardingappender" type="log4net.appender.bufferingforwardingappender">   <buffersize value="512" />   <appender-ref ref="rollinglogfileappender" /> </appender>  <root>   <level value="debug" />   <appender-ref ref="bufferingforwardingappender" />     </root> 

and here benchmark (very simple code):

var stopwatch = new stopwatch(); stopwatch.start();             (int = 0; < 100000; i++)             {    log.debug("hello"); } stopwatch.stop(); console.writeline("done in {0} ms", stopwatch.elapsedmilliseconds); 

going directly through rollingfileappender output is:

done in 511 ms

whereas going through bufferingforwardingappender decorating rollingfileappender :

done in 14261 ms

that's approx 30 times slower.

i thought gain speed buffering amount of log before writing them file, reason gets things worse.

seems me configuration ok, weird.

anyone got clue?

thanks!

edit 1 :

the behavior strictly same wrapping/decorating fileappender or consoleappender (still there example of basic bufferingforwardingappender wrapping/decorating consoleappender in log4net official config samples .. , nothing specific mentioned dealing performance).

after investigation/profiling, can see majority of time spoiled inside bufferingforwardingappender more in call windowsidentity.getcurrent() ... being called each time make call log.debug() .. in previous sample (100k times in sample source above).

calls method known costly , should avoided or minimized, don't why gets called each log event. misconfiguring / not seeing evident, or bug somehow somewhere, trying figure out now...

the partial call stack :

• appenderskeleton.doappend
• bufferingappenderskeleton.append
• loggingevent.fixvolatiledata
• loggingevent.get_username()

a call get_locationinformation() done in fixvolatiledata, incurring high perf cost (capture stack trace each time).

i trying understand why extremely costly fixvolatiledata call (at least fix asked) happens each log event in context whereas going directly through wrapped appender (directly through consoleappender/fileappender ..) not perform kind of operation.

upcoming update follow, unless got answer of ;)

thanks!

i found out issue.

the bufferingforwardingappender inheriting bufferingappenderskeleton (as other appenders making use of logging events buffering such adonetappender, remotingappender, smtpappender ..).

the bufferingappenderskeleton buffering logging events before delivering them target appender once condition met (buffer full example).

according documentation of loggingevent class (representing logging event, , containing values (message, threadid ...) of event) :

some logging events properties considered "volatile", values correct @ time event delivered appenders, not consistent @ time afterwards. if event stored , processed @ later time, these volatile values must fixed bycalling fixvolatiledata. there performance penalty incurred calling fixvolatiledata is essential maintain data consistency

these "volatile" properties represented fixflags enumeration containing flags such message, threadname, username, identity ... volatile properties. contains flag "none" (fix no properties), "all" (fix properties) , "partial" (fix predefine dset of properties).

whem bufferingappenderskeleton instanciated, default sets fixing "all" meaning "volatile" properties should fixed.

in context, each loggingevent appended bufferingappenderskeleton, "volatile" properties fixed before event inserted in buffer. includes properties identity (username) , locationinformation (stack trace) if these properties not included in layout (but guess makes kind of sense if layout changed include these properties @ later time while buffer has been been filled loggingevents).

however in case hurts performance. not including identity , locationinformation in layout , don't plan (mainly performance issues)

now solution ...

there 2 properties in bufferingappenderskeleton can used control fixflags flag value of bufferingappenderskeleton (once again default set "all" not nice !). these 2 properties fix (fixflags type) , onlyfixpartialeventdata (bool type).

for fine tune of flag value or disable fix, fix property should used. specific partial predefined combination of flags (not including identity or locationinfo), onlyfixpartialeventdata can used instead setting "true".

if reuse configuration sample above (in question), change made configuration unleash performance indicated below:

<appender name="bufferingforwardingappender" type="log4net.appender.bufferingforwardingappender">   <buffersize value="512" />   <appender-ref ref="rollinglogfileappender" />   <fix value="0"/> <!-- set fix flag none --> </appender> 

using modified configuration, benchmark code execution presented in question above, dropping approx 14000ms 230ms (60x faster) ! , if use <onlyfixpartialeventdata value="true"/> instead of disabling fix taking approx 350ms.

sadly, flag not documented (except in sdk documentation, little bit) .. had dig deep log4net sources find issue.

this particularly problematic in "reference" configuration samples, flag appears (http://logging.apache.org/log4net/release/config-examples.html). samples provided bufferingforwardingappender, , adonetappender (and other appenders inheriting bufferingappenderskeleton) give terrible performance users, if layout using pretty minimal.