Dans cet article, j'ai placé des références des appels les plus privés des enregistreurs. J'ai mené toutes les expériences sur log4net et NLog, sur Intel Windows 10 x64 avec SSD M.2.

Les résultats bruts peuvent être consultés sur GitHub . Le code est dans le même référentiel (pour fonctionner, vous aurez besoin de .Net 4.7.2 + Microsoft Visual Studio 2017+).

Quoi, comment et pourquoi - sous la coupe.

Afin de ne pas lire longtemps, le tableau des résultats:

NoOpLogging

Tout d'abord, estimons combien de temps nous passons à appeler une méthode de journalisation, ce qui ne mènera finalement à rien. Dans la plupart des cas (d'après mon expérience), le débogage détaillé est désactivé sur les serveurs de combat, cependant, personne ne supprime les appels.

Tout d'abord, le résultat:

Et le code:

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

Voyons d'abord pourquoi ces tests ont été choisis:

• Les expériences ont été réalisées sur les bibliothèques les plus populaires.

• NLog et log4net ont des signatures de fonction différentes pour un petit nombre d'arguments:

  
  
  • log4net:
  
  

   void DebugFormat(string format, object arg0) 

  
  
  • Nlog:
  
  

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

  
  
  • Théorie: lors du transfert d'un type significatif vers log4net, la boxe devrait se produire, ce qui passe simplement du temps processeur et ne mène à rien. Dans le cas de NLog, il n'y a pas un tel comportement, donc ce dernier devrait fonctionner plus rapidement.
  
  
• Les signatures d'un grand nombre d'arguments dans les bibliothèques sont à peu près les mêmes, je voudrais donc savoir:
  
  • Il est beaucoup plus efficace d'invoquer des méthodes avec un petit nombre de paramètres.
  • Existe-t-il une différence dans la vitesse d'appel de la méthode "Is ... Enabled" entre les deux bibliothèques

Et maintenant l'analyse des résultats:

• En raison de l'utilisation d'arguments génériques dans NLog, cela fonctionne plus rapidement dans le cas où la journalisation directe n'est pas nécessaire. Autrement dit, dans le cas où dans votre programme de débogage le niveau est activé uniquement sur le système de test, le simple fait de changer de bibliothèque peut accélérer le logiciel (et améliorer la vie des utilisateurs).
• Si la journalisation est désactivée et que vous souhaitez appeler une méthode avec un grand nombre d'arguments, il est plus efficace de la diviser en deux. Pour cette raison, les appels de méthode ci-dessus fonctionneront dix fois plus rapidement.
• Lorsque vous écrivez une fonction qui peut prendre n'importe quel objet, il est souvent plus efficace de se confondre et de créer une fonction générique. En raison d'une telle optimisation simple, le code fonctionnera plus rapidement (cela se voit clairement dans la différence de temps entre les appels à Log4NetSingleReferenceParam et Log4NetSingleValueParam )

Filelogging

La plupart des programmes (selon mes observations) enregistrent toujours les résultats dans un fichier, donc pour comparaison nous choisissons cette opération. Par souci de simplicité, nous prenons simplement la configuration des enregistreurs lorsqu'un fichier est écrit dans le fichier sans mise en mémoire tampon, sans verrous supplémentaires, etc.

Résultats:

Code utilisé:

• 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 }; 

Comme vous pouvez le constater, la configuration des enregistreurs est plus ou moins similaire, et selon les résultats:

• NLog est légèrement plus rapide que log4net, quelque part autour de 15%.
• Selon des tests, il s'est avéré qu'il est plus efficace d'enregistrer moins de paramètres. Cependant, il ne faut pas oublier qu'avec un plus grand nombre de paramètres, la chaîne résultante s'est également développée. Par conséquent, le tableau compare uniquement NLog correctement avec log4net.

NLog - différents types de serrures

Code source:

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

Si nous mettons toutes les combinaisons possibles à la place de XXXXX et YYYYY, nous obtenons le test du tableau.

Les résultats sont assez prévisibles:

• Si vous activez ConcurrentWrites, le système prendra et donnera constamment Mutex, qui n'est pas gratuit. Mais, comme nous le voyons, écrire une ligne dans un fichier équivaut approximativement à un verrou système.
• La fermeture et l'ouverture d'un fichier, comme nous le voyons, affectent encore plus les performances du système. Dans les exemples avec KeepFileOpen=true pour chaque opération de journalisation, nous avons créé un fichier (avec Handle), écrit sur le disque, appelé Flush, renvoyé Handle et également effectué de nombreuses opérations sur le capot moteur. En conséquence, la vitesse diminue des centaines de fois.

Journalisation asynchrone et différentes méthodes de verrouillage

La bibliothèque NLog est également capable d'effectuer toutes les opérations d'E / S sur un autre thread, libérant immédiatement celui en cours. Et il le fait avec compétence, en préservant l'ordre des événements, en supprimant toutes les données dans des blocs, et dans chaque bloc, un entier est un numéro d'événement (afin que les lignes recadrées ne soient pas obtenues), etc.

Les résultats de différentes méthodes non bloquantes:

La comparaison des approches de blocage et asynchrones sera plus loin, mais ici - seulement la dernière.

Code AsyncTargetWrapper :

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

Comme vous pouvez le voir, les paramètres de l'encapsuleur sont tels qu'un vidage direct dans le fichier ne prend pas un certain temps. Ainsi, un grand tampon est accumulé, ce qui signifie que toutes les opérations gourmandes en ressources telles que "ouvrir un fichier" sont effectuées une fois pour tout le bloc. Cependant, un tel algorithme nécessite de la mémoire supplémentaire (et beaucoup).

