c# - application - Log4net BufferingForwardingAppender problema de rendimiento

log4net install

Question

EDIT 2: solucioné el problema (vea la respuesta a continuación) Tenga en cuenta que el problema puede afectar a todos los agregadores decorados con BufferingForwardingAppender, así como a todos los agregados que heredan de BufferingAppenderSkeleton (respectivamente: AdoNetAppender, RemotingAppender, SmtpAppender and SmtpPickupDirender) *

Estaba haciendo algunos bancos muy básicos de log4net y traté de decorar un RollingFileAppender con un BufferingForwardingAppender.

Experimenté un rendimiento terrible al pasar por el BufferingForwardingppender en lugar de hacerlo directamente a través de RollingFileAppender y realmente no entiendo la razón.

Aquí está mi configuración:

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

Y aquí está el punto de referencia (código muy simple):

var stopWatch = new Stopwatch();
stopWatch.Start();            
for (int i = 0; i < 100000; i++)            
{
   Log.Debug("Hello");
}
stopWatch.Stop();
Console.WriteLine("Done in {0} ms", stopWatch.ElapsedMilliseconds);

Pasando directamente a través de RollingFileAppender, la salida es:

Hecho en 511 ms.

Mientras que va a través de BufferingForwardingAppender decorando el RollingFileAppender:

Hecho en 14261 ms

Eso es aproximadamente 30 veces más lento.

Pensé que ganaría algo de velocidad al almacenar una cierta cantidad de registros antes de escribirlos en el archivo, sin embargo, por alguna razón, las cosas empeoran.

Me parece que la configuración está bien, así que esto es realmente extraño.

¿Alguien tiene una pista?

¡Gracias!

EDITAR 1:

El comportamiento es estrictamente el mismo envolviendo / decorando un FileAppender o incluso ConsoleAppender (todavía hay un ejemplo de BufferingForwardingAppender envolviendo / decorando ConsoleAppender en los ejemplos de configuración oficial de log4net .. y nada específico se refiere al rendimiento).

Después de algunas investigaciones / perfiles, puedo ver que la mayoría del tiempo se echa a perder dentro del BufferingForwardingAppender más específicamente en una llamada a WindowsIdentity.GetCurrent () ... se llama CADA vez que hacemos una llamada a Log.Debug() .. en la muestra anterior (100K veces en la fuente de muestra anterior).

Se sabe que las llamadas a este método son muy costosas y se deben evitar o minimizar, realmente no entiendo por qué se llama para cada evento de registro. ¿Realmente estoy malinterpretando completamente algo / no veo algo evidente, o es un error de alguna manera en algún lugar, esto es lo que estoy tratando de averiguar ahora ...

La pila de llamadas parciales es:

• AppenderSkeleton.DoAppend
• BufferingAppenderSkeleton.Append
• LoggingEvent.FixVolatileData
• LoggingEvent.get_UserName ()

También se realiza una llamada a get_LocationInformation() en FixVolatileData, incurriendo también en un alto costo de rendimiento (captura el seguimiento de la pila cada vez).

Ahora estoy tratando de entender por qué esta llamada FixVolatileData extremadamente costosa (al menos para la corrección solicitada) ocurre para cada evento de registro en este contexto, mientras que ir directamente a través del appender envuelto (directamente a través de ConsoleAppender / FileAppender ..) no realiza este tipo de operación.

Próxima actualización a seguir, a menos que alguien tenga una respuesta a todo esto;)

¡Gracias!

Answer 1

Es posible que sea porque no está especificando un patrón de diseño en BufferingForwardingAppender pero está en RollingLogFileAppender por lo tanto, BufferingForwardingAppender incluye todo en su salida, incluido el nombre de usuario (% username)

A continuación se muestra un interesante artículo de blog que tiene una lista de las opciones en los diseños de patrones y parece que tiene varias de ellas marcadas como lentas.

http://www.beefycode.com/post/Log4Net-Tutorial-pt-4-Layouts-and-Patterns.aspx

Answer 2

Me enteré del problema.

El BufferingForwardingAppender se hereda de BufferingAppenderSkeleton (al igual que otros agregadores que utilizan el registro de eventos en el búfer, como AdoNetAppender , RemotingAppender , SmtpAppender ...).

