Bonjour, Habr!
Je pense que presque tous les programmes ont une journalisation. De plus, dans un certain nombre d'applications déjà nouvelles (ce qui signifie avec une mer de conditions non triviales), les journaux deviennent souvent vitaux sur un serveur de combat.
Cependant, malgré l'importance et la prévalence d'une telle technologie, j'ai remarqué que les gens font souvent des erreurs standard lorsqu'ils travaillent avec eux. Cet article décrit le comportement de .Net à bien des égards, cependant, j'ai fait de petites insertions du monde Java, juste pour avoir une comparaison.
Allocations (allocation de mémoire)
L'erreur la plus courante (selon mes observations) est une négligence par rapport aux petites allocations de mémoire près du lieu de l'appel à la fonction log.Debug(...) .
Donc, notre code standard 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 }
À bien des égards, je n'ai vu que les bibliothèques log4net et NLog , et donc je les utiliserai dans les exemples.
Les questions sont donc:
- Dans quelles lignes la mémoire sera-t-elle allouée même si le débogage est désactivé?
- Si de la mémoire est allouée, est-il facile de détecter dans le même dotTrace que les enregistreurs sont spécifiquement responsables de cette allocation de mémoire?
La bonne réponse à la première question: la mémoire n'est pas allouée uniquement au paragraphe "6". Et la réponse à la deuxième question: c'est incroyablement difficile à saisir, car un tel code est souvent réparti sur le projet. Vous vous souvenez peut-être d'une application .Net typique. Il aura souvent un code similaire qui fait fonctionner GC.
Cependant, passons en revue les détails techniques pour comprendre exactement où nous aurons un impact sur les performances.
Donc le premier point:
Log4NetLog.Debug($"Id={id}"); // 1
En fait, le compilateur le convertira en:
var temp = string.Format("Id={0}", id); // <-- Log4NetLog.Debug(temp);
Autrement dit, la première expression forcera essentiellement le processeur à créer une chaîne, à la transmettre à l'enregistreur. Il vérifiera rapidement que vous n'avez pas besoin de vous connecter, et donc la ligne vient d'être créée en mémoire. Et, surtout, si vous copiez plus de ce code, les lignes seront créées dans des tas d'endroits de programme, c'est-à-dire que le programme fonctionnera un peu plus lentement. Partout.
Le deuxième exemple est un peu plus efficace, car aucune ligne n'y est créée:
Log4NetLog.DebugFormat("Id={0}", id);
Cependant, la mémoire est toujours allouée ici, car la boxe se produira. Permettez-moi de vous rappeler la signature de la méthode DebugFormat:
void DebugFormat(string format, object arg0)
Comme vous pouvez le voir, l'entrée nécessite un type de référence. Cependant, nous essayons de passer un type int significatif. Par conséquent, chaque appel entraînera la transmission de l' id paramètre de id mémoire pour le transmettre à la méthode. Et permettez-moi de vous rappeler que le paramètre lui-même n'est pas nécessaire dans la méthode elle-même, car Debug est désactivé par l'état de la tâche.
L'exemple suivant est chargé et simple:
Log4NetLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 3
Je suis sûr que vous avez déjà compris que la ligne se démarquera à nouveau et ainsi de suite. Par conséquent, ignorez immédiatement cet exemple. La méthode d'appel suivante semble plus efficace:
Log4NetLog.DebugFormat("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 4
Et c'est ainsi, cependant, calculons combien de fois il est nécessaire d'allouer un morceau de mémoire:
email.Normalize() conduit à la création d'une sorte d'objet. Par conséquent, cet objet sera alloué sur le tas (ou sur la pile - cela n'a pas d'importance, car la boxe obligera à tout sélectionner sur le tas)id ira à un tas, comme nous l'avons déjà considéré précédemment.- Log4net possède l'interface suivante pour ces appels au format long:
void DebugFormat(string format, params object[] args) . Comme vous pouvez le voir, .Net créera un tableau sur le tas pour le transmettre à la méthode DebugFormat .
Par conséquent, un appel assez typique à l'opération de journalisation entraînera la création d'un tas d'objets en mémoire. Ce qui est plutôt décevant, car la journalisation elle-même est souvent désactivée. Passons cependant à NLog.
Cette ligne provoquera l'allocation de l'objet sur le tas:
NLogLog.Debug($"Id={id}");
Tout est évident ici, mais la ligne ci-dessous n'a plus un tel inconvénient:
NLogLog.Debug("Id={0}", id);
Et la raison en est que NLog a une signature spéciale pour ints: void Debug(string message, int argument) . De plus, même si vous transférez une structure différente, la void Debug<TArgument>([Localizable(false)] string message, TArgument argument) . Et cette méthode ne nécessite pas de boxe, car après JIT, une fonction distincte sera créée pour chaque type (bien sûr, ce n'est pas entièrement vrai, mais le point important est: il n'y aura pas de boxe).
Je vais sauter le script facile à comprendre avec une grande ligne d'entrée et aller directement à:
NLogLog.Debug("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount);
Curieusement, NLog n'a pas augmenté le nombre de paramètres génériques pour les méthodes, et donc la signature sera utilisée: void Debug([Localizable(false)] string message, params object[] args) . Et cela conduira à nouveau à la création d'objets en tas et ainsi de suite.
Conclusions et améliorations
La principale conclusion: si vous avez beaucoup d'appels aux méthodes de journalisation dans le programme qui ne conduisent pas à une écriture physique dans le fichier, vous pouvez à l'improviste allouer beaucoup d'objets inutiles sur le tas. Et ainsi inhiber le travail du programme.
Conclusion 2: Si vous passez peu d'objets à une méthode, utilisez NLog. En raison du fait qu'il s'est occupé des paramètres génériques, vous pouvez être plus détendu quant aux performances.
Cependant, pour être complètement sûr, il est plus logique de le faire:
if (NLogLog.IsDebugEnabled) { NLogLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); }
Ici, la méthode de journalisation ne sera pas appelée si elle n'est pas nécessaire. Cependant, si vous devez encore vider les données dans le journal, alors l'interpolation de chaîne pratique sera utilisée. À l'intérieur, les enregistreurs (au moins le même NLog) ont des optimisations pour écrire directement une ligne dans les journaux (c'est-à-dire que le formatage se produira immédiatement dans Stream , au lieu de créer une ligne en mémoire). Cependant, cette optimisation de NLog s'estompe avec le fait que vous devez réinitialiser les données dans un fichier.
Exemple de Kotlin
Pour diluer la description du travail des enregistreurs populaires dans .Net, je donnerai une façon intéressante de boucler les appels en kotlin. L'idée est basée littéralement sur une caractéristique intéressante du langage: les méthodes en ligne . Donc, un code simple pour sortir quelque chose à déboguer:
class SomeService{ private companion object : KLogging() fun publishData(id: Int){ logger.debug { "Identity: $id" } } }
Et il sera converti par le compilateur en quelque chose comme ceci:
class SomeService{ private companion object : KLogging() fun publishData(id: Int){ if(logger.isDebugEnabled){ try{ val message = "Identity: $id" logger.debug(message) }catch (e: Exception){ } } } }
C'est important ici: tout ce qui se trouve à l'intérieur des accolades près du debug est un lambda. Cependant, il sera incorporé dans votre méthode, c'est-à-dire qu'un objet fonction ne sera pas créé dans le tas. Ainsi, vous pouvez masquer de grandes opérations à l'intérieur, qui ne seront appelées que si vous souhaitez sortir le résultat à debug . Par exemple:
class SomeService{ private companion object : KLogging() fun publishData(id: Int){ logger.debug { val idList = getIdList() "Identity: $idList" } } }
Ici, getIdList sera appelé uniquement si vous devez envoyer quelque chose au fichier. Et tout cela parce que le code est converti en:
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" } } }
Grand objet ==> Gros objet
En plus de l'exemple précédent. Je suis sûr que beaucoup de gens savent que .Net / JVM a le concept de "Large Object Heap". Plus précisément, il n'y a pas de définition spéciale en Java, cependant, les allocateurs créent souvent de gros objets immédiatement dans la dernière génération (pour minimiser le mouvement des objets et niveler le problème de pénétration rapide de la mémoire pour un allocateur de streaming).
Retour à l'exemple:
NLogLog.Debug($"Id={id}");
Comme vous le comprenez, si l'objet id a une implémentation de ToString , qui crée une chaîne de la taille d'un mégaoctet, les hits suivants dans la face LOH:
ToString s'appelle- Formatage de
$"Id={id}" - Et si les développeurs de l'enregistreur n'ont pas saisi toutes ces choses (et il est extrêmement difficile d'écrire un test pour l'absence d'objets dans LOH), l'enregistreur ajoutera des problèmes.
Et ici, vous pouvez utiliser trois méthodes de journalisation de telles choses:
- Utilisez une disposition spéciale et ne nécessite pas d'appel à
ToString . Par exemple, NLog a un JsonLayout . Ainsi, vous pouvez simplement transférer un objet vers l'enregistreur, qui sera immédiatement sérialisé dans le flux résultant (par exemple, dans un fichier). - Écrivez vous-même le fichier. Ou en d'autres termes - n'utilisez pas l'enregistreur. Je ne peux que conseiller par moi-même comment savoir dans quel fichier NLog écrira:
var filePath = NLog.LogManager.Configuration.AllTargets.OfType<FileTarget>().First().FileName.Render(LogEventInfo.CreateNullEvent()) . Évidemment, cette fonction renverra le premier FileTarget , mais si tout le monde écrit dans le même dossier, de la même manière, vous pouvez trouver le dossier pour l'enregistrement, puis envoyer directement un cliché de votre objet dans le fichier. - Si vous avez log4j2 (le second est important), vous pouvez utiliser StringBuilderFormattable . Il vient d'être créé afin de sortir les données dans l'enregistreur par morceaux (de plus, afin de ne pas allouer une partie des morceaux dans le tas, car ils sont déjà sélectionnés).
public interface StringBuilderFormattable { void formatTo(StringBuilder buffer); }
Synchronicité (et problèmes d'asynchronie)
Une fois, dans un programme, j'ai remarqué que pendant les opérations chargées, environ la moitié du temps d'attente de l'interface utilisateur était due aux opérations de journalisation. Encore une fois: la moitié du temps du programme a été consacrée à un appel à logger.Debug ou quelque chose comme ça. Et la raison en est simple: nous avons utilisé log4net, qui ne peut écrire des fichiers que de manière synchrone.
De là, j'ai déduit la règle 1 : l'enregistreur doit toujours fonctionner dans un autre thread. Vous ne devez pas bloquer le code de l'application à cause des traces, car c'est incroyablement étrange. En d'autres termes - en utilisant NLog - vous devez toujours mettre async=true dans la balise nlog (c'est la principale). Ou, comme le dit l' exemple :
<targets async="true"> ... your targets go here ... </targets>
Si vous utilisez log4net, redirigez-le vers NLog ou créez AsyncFileAppender.
Pour le monde Java: Logback et Log4J2 ont tous deux la possibilité d'effectuer une journalisation asynchrone. Voici une comparaison du site officiel :
Cependant, lorsque tout est écrit de manière asynchrone, un autre problème se pose - que faire en cas d'erreurs critiques? Après tout, il arrive qu'un programme ne se ferme pas parce qu'il a quitté le thread Main (par exemple, un programme peut quitter en appelant Application.Exit ou Environment.FailFast , ce qui n'est pas très beau, mais cela se produit). Dans ce cas, vous devez toujours appeler Flush avant de tuer votre processus. Sinon, si vous tombez sur le serveur de combat, les informations les plus précieuses seront manquées.
Conclusion
J'espère que cet article vous aide à écrire des programmes rapides avec une journalisation pratique. Je n'ai souligné qu'une partie des problèmes que je vois dans le code. Tous ne sont pas les plus évidents, mais pas les plus difficiles.
En tout cas, comme je l'ai dit au début, travailler avec des enregistreurs est dans presque toutes les applications. De plus, selon mes notes, environ la moitié des classes elles-mêmes sortent quelque chose dans le journal. Ainsi, le bon fonctionnement de ces fonctions affecte la quasi-totalité de l'application.