Conclusions:

• Si la sortie asynchrone est utilisée, peu importe le type de paramètres de sortie avec le fichier utilisé. Vous pouvez ouvrir et fermer le fichier à chaque fois, avec un grand tampon, il sera presque imperceptible.
• Toutes les mesures ne sont vraies que dans le cas où les données sont vidées sur le disque à environ la même vitesse que le remplissage des tampons (je l'ai fait en raison du système de fichiers rapide + des pauses naturelles entre les mesures).

Journalisation synchrone et asynchrone

Conclusions:

• Malgré le disque rapide (dans mon cas - SSD M.2), l'écriture dans un fichier dans un autre flux accélère le travail plusieurs fois. Si votre application écrit sur des disques durs et s'exécute même sur une machine virtuelle, le gain sera encore plus important.
• Cependant, malgré le fonctionnement même rapide du code asynchrone, le manque de journalisation donne un gain encore plus important (quoique légèrement différent, selon la bibliothèque).

Création d'enregistreurs

Résultats:

Ce qui a été testé:

 [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 }; } 

Remarque importante: malheureusement, il m'a été difficile de faire un benchmark reproductible qui ne conduisait pas à Out Of Memory, mais qui créerait des enregistreurs différents (c'est-à-dire pour différents types, pour différentes lignes, etc.).

Cependant, après avoir étudié le travail des bibliothèques, j'ai constaté que presque les opérations les plus difficiles sont effectuées pour créer une clé de journalisation (c'est-à-dire déterminer un nom, effacer les arguments génériques, etc.).
De plus, afin de stabiliser la référence pour la création d'un enregistreur pour log4net, il était nécessaire d'effectuer non pas une opération, mais 16 (c'est-à-dire qu'un tableau de 16 objets identiques est retourné). Si vous ne renvoyez rien, alors .Net a optimisé l'exécution pour moi (apparemment, ne renvoyant pas le résultat), ce qui a conduit à des résultats incorrects.

Et conclusions:

• Les enregistreurs sont créés le plus rapidement à partir de chaînes (NLog est à nouveau plus rapide, cependant, la différence entre les bibliothèques est petite, étant donné que les enregistreurs sont créés non seulement comme ça, mais pour un travail ultérieur avec eux).
• log4net est plus rapide que NLog lors de l'initialisation d'un projet. Cela est peut-être dû à la mise en cache supplémentaire du côté NLog, qui permet d'accélérer les appels directs vers Debug , Info , etc. En fait, chaque ILogger connaît lui-même la réponse: appeler ou non les méthodes suivantes (et cela nécessite au moins une sorte de liaison à la configuration générale). En raison de ce schéma de travail, Out Of Memory a été utilisé par moi sur la plupart des tests (si j'utilise des lignes différentes, etc.).
• LogManager.GetCurrentClassLogger() est encore plus lent que LogManager.GetLogget(typeof(XXX)) . C'est logique, même les développeurs NLog ne recommandent pas d'appeler la première méthode dans une boucle.
• Et surtout: la vitesse de toutes ces méthodes n'affecte souvent que le démarrage à froid de l'application lorsque les champs du formulaire private static readonly ILogger Log = LogManager.GetCurrentClassLogger() . En d'autres termes, cela n'affecte pas directement les performances du système.

Conclusion

Quelle est la meilleure façon de gérer les journaux:

• S'il est possible de ne pas se connecter du tout, ce sera le plus rapide (ce qui est évident jusqu'à présent).
• Si le projet a de nombreux appels d'enregistreur qui ne transfèrent pas de données dans un fichier (vers la console, etc.), NLog est plus rapide. En outre, il alloue moins d'objets sur le tas.
• Si vous devez toujours écrire dans un fichier, NLog fonctionne de manière asynchrone le plus rapidement. Oui, il consomme plus de mémoire (par rapport à NLog en mode synchrone, car selon mes mesures précédentes, log4net n'essaye même pas de réutiliser les tableaux et Stream ). Cependant, le programme pourra s'exécuter plus rapidement.
• La création d'un enregistreur n'est pas une opération gratuite, il est donc souvent préférable de le créer avec un champ statique. Cela ne s'applique pas à la création à partir d'une chaîne, c'est-à-dire quelque chose comme LogManager.GetLogger("123") . De tels appels fonctionnent plus rapidement, ce qui signifie qu'un enregistreur peut être créé pour de grandes instances d'objets (par exemple, "un enregistreur pour le contexte de la requête").
• Si vous souhaitez afficher un grand nombre de paramètres dans le journal, mais dans la plupart des cas, il n'y aura pas de vidage direct des données dans le fichier, il est préférable d'effectuer plusieurs appels. Par conséquent, NLog ne créera pas d'objets supplémentaires sur le tas s'ils n'y sont pas nécessaires.

Conclusions pour votre code:

• Si votre méthode accepte un objet arbitraire (c'est-à-dire un object ) et dans la plupart des cas ne fait rien (ce qui est vrai pour les contrats / validateurs), alors il est plus correct d'encapsuler les appels sous une forme générique (c'est-à-dire de créer des méthodes de la forme Something<TArg>(TArg arg) ). Cela fonctionnera vraiment plus rapidement.
• Si dans votre code une réinitialisation des données de fichier est autorisée et fonctionne en même temps avec autre chose, il est préférable de se confondre et de le prendre en charge. Oui, il semble évident que l'exécution parallèle peut accélérer le travail, cependant, dans le cas des opérations d'E / S, cette approche donne également un coup de pouce supplémentaire aux performances sur les machines avec des disques lents.