En este artículo he colocado puntos de referencia de las llamadas más privadas de los madereros. Realicé todos los experimentos en log4net y NLog, en Intel Windows 10 x64 con M.2 SSD.

Los resultados sin procesar se pueden ver en GitHub . El código está en el mismo repositorio (para ejecutar, necesitará .Net 4.7.2 + Microsoft Visual Studio 2017+).

Qué, cómo y por qué, debajo del corte.

Para no leer durante mucho tiempo, la tabla de resultados:

NoOpLogging

Primero, calculemos cuánto tiempo pasamos llamando a un método para iniciar sesión, que al final no conducirá a nada. En la mayoría de los casos (en mi experiencia), la depuración detallada está deshabilitada en los servidores de batalla, pero nadie elimina las llamadas.

Primero, el resultado:

Y el código:

void Log4NetNoParams() => _log4Net.Debug("test"); void Log4NetSingleReferenceParam() => _log4Net.DebugFormat("test {0}", _stringArgument); void Log4NetSingleValueParam() => _log4Net.DebugFormat("test {0}", _intArgument); void Log4NetMultipleReferencesParam() => _log4Net.DebugFormat( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument); void Log4NetMultipleValuesParam() => _log4Net.DebugFormat( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument); void NLogNetNoParams() => _nlog.Debug("test"); void NLogNetSingleReferenceParam() => _nlog.Debug("test {0}", _stringArgument); void NLogNetSingleValueParam() => _nlog.Debug("test {0}", _intArgument); void NLogNetMultipleReferencesParam() => _nlog.Debug( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument); void NLogNetMultipleValuesParam() => _nlog.Debug( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument); 

Primero, determinemos por qué se eligieron tales pruebas:

• Los experimentos se realizaron en las bibliotecas más populares.

• NLog y log4net tienen diferentes firmas de función para una pequeña cantidad de argumentos:

  
  
  • log4net:
  
  

   void DebugFormat(string format, object arg0) 

  
  
  • Nlog:
  
  

   void Debug(string message, string argument) void Debug<TArgument>(string message, TArgument argument) 

  
  
  • Teoría: cuando se transfiere un tipo significativo a log4net, debe producirse un boxeo, que simplemente pasa el tiempo del procesador y no conduce a nada. En el caso de NLog, no existe tal comportamiento, por lo que este último debería funcionar más rápido.
  
  
• Las firmas para una gran cantidad de argumentos en las bibliotecas son aproximadamente las mismas, por lo que me gustaría saber:
  
  • ¿Cuánto más eficiente es invocar métodos con un pequeño número de parámetros?
  • ¿Hay alguna diferencia en la velocidad de llamar al método "Está ... habilitado" entre las dos bibliotecas

Y ahora el análisis de los resultados:

• Debido al uso de argumentos genéricos en NLog, funciona más rápido para el caso cuando el registro directo no es necesario. Es decir, en el caso de que en su programa de depuración el nivel esté habilitado solo en el sistema de prueba, solo cambiar la biblioteca puede acelerar el software (y mejorar la vida de los usuarios).
• Si tiene el registro desactivado y desea llamar a un método con una gran cantidad de argumentos, es más eficiente dividirlo en dos. Debido a esto, las llamadas a métodos anteriores funcionarán diez veces más rápido.
• Cuando escribe una función que puede tomar cualquier objeto, a menudo es más efectivo confundirse y hacer una función genérica. Debido a una optimización tan simple, el código funcionará más rápido (esto se ve claramente en la diferencia de tiempo entre las llamadas a Log4NetSingleReferenceParam y Log4NetSingleValueParam )

Registro de archivos

La mayoría de los programas (de acuerdo con mis observaciones) todavía registran los resultados en un archivo, por lo que para la comparación elegimos esta operación. Para simplificar, simplemente tomamos la configuración de los registradores cuando un archivo se escribe en el archivo sin almacenamiento en búfer, sin bloqueos adicionales, etc.

Resultados:

Código utilizado:

• log4net:

 var roller = new RollingFileAppender(); roller.ImmediateFlush = true; roller.RollingStyle = RollingFileAppender.RollingMode.Once; roller.MaxFileSize = 128 * 1000 * 1000; 

• Nlog:

 new FileTarget($"target_{_logIndex++}") { ArchiveAboveSize = 128 * 1000 * 1000, MaxArchiveFiles = 16, AutoFlush = true, ConcurrentWrites = false, KeepFileOpen = false }; 