El BufferingAppenderSkeleton realidad almacena en búfer los eventos de registro antes de entregarlos realmente al aplicador de destino una vez que se cumple una determinada condición (búfer lleno, por ejemplo)

De acuerdo con la documentación de la clase LoggingEvent (que representa un evento de registro y que contiene todos los valores (mensaje, threadid ...) del evento):

Algunas propiedades de eventos de registro se consideran "volátiles", es decir, los valores son correctos en el momento en que se entrega el evento a los agregadores, pero no serán consistentes en ningún momento posterior. Si se va a almacenar un evento y procesarlo en un momento posterior, estos valores volátiles se deben corregir llamando FixVolatileData. Se produce una penalización de rendimiento al llamar a FixVolatileData, pero es esencial para mantener la consistencia de los datos.

Estas propiedades "volátiles" están representadas por la enumeración FixFlags contiene FixFlags como Mensaje, Nombre de hilo, Nombre de usuario, Identidad ... así que todas las propiedades volátiles. También contiene el indicador "Ninguno" (no corregir propiedades), "Todos" (corregir todas las propiedades) y "Parcial" (corregir solo un determinado conjunto de propiedades predefinido).

En el caso de que BufferingAppenderSkeleton se ejecute, por DEFAULT establece la fijación en "Todas", lo que significa que todas las propiedades "volátiles" deben corregirse.

En ese contexto, para cada LoggingEvent agregado en el BufferingAppenderSkeleton, TODAS las propiedades "volátiles" se corregirán antes de que el evento se inserte en el búfer. Esto incluye las propiedades Identidad (nombre de usuario) y LocationInformation (seguimiento de la pila) incluso si estas propiedades no están incluidas en el diseño (pero creo que tiene algún sentido si se modifica el diseño para incluir estas propiedades en un momento posterior, mientras que un búfer ya ha sido llenado con LoggingEvents).

Sin embargo, en mi caso esto realmente duele el rendimiento. No incluyo la Identidad y la Información de Ubicación en mi diseño y no planeo hacerlo (principalmente por problemas de rendimiento)

Ahora para la solución ...

Hay dos propiedades en BufferingAppenderSkeleton que se pueden usar para controlar el valor del indicador FixFlags del BufferingAppenderSkeleton (una vez más, de forma predeterminada, se establece en "TODOS", lo que no es muy bueno). Estas dos propiedades son Fix (tipo FixFlags) y OnlyFixPartialEventData (tipo bool).

Para un ajuste fino del valor del indicador o para deshabilitar todas las correcciones, se debe usar la propiedad Fix . Para una combinación parcial predefinida de indicadores específica (sin incluir Identity o LocationInfo), se puede usar OnlyFixPartialEventData su lugar, configurándolo en "true".

Si reutilizo el ejemplo de configuración anterior (en mi pregunta), el único cambio realizado en la configuración para liberar el rendimiento se indica a continuación:

<appender name="BufferingForwardingAppender" type="log4net.Appender.BufferingForwardingAppender">
  <bufferSize value="512" />
  <appender-ref ref="RollingLogFileAppender" />
  <Fix value="0"/> <!-- Set Fix flag to NONE -->
</appender>

¡Al usar esta configuración modificada, la ejecución del código de referencia presentada en mi pregunta anterior, se está reduciendo de aproximadamente 14000 ms a 230 ms (60 veces más rápido)! Y si uso <OnlyFixPartialEventData value="true"/> lugar de deshabilitar todo el arreglo, está tomando aproximadamente 350ms.

Lamentablemente, esta bandera no está muy bien documentada (excepto en la documentación del SDK, un poco) ... así que tuve que profundizar en las fuentes de log4net para encontrar el problema.

Esto es particularmente problemático, especialmente en los ejemplos de configuración de "referencia", esta bandera no aparece en ninguna parte (http://logging.apache.org/log4net/release/config-examples.html). Por lo tanto, los ejemplos proporcionados para BufferingForwardingAppender y AdoNetAppender (y otros agregadores que heredan de BufferingAppenderSkeleton) proporcionarán un rendimiento TERRIBLE a los usuarios, incluso si el diseño que están usando es bastante mínimo.