Hola Habr!
Creo que casi todos los programas tienen registro. Además, en una serie de aplicaciones ya nuevas (lo que significa un mar de condiciones no triviales), los registros a menudo se vuelven vitales en un servidor de combate.
Sin embargo, a pesar de la importancia y prevalencia de dicha tecnología, noté que las personas a menudo cometen errores estándar cuando trabajan con ellos. Este artículo describe el comportamiento de .Net en muchos aspectos, sin embargo, hice pequeños insertos del mundo Java, solo para tener una comparación.
Asignaciones (asignación de memoria)
El error más común (según mis observaciones) es una negligencia en relación con pequeñas asignaciones de memoria cerca del lugar de la llamada al log.Debug(...) . Función de log.Debug(...) .
Entonces, nuestro código estándar en .Net:
private static readonly ILog Log4NetLog = LogManager.GetLogger(typeof(Program)); private static readonly Logger NLogLog = NLog.LogManager.GetCurrentClassLogger(); private static void PublishData(int id, string name, EMail email, decimal amount) { Log4NetLog.Debug($"Id={id}"); // 1 Log4NetLog.DebugFormat("Id={0}", id); // 2 Log4NetLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 3 Log4NetLog.DebugFormat("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 4 NLogLog.Debug($"Id={id}"); // 5 NLogLog.Debug("Id={0}", id); // 6 NLogLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 7 NLogLog.Debug("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 8 }
En muchos sentidos, solo vi las bibliotecas log4net y NLog , y por lo tanto las usaré en los ejemplos.
Entonces las preguntas son:
- ¿En qué líneas se asignará la memoria incluso si la depuración está desactivada?
- Si se asigna memoria, ¿qué tan fácil es detectar en el mismo dotTrace que específicamente los registradores tienen la culpa de esta asignación de memoria?
La respuesta correcta a la primera pregunta: la memoria no se asigna solo en el párrafo "6". Y la respuesta a la segunda pregunta: es increíblemente difícil de atrapar, porque ese código a menudo se extiende por el proyecto. Puede recordar una aplicación típica .Net. A menudo tendrá un código similar que hace que GC funcione.
Sin embargo, repasemos los detalles técnicos para comprender exactamente dónde tendremos un impacto en el rendimiento.
Entonces el primer punto:
Log4NetLog.Debug($"Id={id}"); // 1
De hecho, el compilador lo convertirá a:
var temp = string.Format("Id={0}", id); // <-- Log4NetLog.Debug(temp);
Es decir, la primera expresión esencialmente obligará al procesador a crear una cadena, pasarla al registrador. Comprobará rápidamente que no es necesario iniciar sesión y, por lo tanto, la línea se acaba de crear en la memoria. Y, lo que es más importante, si copia más de dicho código, las líneas se crearán en muchos lugares del programa, es decir, el programa funcionará un poco más lento. En todas partes
El segundo ejemplo es un poco más eficiente, ya que no se crea una línea en él:
Log4NetLog.DebugFormat("Id={0}", id);
Sin embargo, la memoria todavía está asignada aquí, ya que se producirá un boxeo. Déjame recordarte la firma del método DebugFormat:
void DebugFormat(string format, object arg0)
Como puede ver, la entrada requiere un tipo de referencia. Sin embargo, estamos tratando de pasar un tipo int significativo. Como resultado, cada llamada dará como resultado que se pase la id parámetro del montón para pasarla al método. Y permítame recordarle que el parámetro en sí no es necesario en el método en sí, ya que Debug está desactivado por la condición de la tarea.
El siguiente ejemplo es cargado y simple:
Log4NetLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 3
Estoy seguro de que ya entendió que nuevamente la línea se destacará en el montón y así sucesivamente. Por lo tanto, omita inmediatamente este ejemplo. El siguiente método de llamada parece más eficiente:
Log4NetLog.DebugFormat("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 4
Y esto es así, sin embargo, calculemos cuántas veces es necesario asignar un trozo de memoria:
email.Normalize() conduce a la creación de algún tipo de objeto. Por lo tanto, este objeto se asignará en el montón (o en la pila, no importa, ya que el boxeo hará que sea necesario seleccionar todo en el montón)id irá a un montón, como ya hemos considerado anteriormente.- Log4net tiene la siguiente interfaz para llamadas con formato largo:
void DebugFormat(string format, params object[] args) . Como puede ver, .Net creará una matriz en el montón para pasarla al método DebugFormat .
Como resultado, una llamada bastante típica a la operación de registro conducirá a la creación de un montón de objetos en la memoria. Lo cual es bastante decepcionante, ya que el registro en sí mismo a menudo está desactivado. Sin embargo, pasemos a NLog.
Esta línea provocará la asignación del objeto en el montón:
NLogLog.Debug($"Id={id}");
Aquí todo es obvio, pero la siguiente línea ya no tiene ese inconveniente:
NLogLog.Debug("Id={0}", id);
Y la razón es que NLog tiene una firma especial para ints: void Debug(string message, int argument) . Además, incluso si transfiere una estructura diferente, void Debug<TArgument>([Localizable(false)] string message, TArgument argument) . Y este método no requiere boxeo, ya que después de JIT se creará una función separada para cada tipo (por supuesto, esto no es del todo cierto, pero el punto importante es: no habrá boxeo).
Me saltearé el script fácil de entender con una línea de entrada grande e iré directamente a:
NLogLog.Debug("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount);
Por extraño que parezca, NLog no aumentó el número de parámetros genéricos para los métodos y, por lo tanto, se usará la firma: void Debug([Localizable(false)] string message, params object[] args) . Y nuevamente conducirá a la creación de objetos en montones, etc.
Conclusiones y mejoras
La conclusión principal: si tiene muchas llamadas a los métodos de registro en el programa que no conducen a la escritura física en el archivo, entonces puede comenzar de inmediato para asignar muchos objetos innecesarios en el montón. Y por lo tanto inhibiendo el trabajo del programa.
Conclusión 2: si no pasa muchos objetos a un método, use NLog. Debido al hecho de que se ocupó de los parámetros genéricos, puede estar más relajado sobre el rendimiento.
Sin embargo, para estar completamente seguro, es más lógico hacer esto:
if (NLogLog.IsDebugEnabled) { NLogLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); }
Aquí no se llamará al método de registro si no es necesario. Sin embargo, si todavía tiene que volcar los datos en el registro, se utilizará la conveniente Interpolación de cadenas. En el interior, los registradores (al menos el mismo NLog) tienen optimizaciones para escribir una línea en los registros directamente (es decir, el formateo ocurrirá inmediatamente en Stream , en lugar de crear una línea en la memoria). Sin embargo, esta optimización de NLog se desvanece con el hecho de que debe restablecer los datos a un archivo.
Ejemplo de Kotlin
Para diluir la descripción del trabajo de los registradores populares en .Net, daré una forma interesante de ajustar las llamadas en kotlin. La idea se basa literalmente en una característica interesante del lenguaje: los métodos en línea . Entonces, un código simple para generar algo para depurar:
class SomeService{ private companion object : KLogging() fun publishData(id: Int){ logger.debug { "Identity: $id" } } }
Y el compilador lo convertirá en algo como esto:
class SomeService{ private companion object : KLogging() fun publishData(id: Int){ if(logger.isDebugEnabled){ try{ val message = "Identity: $id" logger.debug(message) }catch (e: Exception){ } } } }
Aquí es importante: todo dentro de los corchetes cerca de la debug es una lambda. Sin embargo, se incrustará en su método, es decir, no se creará un objeto de función en el montón. Por lo tanto, puede ocultar operaciones grandes en el interior, que se invocarán solo si desea generar el resultado para debug . Por ejemplo:
class SomeService{ private companion object : KLogging() fun publishData(id: Int){ logger.debug { val idList = getIdList() "Identity: $idList" } } }
Aquí se getIdList a getIdList solo si necesita enviar algo al archivo. Y todo porque el código se convierte a:
class SomeService{ private companion object : KLogging() fun publishData(id: Int){ if(logger.isDebugEnabled){ try{ val idList = getIdList() val message = "Identity: $idList" logger.debug(message) }catch (){ } } logger.debug { "Identity: $id" } } }
Objeto grande ==> Montón de objetos grandes
Además del ejemplo anterior. Estoy seguro de que muchas personas saben que .Net / JVM tiene el concepto de "Montón de objetos grandes". Más precisamente, no existe una definición especial en Java, sin embargo, los asignadores a menudo crean objetos grandes inmediatamente en la última generación (para minimizar el movimiento de los objetos y nivelar el problema de la rápida penetración de la memoria para un asignador de transmisión).
De vuelta al ejemplo:
NLogLog.Debug($"Id={id}");
Como comprenderá, si el objeto id tiene una implementación de ToString , que crea una cadena del tamaño de un megabyte, los siguientes hits en la cara LOH:
ToString llama a sí mismo- Formateando
$"Id={id}" - Y si los desarrolladores del registrador no captaron todas estas cosas (y es extremadamente difícil escribir una prueba para la ausencia de objetos en LOH), entonces el registrador agregará problemas.
Y aquí puede usar tres métodos para registrar tales cosas:
- Use un diseño especial y no requiera una llamada a
ToString . Por ejemplo, NLog tiene un JsonLayout . Por lo tanto, simplemente puede transferir un objeto al registrador, que se serializará inmediatamente a la secuencia resultante (por ejemplo, a un archivo). - Escribe en el archivo tú mismo. O en otras palabras, no use el registrador. Solo puedo aconsejar por mi cuenta cómo averiguar en qué archivo escribirá NLog:
var filePath = NLog.LogManager.Configuration.AllTargets.OfType<FileTarget>().First().FileName.Render(LogEventInfo.CreateNullEvent()) . Obviamente, esta función devolverá el primer FileTarget que aparece, pero si todos escriben en la misma carpeta, de manera similar, puede encontrar la carpeta para la grabación y luego enviar directamente un volcado de su objeto al archivo. - Si tiene log4j2 (el segundo es importante), puede usar StringBuilderFormattable . Acaba de crearse para generar datos en el registrador en partes (además, para no asignar parte de las partes en el montón, ya que ya están seleccionadas).
public interface StringBuilderFormattable { void formatTo(StringBuilder buffer); }
Sincronía (y problemas de asincronía)
Una vez, en un programa, noté que durante las operaciones cargadas, aproximadamente la mitad del tiempo de espera de la IU se contabilizaba en las operaciones de registro. Una vez más: la mitad del tiempo del programa se dedicó a una llamada al logger.Debug o algo así. Y la razón de esto es simple: utilizamos log4net, que puede escribir archivos solo sincrónicamente.
De aquí deduje la regla 1 : el registrador siempre debería funcionar en otro hilo. No debe bloquear el código de la aplicación en aras de los rastros, porque es increíblemente extraño. En otras palabras, usando NLog, siempre necesita poner async=true en la etiqueta nlog (es la principal). O, como dice el ejemplo :
<targets async="true"> ... your targets go here ... </targets>
Si usa log4net, entonces redirija desde él a NLog o realice AsyncFileAppender.
Para el mundo Java: tanto Logback como Log4J2 tienen la capacidad de realizar registros asincrónicos. Aquí hay una comparación del sitio oficial :
Sin embargo, cuando todo se escribe de forma asíncrona, surge otro problema: ¿qué hacer en caso de errores críticos? Después de todo, sucede que un programa no sale porque ha salido del hilo Main (por ejemplo, un programa puede salir llamando a Application.Exit o Environment.FailFast , que no es muy bonito, pero ocurre). En este caso, siempre debe llamar a Flush antes de finalizar su proceso. De lo contrario, si caes en el servidor de batalla, se perderá la información más valiosa.
Conclusión
Espero que este artículo te ayude a escribir programas rápidos con un registro conveniente. Destaqué solo una parte de los problemas que veo en el código. Todos ellos no son los más obvios, pero no los más difíciles.
En cualquier caso, como dije al principio, trabajar con registradores está en casi todas las aplicaciones. Además, según mis notas, aproximadamente la mitad de las clases mismas generan algo en el registro. Por lo tanto, la operación correcta con estas funciones afecta a casi toda la aplicación.