Como puede ver, la configuración de los registradores es más o menos similar y según los resultados:

• NLog es un poco más rápido que log4net, en algún lugar alrededor del 15%.
• Según las pruebas, resultó que es más eficiente registrar menos parámetros. Sin embargo, no se debe olvidar que con un mayor número de parámetros, la cadena resultante también se expandió. Por lo tanto, la tabla solo compara correctamente NLog con log4net.

NLog - diferentes tipos de cerraduras

Código fuente:

 new FileTarget($"target_{_logIndex++}") { ArchiveAboveSize = 128 * 1000 * 1000, MaxArchiveFiles = 16, AutoFlush = true, ConcurrentWrites = XXXXX, KeepFileOpen = YYYYY }; 

Si ponemos todas las combinaciones posibles en lugar de XXXXX y AAAA, obtenemos la prueba de la tabla.

Los resultados son bastante predecibles:

• Si habilita ConcurrentWrites, entonces el sistema tomará constantemente y le dará Mutex, que no es gratuito. Pero, como vemos, escribir una línea en un archivo es aproximadamente equivalente a un bloqueo del sistema.
• Cerrar y abrir un archivo, como vemos, afecta aún más el rendimiento del sistema. En los ejemplos con KeepFileOpen=true para cada operación de registro, creamos un archivo (junto con Handle), escribimos en el disco, llamado Flush, devolvimos Handle y también realizamos muchas operaciones de capó del motor. Como resultado, la velocidad cae cientos de veces.

Registro asincrónico y diferentes métodos de bloqueo.

La biblioteca NLog también puede realizar todas las operaciones de E / S en otro subproceso, liberando inmediatamente el actual. Y lo hace de manera competente, preservando el orden de los eventos, colocando todos los datos en bloques, y en cada bloque un número entero es un número de evento (para que no se obtengan líneas recortadas), y así sucesivamente.

Los resultados de diferentes métodos sin bloqueo:

La comparación de los enfoques de bloqueo y asincrónicos será más profunda, pero aquí, solo la última.

Código AsyncTargetWrapper :

 new AsyncTargetWrapper(fileTargetWithConcurrentWritesAndCloseFileAsync) { OverflowAction = AsyncTargetWrapperOverflowAction.Block, QueueLimit = 10000 } 

Como puede ver, la configuración del contenedor es tal que un volcado directo al archivo no lleva bastante tiempo. Por lo tanto, se acumula un búfer grande, lo que significa que todas las operaciones intensivas en recursos, como "abrir archivo", se realizan una vez para todo el bloque. Sin embargo, dicho algoritmo requiere memoria adicional (y mucha).

Conclusiones:

• Si se utiliza una salida asincrónica, no importa qué tipo de configuración de salida se use con el archivo. Puede abrir y cerrar el archivo cada vez, con un búfer grande será casi imperceptible.
• Todas las mediciones son verdaderas solo para el caso en que los datos se descargan en el disco a aproximadamente la misma velocidad que el llenado de las memorias intermedias (lo hice debido al sistema de archivos rápido + pausas naturales entre mediciones).

Registro síncrono y asíncrono

Conclusiones:

• A pesar del disco rápido (en mi caso, SSD M.2), escribir en un archivo en otra secuencia acelera el trabajo varias veces. Si su aplicación escribe en discos HDD e incluso se ejecuta en una máquina virtual, la ganancia será aún mayor.
• Sin embargo, a pesar de la operación incluso rápida del código asincrónico, la falta de registro proporciona una ganancia aún mayor (aunque ligeramente diferente, dependiendo de la biblioteca).

Crear registradores

Resultados:

