Journalisation asynchrone - comment procéder?

Dans de nombreux services sur lesquels je travaille, il y a beaucoup de journalisation en cours. Les services sont des services WCF (principalement) qui utilisent la classe .NET EventLogger.

Je suis en train d'améliorer les performances de ces services et je dois penser que la journalisation asynchrone bénéficierait aux performances.

Je ne sais pas ce qui se passe lorsque plusieurs threads demandent à se connecter, et si cela crée un goulot d'étranglement, mais même si ce n'est pas le cas, je pense toujours que cela ne devrait pas interférer avec le processus en cours d'exécution.

Je pense que je devrais invoquer la même méthode de journal que j'appelle maintenant, mais le faire en utilisant un nouveau thread, tout en poursuivant le processus réel.

Quelques questions à ce sujet:

Est-ce que c'est bon?

Y a-t-il des inconvénients?

Faut-il le faire d'une manière différente?

Peut-être que c'est si rapide que ça ne vaut même pas la peine?

Un thread séparé pour le fonctionnement des E / S semble raisonnable.

Par exemple, il ne serait pas bon d'enregistrer les boutons sur lesquels l'utilisateur a appuyé dans le même thread d'interface utilisateur. Une telle interface utilisateur se bloque au hasard et a des performances perçues lentes .

La solution consiste à dissocier l'événement de son traitement.

Voici beaucoup d'informations sur le problème des producteurs-consommateurs et la file d'attente des événements du monde du développement de jeux

Il y a souvent un code comme

///Never do this!!!
public void WriteLog_Like_Bastard(string msg)
{
    lock (_lockBecauseILoveThreadContention)
    {
        File.WriteAllText("c:\\superApp.log", msg);
    }
}

Cette approche conduira à un conflit de thread. Tous les threads de traitement se battront pour pouvoir obtenir le verrouillage et écrire dans le même fichier à la fois.

Certains peuvent essayer de supprimer les verrous.

public void Log_Like_Dumbass(string msg)
{
      try 
      {  File.Append("c:\\superApp.log", msg); }
        catch (Exception ex) 
        {
            MessageBox.Show("Log file may be locked by other process...")
        }
      }    
}

Il n'est pas possible de prédire le résultat si 2 threads entreront en même temps dans la méthode.

Ainsi, les développeurs désactiveront finalement la journalisation ...

Est-il possible de réparer?

Oui.

Disons que nous avons une interface:

 public interface ILogger
 {
    void Debug(string message);
    // ... etc
    void Fatal(string message);
 }

Au lieu d'attendre le verrouillage et d'effectuer une opération de blocage de fichier à chaque ILoggerappel, nous ajouterons un nouveau LogMessage à la file d'attente des messages de ping et reviendrons à des choses plus importantes:

public class AsyncLogger : ILogger
{
    private readonly BlockingCollection<LogMessage> _pendingMessages;
    private readonly Type _loggerFor;
    private readonly IThreadAdapter _threadAdapter;

    public AsyncLogger(BlockingCollection<LogMessage> pendingMessages, Type loggerFor, IThreadAdapter threadAdapter)
    {
        _pendingMessages = pendingMessages;
        _loggerFor = loggerFor;
        _threadAdapter = threadAdapter;
    }

    public void Debug(string message)
    {
        Push(LoggingLevel.Debug, message);
    }

    public void Fatal(string message)
    {
        Push(LoggingLevel.Fatal, message);
    }

    private void Push(LoggingLevel importance, string message)
    {
        // since we do not know when our log entry will be written to disk, remember current time
        var timestamp = DateTime.Now;
        var threadId = _threadAdapter.GetCurrentThreadId();

        // adds message to the queue in lock-free manner and immediately returns control to caller
        _pendingMessages.Add(LogMessage.Create(timestamp, importance, message, _loggerFor, threadId));
    }
}

Nous avons terminé avec ce simple enregistreur asynchrone .

L'étape suivante consiste à traiter les messages entrants.

Pour plus de simplicité, permet de démarrer un nouveau thread et d'attendre indéfiniment jusqu'à ce que l'application se termine ou que l' enregistreur asynchrone ajoute un nouveau message à la file d'attente en attente .

public class LoggingQueueDispatcher : IQueueDispatcher
{
    private readonly BlockingCollection<LogMessage> _pendingMessages;
    private readonly IEnumerable<ILogListener> _listeners;
    private readonly IThreadAdapter _threadAdapter;
    private readonly ILogger _logger;
    private Thread _dispatcherThread;

    public LoggingQueueDispatcher(BlockingCollection<LogMessage> pendingMessages, IEnumerable<ILogListener> listeners, IThreadAdapter threadAdapter, ILogger logger)
    {
        _pendingMessages = pendingMessages;
        _listeners = listeners;
        _threadAdapter = threadAdapter;
        _logger = logger;
    }

