Log de forma assíncrona - como isso deve ser feito?

Em muitos dos serviços em que trabalho, muitos registros estão sendo feitos. Os serviços são serviços WCF (principalmente) que usam a classe .NET EventLogger.

Estou no processo de melhorar o desempenho desses serviços e acho que o log de maneira assíncrona beneficiaria o desempenho.

Não sei o que acontece quando vários threads pedem para registrar, e se isso cria um gargalo, mas mesmo que não ache, ainda acho que não deve interferir no processo real que está sendo executado.

Penso que devo invocar o mesmo método de log que chamo agora, mas usando um novo encadeamento, continuando com o processo real.

Algumas perguntas sobre isso:

Tudo bem?

Existem desvantagens?

Deve ser feito de uma maneira diferente?

Talvez seja tão rápido que nem vale o esforço?

Segmento separado para operação de E / S parece razoável.

Por exemplo, não seria bom registrar quais botões o usuário pressionou no mesmo thread da interface do usuário. Essa interface do usuário será interrompida aleatoriamente e terá um desempenho percebido lento .

A solução é desacoplar o evento de seu processamento.

Aqui estão muitas informações sobre o problema produtor-consumidor e fila de eventos do mundo do desenvolvimento de jogos

Muitas vezes, existe um código como

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

Essa abordagem levará à contenção de threads. Todos os threads de processamento estarão lutando para obter bloqueio e gravação no mesmo arquivo de uma só vez.

Alguns podem tentar remover bloqueios.

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

Não é possível prever o resultado se 2 threads entrarem no método ao mesmo tempo.

Então, eventualmente, os desenvolvedores desabilitarão o log ...

É possível consertar?

Sim.

Vamos dizer que temos interface:

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

Em vez de esperar pelo bloqueio e executar a operação do arquivo de bloqueio sempre que ILoggerfor chamado, adicionaremos o LogMessage à fila de mensagens Penging e voltaremos para coisas mais 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));
    }
}

Fizemos com este simples registrador assíncrono .

O próximo passo é processar as mensagens recebidas.

Para simplificar, vamos iniciar um novo thread e aguardar eternamente até o aplicativo sair ou o Asynchronous Logger adicionará uma nova mensagem à fila pendente .

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

    }
}

Estou passando por uma cadeia de ouvintes personalizados. Você pode querer enviar apenas a estrutura de registro de chamadas ( log4net, etc ...)

Aqui está o restante do código:

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

Ponto de entrada:

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

Os principais fatores a serem considerados são sua necessidade de confiabilidade nos arquivos de log e a necessidade de desempenho. Consulte desvantagens. Eu acho que essa é uma ótima estratégia para situações de alto desempenho.

Tudo bem - sim

Existem desvantagens - sim - dependendo da criticidade do seu log e da sua implementação, qualquer um dos seguintes itens pode ocorrer - logs gravados fora de sequência, ações do encadeamento de logs não concluídas antes da conclusão das ações do evento. (Imagine um cenário em que você registra "começando a se conectar ao banco de dados" e depois trava o servidor, o evento de log nunca pode ser gravado, mesmo que o evento tenha ocorrido (!))

Deve ser feito de uma maneira diferente - você pode querer olhar para o modelo Disruptor, pois é quase ideal para este cenário

Talvez seja tão rápido que nem sequer valha o esforço - discordo. Se a sua é uma lógica de "aplicativo", e a única coisa que você faz é gravar logs da atividade - então você terá ordens de magnitude mais baixa latência descarregando o log. Se, no entanto, você confiar em uma chamada SQL de 5 segundos para retornar antes de registrar 1-2 instruções, os benefícios serão variados.

Eu acho que o log é geralmente uma operação síncrona por natureza. Você deseja registrar as coisas se elas acontecerem ou não, dependendo da sua lógica. Portanto, para registrar alguma coisa, essa coisa precisa ser avaliada primeiro.

Dito isto, você pode melhorar o desempenho do seu aplicativo armazenando em cache os logs e, em seguida, criando um encadeamento e salvando-os em arquivos quando tiver uma operação vinculada à CPU.

Você precisa identificar seus pontos de verificação de maneira inteligente, para não perder suas informações importantes de registro durante esse período de cache.

Se você deseja obter um aumento de desempenho em seus encadeamentos, precisa equilibrar as operações de E / S e as operações da CPU.

Se você criar 10 threads que executam IO, não receberá um aumento de desempenho.

O log de forma assíncrona é o único caminho a percorrer se você precisar de baixa latência nos threads de log. A maneira como isso é feito para obter o desempenho máximo é através do padrão de disruptor para comunicação de encadeamento sem bloqueios e sem lixo. Agora, se você deseja permitir que vários encadeamentos registrem simultaneamente no mesmo arquivo, você deve sincronizar as chamadas de log e pagar o preço em contenção de bloqueio OU usar um multiplexador sem bloqueio. Por exemplo, o CoralQueue fornece uma fila simples de multiplexação, conforme descrito abaixo:

Você pode dar uma olhada no CoralLog, que usa essas estratégias para o log assíncrono.

Disclaimer: Eu sou um dos desenvolvedores do CoralQueue e CoralLog.