Lo que fue probado:

 [Benchmark] public object CreateLog4NetFromString() { return LogManager.GetLogger("my-logger_" + (Interlocked.Increment(ref _log4NetStringLogIndex) % 1000)); } [Benchmark] public object CreateNLogFromString() { return NLog.LogManager.GetLogger("my-logger_" + (Interlocked.Increment(ref _nLogStringLogIndex) % 1000)); } [Benchmark] public object CreateLog4NetLogger() { return new [] { LogManager.GetLogger(typeof(BaseTest)), // x16 times }; } [Benchmark] public object CreateNLogTypeOfLogger() { return new[] { NLog.LogManager.GetCurrentClassLogger(typeof(BaseTest)), // x16 times }; } [Benchmark] public object CreateNLogDynamicLogger() { return new[] { NLog.LogManager.GetCurrentClassLogger(), // x16 times }; } 

Comentario importante: desafortunadamente, fue difícil para mí hacer un punto de referencia reproducible que no condujera a la falta de memoria, pero que crearía diferentes registradores (es decir, para diferentes tipos, para diferentes líneas, etc.).

Sin embargo, después de estudiar el trabajo de las bibliotecas, descubrí que se realizan casi las operaciones más difíciles para crear una clave de registro (es decir, determinar un nombre, borrar argumentos genéricos, etc.).
Además, para estabilizar el punto de referencia para crear un registrador para log4net, fue necesario realizar no una operación, sino 16 (es decir, se devuelve una matriz de 16 objetos idénticos). Si no devuelve nada, .Net optimizó la ejecución para mí (aparentemente, simplemente no devolvió el resultado), lo que condujo a resultados incorrectos.

Y conclusiones:

• Los registradores se crean más rápidamente a partir de cadenas (NLog es más rápido nuevamente, sin embargo, la diferencia entre las bibliotecas es pequeña, teniendo en cuenta que los registradores se crean no solo así, sino para el trabajo posterior con ellos).
• log4net es más rápido que NLog al inicializar un proyecto. Quizás esto se deba al almacenamiento en caché adicional en el lado NLog, que ayuda a acelerar las llamadas directas a Debug , Info , etc. De hecho, cada ILogger conoce la respuesta a sí mismo: si debe llamar a los siguientes métodos o no (y esto requiere al menos algún tipo de enlace a la configuración general). Debido a este esquema de trabajo, Out of Memory fue utilizado por mí en la mayoría de las pruebas (si uso diferentes líneas, etc.).
• LogManager.GetCurrentClassLogger() es incluso más lento que LogManager.GetLogget(typeof(XXX)) . Esto es lógico, incluso los desarrolladores de NLog no recomiendan llamar al primer método en un bucle.
• Y lo más importante: la velocidad de todos estos métodos a menudo afecta solo el inicio en frío de la aplicación cuando private static readonly ILogger Log = LogManager.GetCurrentClassLogger() campos de la forma private static readonly ILogger Log = LogManager.GetCurrentClassLogger() . Es decir, no afecta directamente el rendimiento del sistema.

Conclusión

¿Cuál es la mejor manera de manejar los registros?

• Si es posible no iniciar sesión en absoluto, este será el más rápido (lo cual es obvio hasta ahora).
• Si el proyecto tiene muchas llamadas de registrador que no vuelcan datos a un archivo (a la consola, etc.), entonces NLog es más rápido. Además, asigna menos objetos en el montón.
• Si aún necesita escribir en un archivo, NLog funciona de forma asíncrona con la mayor rapidez. Sí, consume más memoria (en comparación con NLog en modo síncrono, ya que de acuerdo con mis mediciones anteriores, log4net ni siquiera intenta reutilizar las matrices y Stream 's). Sin embargo, el programa podrá ejecutarse más rápido.
• Crear un registrador no es una operación gratuita, por lo que a menudo es mejor crearlo con un campo estático. Esto no se aplica a la creación de una cadena, es decir, algo así como LogManager.GetLogger("123") . Estas llamadas funcionan más rápido, lo que significa que se puede crear un registrador para grandes instancias de objetos (por ejemplo, "un registrador para el contexto de la consulta").
• Si desea generar muchos parámetros en el registro, pero en la mayoría de los casos no habrá volcado directo de datos en el archivo, entonces es mejor hacer varias llamadas. Por lo tanto, NLog no creará objetos adicionales en el montón si no se necesitan allí.

Conclusiones para su código:

• Si su método acepta un objeto arbitrario (es decir, un object ) y en la mayoría de los casos no hace nada (lo cual es cierto para los contratos / validadores), entonces es más correcto ajustar las llamadas en una forma genérica (es decir, hacer métodos de la forma Something<TArg>(TArg arg) ). Esto funcionará realmente más rápido.
• Si en su código se permite un restablecimiento de datos de archivo y al mismo tiempo funciona con otra cosa, es mejor confundirse y respaldar esto. Sí, parece obvio que la ejecución paralela puede acelerar el trabajo, sin embargo, en el caso de las operaciones de E / S, este enfoque también brinda un aumento de rendimiento adicional en máquinas con discos lentos.