    public void Start()
    {
        //  Here I use 'new' operator, only to simplify example. Should be using interface  '_threadAdapter.CreateBackgroundThread' to allow unit testing
        Thread thread = new Thread(MessageLoop);
        thread.Name = "LoggingQueueDispatcher Thread";
        thread.IsBackground = true;

        thread.Start();
        _logger.Debug("Asked to start log message Dispatcher ");

        _dispatcherThread = thread;
    }

    public bool WaitForCompletion(TimeSpan timeout)
    {
        return _dispatcherThread.Join(timeout);
    }

    private void MessageLoop()
    {
        _logger.Debug("Entering dispatcher message loop...");
        var cancellationToken = new CancellationTokenSource();
        LogMessage message;

        while (_pendingMessages.TryTake(out message, Timeout.Infinite, cancellationToken.Token))
        {
            // !!!!! Now it is safe to use File.AppendAllText("c:\\my.log") without ever using lock or forcing important threads to wait.
            // this is example, do not use in production
            foreach (var listener in _listeners)
            {
                listener.Log(message);
            }
        }

    }
}

Je passe une chaîne d'auditeurs personnalisés. Vous voudrez peut-être simplement envoyer un cadre de journalisation des appels ( log4net, etc ...)

Voici le reste du code:

public enum LoggingLevel
{
    Debug,
    // ... etc
    Fatal,
}


public class LogMessage
{
    public DateTime Timestamp { get; private set; }
    public LoggingLevel Importance { get; private set; }
    public string Message { get; private set; }
    public Type Source { get; private set; }
    public int ThreadId { get; private set; }

    private LogMessage(DateTime timestamp, LoggingLevel importance, string message, Type source, int threadId)
    {
        Timestamp = timestamp;
        Message = message;
        Source = source;
        ThreadId = threadId;
        Importance = importance;
    }

    public static LogMessage Create(DateTime timestamp, LoggingLevel importance, string message, Type source, int threadId)
    {
        return  new LogMessage(timestamp, importance, message, source, threadId);
    }

    public override string ToString()
    {
        return string.Format("{0}  [TID:{4}] {1:h:mm:ss} ({2})\t{3}", Importance, Timestamp, Source, Message, ThreadId);
    }
}

public class LoggerFactory : ILoggerFactory
{
    private readonly BlockingCollection<LogMessage> _pendingMessages;
    private readonly IThreadAdapter _threadAdapter;

    private readonly ConcurrentDictionary<Type, ILogger> _loggersCache = new ConcurrentDictionary<Type, ILogger>();


    public LoggerFactory(BlockingCollection<LogMessage> pendingMessages, IThreadAdapter threadAdapter)
    {
        _pendingMessages = pendingMessages;
        _threadAdapter = threadAdapter;
    }

    public ILogger For(Type loggerFor)
    {
        return _loggersCache.GetOrAdd(loggerFor, new AsyncLogger(_pendingMessages, loggerFor, _threadAdapter));
    }
}

public class ThreadAdapter : IThreadAdapter
{
    public int GetCurrentThreadId()
    {
        return Thread.CurrentThread.ManagedThreadId;
    }
}

public class ConsoleLogListener : ILogListener
{
    public void Log(LogMessage message)
    {
        Console.WriteLine(message.ToString());
        Debug.WriteLine(message.ToString());
    }
}

public class SimpleTextFileLogger : ILogListener
{
    private readonly IFileSystem _fileSystem;
    private readonly string _userRoamingPath;
    private readonly string _logFileName;
    private FileStream _fileStream;

    public SimpleTextFileLogger(IFileSystem fileSystem, string userRoamingPath, string logFileName)
    {
        _fileSystem = fileSystem;
        _userRoamingPath = userRoamingPath;
        _logFileName = logFileName;
    }

    public void Start()
    {
        _fileStream = new FileStream(_fileSystem.Path.Combine(_userRoamingPath, _logFileName), FileMode.Append);
    }

    public void Stop()
    {
        if (_fileStream != null)
        {
            _fileStream.Dispose();
        }
    }

    public void Log(LogMessage message)
    {
        var bytes = Encoding.UTF8.GetBytes(message.ToString() + Environment.NewLine);
        _fileStream.Write(bytes, 0, bytes.Length);
    }
}

public interface ILoggerFactory
{
    ILogger For(Type loggerFor);
}

public interface ILogListener
{
    void Log(LogMessage message);
}

public interface IThreadAdapter
{
    int GetCurrentThreadId();
}

public interface IQueueDispatcher
{
    void Start();
}

Point d'accès:

public static class Program
{
    public static void Main()
    {
        Debug.WriteLine("[Program] Entering Main ...");

        var pendingLogQueue = new BlockingCollection<LogMessage>();


        var threadAdapter = new ThreadAdapter();
        var loggerFactory = new LoggerFactory(pendingLogQueue, threadAdapter);


        var fileSystem = new FileSystem();
        var userRoamingPath = GetUserDataDirectory(fileSystem);

        var simpleTextFileLogger = new SimpleTextFileLogger(fileSystem, userRoamingPath, "log.txt");
        simpleTextFileLogger.Start();
        ILogListener consoleListener = new ConsoleLogListener();
        ILogListener[] listeners = new [] { simpleTextFileLogger , consoleListener};

        var loggingQueueDispatcher = new LoggingQueueDispatcher(pendingLogQueue, listeners, threadAdapter, loggerFactory.For(typeof(LoggingQueueDispatcher)));
        loggingQueueDispatcher.Start();

        var logger = loggerFactory.For(typeof(Console));

        string line;
        while ((line = Console.ReadLine()) != "exit")
        {
            logger.Debug("you have entered: " + line);
        }

        logger.Fatal("Exiting...");

        Debug.WriteLine("[Program] pending LogQueue will be stopped now...");
        pendingLogQueue.CompleteAdding();
        var logQueueCompleted = loggingQueueDispatcher.WaitForCompletion(TimeSpan.FromSeconds(5));

        simpleTextFileLogger.Stop();
        Debug.WriteLine("[Program] Exiting... logQueueCompleted: " + logQueueCompleted);

    }



    private static string GetUserDataDirectory(FileSystem fileSystem)
    {
        var roamingDirectory = Environment.GetFolderPath(Environment.SpecialFolder.ApplicationData);
        var userDataDirectory = fileSystem.Path.Combine(roamingDirectory, "Async Logging Sample");
        if (!fileSystem.Directory.Exists(userDataDirectory))
            fileSystem.Directory.CreateDirectory(userDataDirectory);
        return userDataDirectory;
    }
}

Les facteurs clés à considérer sont votre besoin de fiabilité dans les fichiers journaux et le besoin de performances. Reportez-vous aux inconvénients. Je pense que c'est une excellente stratégie pour les situations de haute performance.

Est-ce que ça va - oui

Existe-t-il des inconvénients - oui - selon la criticité de votre journalisation et de votre implémentation, l'un des événements suivants peut se produire - journaux écrits hors séquence, actions de thread de journalisation non terminées avant la fin des actions d'événement. (Imaginez un scénario dans lequel vous vous connectez "en commençant à vous connecter à la base de données" et vous plantez ensuite le serveur, l'événement de journal peut ne jamais être écrit même si l'événement s'est produit (!))

Devrait-il être fait d'une manière différente - vous voudrez peut-être regarder le modèle Disruptor car il est presque idéal pour ce scénario

Peut-être que c'est si rapide qu'il ne vaut même pas la peine - pas d'accord. Si la vôtre est une logique «d'application», et que la seule chose que vous faites est d'écrire des journaux de l'activité - alors vous obtiendrez des ordres de grandeur de latence plus faible en déchargeant la journalisation. Si toutefois vous comptez sur un appel SQL DB de 5 secondes pour retourner avant de consigner les instructions 1-2, les avantages sont mitigés.

Je pense que la journalisation est généralement une opération synchrone de par sa nature. Vous voulez enregistrer des choses si elles se produisent ou non en fonction de votre logique, donc pour enregistrer quelque chose, cette chose doit être évaluée en premier.

Cela dit, vous pouvez améliorer les performances de votre application en mettant en cache les journaux, puis en créant un thread et en les enregistrant dans des fichiers lorsque vous avez une opération liée au processeur.

Vous devez identifier vos points de contrôle intelligemment afin de ne pas perdre vos informations de journalisation importantes pendant cette période de cache.

Si vous souhaitez augmenter les performances de vos threads, vous devez équilibrer les opérations d'E / S et les opérations du processeur.

Si vous créez 10 threads qui font tous des IO, vous n'obtiendrez pas d'amélioration des performances.

La journalisation asynchrone est le seul moyen de procéder si vous avez besoin d'une faible latence dans les threads de journalisation. La façon dont cela est fait pour des performances maximales passe par le modèle de perturbateur pour une communication de thread sans verrouillage et sans déchets. Maintenant, si vous souhaitez autoriser plusieurs threads à se connecter simultanément au même fichier, vous devez soit synchroniser les appels de journal et payer le prix en conflit de verrouillage OU utiliser un multiplexeur sans verrouillage. Par exemple, CoralQueue fournit une simple file d'attente de multiplexage comme décrit ci-dessous:

Vous pouvez jeter un œil sur CoralLog qui utilise ces stratégies pour la journalisation asynchrone.

Avertissement: je suis l'un des développeurs de CoralQueue et CoralLog.