Asynchrone Protokollierung - wie soll das gemacht werden?

In vielen der Dienste, an denen ich arbeite, wird viel protokolliert. Die Dienste sind (meistens) WCF-Dienste, die die .NET EventLogger-Klasse verwenden.

Ich bin dabei, die Leistung dieser Dienste zu verbessern, und ich musste denken, dass eine asynchrone Protokollierung die Leistung verbessern würde.

Ich weiß nicht, was passiert, wenn mehrere Threads nach einer Protokollierung fragen und ob dies zu einem Engpass führt, aber selbst wenn dies nicht der Fall ist, denke ich immer noch, dass dies den tatsächlich ausgeführten Prozess nicht beeinträchtigen sollte.

Ich denke, ich sollte dieselbe Protokollmethode aufrufen, die ich jetzt aufrufe, aber einen neuen Thread verwenden, während ich mit dem eigentlichen Prozess fortfahre.

Einige Fragen dazu:

Ist es o.k?

Gibt es Nachteile?

Sollte es anders gemacht werden?

Vielleicht ist es so schnell, dass es nicht einmal die Mühe wert ist?

Ein separater Thread für den E / A-Betrieb klingt vernünftig.

Zum Beispiel wäre es nicht gut zu protokollieren, welche Schaltflächen der Benutzer im selben UI-Thread gedrückt hat. Eine solche Benutzeroberfläche hängt zufällig und hat eine langsam wahrgenommene Leistung .

Die Lösung besteht darin, das Ereignis von seiner Verarbeitung zu entkoppeln.

Hier finden Sie viele Informationen zu Producer-Consumer Problem und Event Queue aus der Welt der Spieleentwicklung

Oft gibt es einen Code wie

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

Dieser Ansatz führt zu Thread-Konflikten. Alle Verarbeitungsthreads kämpfen darum, Sperren zu erhalten und gleichzeitig in dieselbe Datei zu schreiben.

Einige versuchen möglicherweise, Sperren zu entfernen.

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...")
        }
      }    
}

Es ist nicht möglich, das Ergebnis vorherzusagen, wenn 2 Threads gleichzeitig in die Methode eintreten.

Irgendwann werden Entwickler die Protokollierung überhaupt deaktivieren ...

Ist es möglich zu beheben?

Ja.

Nehmen wir an, wir haben eine Schnittstelle:

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

Anstatt bei jedem Aufruf auf die Sperre zu warten und den Blockiervorgang auszuführen , fügenILogger wir der Penging Messages Queue eine neue LogMessage hinzu und kehren zu wichtigeren Dingen zurück:

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

Wir haben mit diesem einfachen asynchronen Logger fertig .

Der nächste Schritt ist die Verarbeitung eingehender Nachrichten.

Lassen Sie uns der Einfachheit halber einen neuen Thread starten und ewig warten, bis die Anwendung beendet wird, oder Asynchronous Logger fügt der ausstehenden Warteschlange eine neue Nachricht hinzu .

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

    }
}

Ich komme an einer Kette von benutzerdefinierten Zuhörern vorbei. Möglicherweise möchten Sie nur das Anrufprotokollierungsframework ( log4netusw.) senden.

Hier ist der Rest des Codes:

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

Einstiegspunkt:

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

Zu berücksichtigende Schlüsselfaktoren sind Ihr Bedürfnis nach Zuverlässigkeit in den Protokolldateien und das Bedürfnis nach Leistung. Nachteile verweisen. Ich denke, dies ist eine großartige Strategie für Hochleistungssituationen.

Ist es in Ordnung - ja

Gibt es Nachteile - ja - abhängig von der Kritikalität Ihrer Protokollierung und Ihrer Implementierung kann Folgendes auftreten: Protokolle, die nicht in der richtigen Reihenfolge geschrieben wurden, Protokoll-Thread-Aktionen werden nicht abgeschlossen, bevor Ereignisaktionen abgeschlossen sind. (Stellen Sie sich ein Szenario vor, in dem Sie protokollieren, dass eine Verbindung zur Datenbank hergestellt wird, und dann den Server zum Absturz bringen. Das Protokollereignis wird möglicherweise nie geschrieben, obwohl das Ereignis aufgetreten ist (!).)

Sollte dies anders gemacht werden, sollten Sie sich das Disruptor-Modell ansehen, da es für dieses Szenario fast ideal ist

Vielleicht ist es so schnell, dass es nicht einmal die Mühe wert ist - nicht einverstanden. Wenn es sich bei Ihrer um eine "Anwendungs" -Logik handelt und Sie nur Protokolle der Aktivität schreiben, wird die Latenz um eine Größenordnung geringer, wenn Sie die Protokollierung auslagern. Wenn Sie sich jedoch auf einen 5-Sekunden-DB-SQL-Aufruf verlassen, um vor dem Protokollieren von 1-2-Anweisungen zurückzukehren, sind die Vorteile gemischt.

Ich denke, die Protokollierung ist von Natur aus im Allgemeinen eine synchrone Operation. Sie möchten Dinge protokollieren, wenn sie auftreten oder nicht, abhängig von Ihrer Logik. Um also etwas zu protokollieren, muss dieses Element zuerst ausgewertet werden.

Sie können jedoch die Leistung Ihrer Anwendung verbessern, indem Sie Protokolle zwischenspeichern, dann einen Thread erstellen und diese in Dateien speichern, wenn Sie eine CPU-gebundene Operation ausführen.

Sie müssen Ihre Checkpoints geschickt identifizieren, damit Sie während dieser Cache-Zeit Ihre wichtigen Protokollierungsinformationen nicht verlieren.

Wenn Sie eine Leistungssteigerung in Ihren Threads erzielen möchten, müssen Sie E / A-Vorgänge und CPU-Vorgänge in Einklang bringen.

Wenn Sie 10 Threads erstellen, die alle E / A-Vorgänge ausführen, erhalten Sie keine Leistungssteigerung.

Die asynchrone Protokollierung ist der einzige Weg, wenn Sie eine geringe Latenz in den Protokollierungsthreads benötigen. Dies geschieht für maximale Leistung durch das Disruptormuster für eine sperren- und müllfreie Thread-Kommunikation. Wenn Sie nun zulassen möchten, dass mehrere Threads gleichzeitig in derselben Datei protokolliert werden, müssen Sie entweder die Protokollaufrufe synchronisieren und den Preis für Sperrenkonflikte zahlen oder einen sperrenfreien Multiplexer verwenden. Beispielsweise bietet CoralQueue eine einfache Multiplexing-Warteschlange, wie unten beschrieben:

Sie können sich CoralLog ansehen , das diese Strategien für die asynchrone Protokollierung verwendet.

Haftungsausschluss: Ich bin einer der Entwickler von CoralQueue und CoralLog.