title: log4net BufferingForwardingAppender performance issue
body: <p><strong>EDIT 2 : I have solved the problem (see answer below) Please note that the problem potentially affects all appenders decorated with BufferingForwardingAppender as well as all appenders inheriting from BufferingAppenderSkeleton (respectively : AdoNetAppender, RemotingAppender, SmtpAppender and SmtpPickupDirAppender) *</strong></p>
  
  <p>I was doing some very basic benchs of log4net and I tried to decorate a RollingFileAppender with a BufferingForwardingAppender.</p>
  
  <p>I experience terrible performance going through the BufferingForwardingAppender instead of directly through the RollingFileAppender and I really don't get the reason.</p>
  
  <p>Here is my configuration:</p>
  
  <pre class="lang-xml prettyprint-override"><code>&lt;appender name="RollingLogFileAppender" type="log4net.Appender.RollingFileAppender"&gt;
    &lt;file value="c:\" /&gt;
    &lt;appendToFile value="false" /&gt;
    &lt;rollingStyle value="Composite" /&gt;
    &lt;datePattern value="'.'MMdd-HH'.log'" /&gt;
    &lt;maxSizeRollBackups value="168" /&gt;
    &lt;staticLogFileName value="false" /&gt;
    &lt;layout type="log4net.Layout.PatternLayout"&gt;      
      &lt;conversionPattern value="%date [%thread] %-5level %logger - %message%newline" /&gt;
    &lt;/layout&gt;
  &lt;/appender&gt;
  
  &lt;appender name="BufferingForwardingAppender" type="log4net.Appender.BufferingForwardingAppender"&gt;
    &lt;bufferSize value="512" /&gt;
    &lt;appender-ref ref="RollingLogFileAppender" /&gt;
  &lt;/appender&gt;
  
  &lt;root&gt;
    &lt;level value="DEBUG" /&gt;
    &lt;appender-ref ref="BufferingForwardingAppender" /&gt;    
  &lt;/root&gt;
  </code></pre>
  
  <p>And here is the benchmark (very simple code):</p>
  
  <pre><code>var stopWatch = new Stopwatch();
  stopWatch.Start();            
  for (int i = 0; i &lt; 100000; i++)            
  {
     Log.Debug("Hello");
  }
  stopWatch.Stop();
  Console.WriteLine("Done in {0} ms", stopWatch.ElapsedMilliseconds);
  </code></pre>
  
  <p>Going directly through RollingFileAppender the output is:</p>
  
  <blockquote>
    <p>Done in 511 ms</p>
  </blockquote>
  
  <p>Whereas going through the BufferingForwardingAppender decorating the RollingFileAppender :</p>
  
  <blockquote>
    <p>Done in 14261 ms</p>
  </blockquote>
  
  <p>That's approx 30 times slower.</p>
  
  <p>I thought I would gain some speed by buffering a certain amount of log before writing them to the file, however for some reason it gets things much worse.</p>
  
  <p>Seems to me like the configuration is OK, so this is really weird. </p>
  
  <p>Anyone got a clue?</p>
  
  <p>Thanks!</p>
  
  <p><strong>EDIT 1 :</strong> </p>
  
  <p>The behavior is strictly the same by wrapping/decorating a FileAppender or even ConsoleAppender (still there is an example of basic BufferingForwardingAppender wrapping/decorating ConsoleAppender in log4net official config samples .. and nothing specific mentioned dealing with performance).</p>
  
  <p>After some investigation/profiling, I can see that the majority of the time is spoiled inside the BufferingForwardingAppender more specifically in a call to WindowsIdentity.GetCurrent() ... being called EACH time we make a call to <code>Log.Debug()</code> .. in the previous sample (100K times in the sample source above). </p>
  
  <p>Calls to this method are known to be very costly and should be avoided or minimized, I really don't get why it gets called for each log event.
  Am I really completely misconfiguring something / not seeing something evident, or is that a bug somehow somewhere, this is what I am trying to figure out now...</p>
  
  <p>The partial call stack is :</p>
  
  <ul>
  <li>AppenderSkeleton.DoAppend</li>
  <li>BufferingAppenderSkeleton.Append</li>
  <li>LoggingEvent.FixVolatileData</li>
  <li>LoggingEvent.get_UserName()</li>
  </ul>
  
  <p>A call to <code>get_LocationInformation()</code> is also done in FixVolatileData, incurring an high perf cost as well (capture the stack trace each time).</p>
  
  <p>I am now trying to understand why this extremely costly FixVolatileData call (at least for the fix asked) happens for each log event in this context whereas going directly through the wrapped appender (directly through ConsoleAppender/FileAppender ..) does not perform this kind of operation.</p>
  
  <p>Upcoming update to follow, unless someone got an answer to all of this ;)</p>
  
  <p>Thanks!</p>