Problème de performance log4net BufferingForwardingAppender

EDIT 2: J’ai résolu le problème (voir la réponse ci-dessous) Veuillez noter que le problème concerne potentiellement tous les appenders dotés de BufferingForwardingAppender, ainsi que tous les appenders héritant de BufferingAppenderSkeleton (respectivement: AdoNetAppender, RemotingAppender, SmtpAppender et SmtpPickupDirAppender) *

Je faisais quelques bancs très basiques de log4net et j’ai essayé de décorer un RollingFileAppender avec un BufferingForwardingAppender.

J’éprouve de terribles performances en passant par BufferingForwardingAppender plutôt que directement par RollingFileAppender et je ne comprends vraiment pas la raison.

Voici ma configuration:

                   

Et voici le repère (code très 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); 

En passant directement par RollingFileAppender, le résultat est le suivant:

Fait en 511 ms

Considérant que passer par BufferingForwardingAppender décorant RollingFileAppender:

Fait en 14261 ms

C’est environ 30 fois plus lent.

Je pensais que je gagnerais de la vitesse en mettant en mémoire tampon un certain nombre de journaux avant de les écrire dans le fichier. Cependant, pour une raison quelconque, les choses empirent beaucoup.

Il me semble que la configuration est correcte, donc c’est vraiment bizarre.

Quelqu’un a un indice?

Merci!

EDIT 1:

Le comportement est ssortingctement identique en encapsulant / décorant un fichier FileAppender ou même ConsoleAppender (il existe néanmoins un exemple d’emballage / décoration de base de BufferingForwardingAppender dans des exemples de configuration officiels log4net .. et aucun élément spécifique ne concerne les performances).

Après une enquête / un profilage, je constate que la plupart du temps est gâché dans BufferingForwardingAppender, plus précisément dans un appel à WindowsIdentity.GetCurrent () … étant appelé CHAQUE fois, nous appelons Log.Debug() .. dans l’échantillon précédent (100 000 fois dans la source d’échantillon ci-dessus).

Les appels à cette méthode sont connus pour être très coûteux et doivent être évités ou minimisés. Je ne comprends vraiment pas pourquoi elle est appelée à chaque événement de journal. Suis-je vraiment en train de mal configurer quelque chose / de ne pas voir quelque chose d’évident, ou est-ce un bogue quelque part, c’est ce que j’essaie de comprendre maintenant …

La stack d’appels partielle est:

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

Un appel à get_LocationInformation() est également effectué dans FixVolatileData, entraînant également un coût de revient élevé (capturez la trace de la stack à chaque fois).

J’essaie maintenant de comprendre pourquoi cet appel extrêmement coûteux de FixVolatileData (du moins pour le correctif demandé) se produit pour chaque événement de journal dans ce contexte, alors que le fait de passer directement par l’appender encapsulé (directement via ConsoleAppender / FileAppender ..) n’effectue pas ce type de traitement. opération.

Prochaine mise à jour à suivre, à moins que quelqu’un ait une réponse à tout cela;)

Merci!

J’ai découvert le problème.

BufferingForwardingAppender hérite de BufferingAppenderSkeleton (à l’instar d’autres ajouts utilisant la journalisation d’événements tels que AdoNetAppender , RemotingAppender , SmtpAppender , SmtpAppender ).

BufferingAppenderSkeleton met en mémoire tampon les événements de journalisation avant de les transmettre à l’appendeur cible une fois qu’une certaine condition est remplie (mémoire tampon saturée par exemple).

Selon la documentation de la classe LoggingEvent (représentant un événement de journalisation et contenant toutes les valeurs (message, threadid …) de l’événement):

Certaines propriétés des événements de journalisation sont considérées comme “volatiles”, c’est-à-dire que les valeurs sont correctes au moment où l’événement est transmis aux ajouts, mais ne seront pas cohérentes par la suite. Si un événement doit être stocké et traité ultérieurement, ces valeurs volatiles doivent être corrigées en appelant FixVolatileData. L’appel à FixVolatileData entraîne une baisse des performances, mais il est essentiel pour maintenir la cohérence des données.

Ces propriétés “volatiles” sont représentées par l’énumération FixFlags contenant des indicateurs tels que Message, ThreadName, UserName, Identity … donc toutes les propriétés volatiles. Il contient également l’indicateur “Aucun” (correction de non propriétés), “Tout” (correction de toutes les propriétés) et “Partiel” (correction uniquement d’un jeu de propriétés prédéfini).

Lorsque BufferingAppenderSkeleton est instancié, par défaut, DEFAULT définit la correction sur “Tous”, ce qui signifie que toutes les propriétés “volatiles” doivent être corrigées.

Dans ce contexte, pour chaque événement LoggingEvent ajouté au BufferingAppenderSkeleton, TOUTES les propriétés “volatiles” seront corrigées avant que l’événement ne soit inséré dans le tampon. Cela inclut les propriétés Identity (nom d’utilisateur) et LocationInformation (trace de stack) même si ces propriétés ne sont pas incluses dans la présentation (mais je suppose que cela a un sens si la disposition est modifiée pour inclure ces propriétés ultérieurement, alors qu’un tampon a déjà été rempli avec LoggingEvents).

Cependant, dans mon cas, cela nuit vraiment aux performances. Je n’inclus pas les informations d’identité et de localisation dans ma mise en page et je n’envisage pas de le faire (principalement pour des problèmes de performances)

Maintenant pour la solution …

Il existe deux propriétés dans BufferingAppenderSkeleton qui peuvent être utilisées pour contrôler la valeur de l’indicateur FixFlags de BufferingAppenderSkeleton (une fois encore, il est défini par défaut sur “ALL”, ce qui n’est pas très pratique!). Ces deux propriétés sont Fix (type FixFlags) et OnlyFixPartialEventData (type bool).

Pour affiner la valeur de l’indicateur ou désactiver tout correctif, vous devez utiliser la propriété Fix . Pour une combinaison d’indicateurs partielle prédéfinie spécifique ( OnlyFixPartialEventData pas Identity ou LocationInfo), OnlyFixPartialEventData peut être utilisé à la place en le définissant sur “true”.

Si je réutilise l’exemple de configuration ci-dessus (dans ma question), la seule modification apscope à la configuration pour optimiser les performances est indiquée ci-dessous:

       

En utilisant cette configuration modifiée, l’exécution du code de référence présentée dans la question ci-dessus passe d’environ 14 000 ms à 230 ms (60 fois plus rapide)! Et si j’utilise au lieu de désactiver tout correctif, cela prend environ 350 ms.

Malheureusement, cet indicateur n’est pas très bien documenté (sauf dans la documentation du SDK, un peu) .. j’ai donc dû approfondir les sources de log4net pour trouver le problème.

Cela est particulièrement problématique, en particulier dans les exemples de configuration “référence”, cet indicateur n’apparaît nulle part (http://logging.apache.org/log4net/release/config-examples.html). Ainsi, les exemples fournis pour BufferingForwardingAppender et AdoNetAppender (ainsi que d’autres appenders hérités de BufferingAppenderSkeleton) donneront aux utilisateurs les performances de TERRIBLE, même si la présentation qu’ils utilisent est assez minime.

Est-il possible que ce soit parce que vous ne spécifiez pas de modèle de présentation dans BufferingForwardingAppender mais que vous êtes dans RollingLogFileAppender conséquent, BufferingForwardingAppender inclut tout dans sa sortie, y compris le nom d’utilisateur (% username)

Vous trouverez ci-dessous un article de blog intéressant qui contient une liste des options disponibles dans les modèles de motif. Il semble que plusieurs d’entre elles soient marquées comme lentes.

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