How Thread-Safe is NLog?

I don’t really have an answer to your problem, but I do have some observations and some questions:

According to your code, it looks like you want to create a logger per thread and you want to have that logger log to a file named for some passed-in id value. So, the logger whose id is “abc” would log to “x:\abc.log”, “def” would log to “x:\def.log”, and so on. I suspect that you can do this via NLog configuration rather than programmatically. I don’t know if it would work any better, or if NLog would have the same issue as you are having.

My first impression is that you are doing a lot of work: creating a file target per thread, creating a new rule per thread, getting a new logger instance, etc, that you might not need to do to accomplish what it appears that you want to accomplish.

I know that NLog allows the output file to be named dynamically, based on at least some of the NLog LayoutRenderers. For example, I know that this works:

fileName="${level}.log"

and will give you filenames like this:

Trace.log
Debug.log
Info.log
Warn.log
Error.log
Fatal.log

So, for example, it seems that you could use a pattern like this to create output file(s) based on thread id:

fileName="${threadid}.log"

And if you ended up having threads 101 and 102, then you would have two log files: 101.log and 102.log.

In your case, you want to name the file based on your own id. You could store the id in the MappedDiagnosticContext (which is a dictionary that allows you to store thread-local name-value pairs) and then reference that in your pattern.

Your pattern for your filename would look something like this:

fileName="${mdc:myid}.log"

So, in your code you might do this:

         public class ThreadManager
         {
           //Get one logger per type.
           private static readonly Logger logger = LogManager.GetCurrentClassLogger();

           protected override void OnDoWork(DoWorkEventArgs e)
           {
             // Set the desired id into the thread context
             NLog.MappedDiagnosticsContext.Set("myid", myRandomID);

             logger.Info("Hello from thread {0}, myid {1}", Thread.CurrentThread.ManagedThreadId, myRandomID);
             base.OnDoWork(e);  

             //Clear out the random id when the thread work is finished.
             NLog.MappedDiagnosticsContext.Remove("myid");
           }
         }

Something like this should allow your ThreadManager class to have a single logger named “ThreadManager”. Each time it logs a message, it will log the formatted string in the Info call. If the logger is configured to log to the File target (in the config file make a rule that sends “*.ThreadManager” to a File target whose filename layout is something like this:

fileName="${basedir}/${mdc:myid}.log"

At the time a message is logged, NLog will determine what the filename should be, based on the value of the fileName layout (i.e. it applies the formatting tokens at log time). If the file exists, then the message is written to it. If the file does not exist yet, the file is created and the message is logged to it.

If each thread has a random id like “aaaaaaaaaaaa”, “aaaaaaaaaaab”, “aaaaaaaaaaac”, then you should get log files like this:

aaaaaaaaaaaa.log
aaaaaaaaaaab.log
aaaaaaaaaaac.log

And so on.

If you can do it this way, then your life should be simpler as you do not have to all of that programmatic configuration of NLog (creating rules and file targets). And you can let NLog worry about creating the output file names.

I don’t know for sure that this will work any better than what you were doing. Or, even if it does, you might really need to what you are doing in your bigger picture. It should be easy enough to test to see that it even works (i.e. that you can name your output file based a value in the MappedDiagnosticContext). If it works for that, then you can try it for your case where you are creating thousands of threads.

UPDATE:

Here is some sample code:

Using this program:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;

using NLog;
using System.Threading;
using System.Threading.Tasks;

namespace NLogMultiFileTest
{
  class Program
  {
    public static Logger logger = LogManager.GetCurrentClassLogger();

    static void Main(string[] args)
    {

      int totalThreads = 50;
      TaskCreationOptions tco = TaskCreationOptions.None;
      Task task = null;

      logger.Info("Enter Main");

      Task[] allTasks = new Task[totalThreads];
      for (int i = 0; i < totalThreads; i++)
      {
        int ii = i;
        task = Task.Factory.StartNew(() =>
        {
          MDC.Set("id", "_" + ii.ToString() + "_");
          logger.Info("Enter delegate.  i = {0}", ii);
          logger.Info("Hello! from delegate.  i = {0}", ii);
          logger.Info("Exit delegate.  i = {0}", ii);
          MDC.Remove("id");
        });

        allTasks[i] = task;
      }

      logger.Info("Wait on tasks");

      Task.WaitAll(allTasks);

      logger.Info("Tasks finished");

      logger.Info("Exit Main");
    }
  }
}

And this NLog.config file:

<?xml version="1.0" encoding="utf-8" ?>
<!-- 
  This file needs to be put in the application directory. Make sure to set 
  'Copy to Output Directory' option in Visual Studio.
  -->
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">

    <targets>
        <target name="file" xsi:type="File" layout="${longdate} | ${processid} | ${threadid} | ${logger} | ${level} | id=${mdc:id} | ${message}" fileName="${basedir}/log_${mdc:item=id}.txt" />
    </targets>

    <rules>
        <logger name="*" minlevel="Debug" writeTo="file" />
    </rules>
</nlog>

I am able to get one log file for each execution of the delegate. The log file is named for the “id” stored in the MDC (MappedDiagnosticContext).

So, when I run the sample program, I get 50 log files, each of which has three lines in it “Enter…”, “Hello…”, “Exit…”. Each file is named log__X_.txt where X is the value of the captured counter (ii), so I have log_0.txt, log_1.txt, log_1.txt, etc, log_49.txt. Each log file contains only those log messages pertaining to one execution of the delegate.

Is this similar to what you want to do? My sample program uses Tasks rather than threads because I had already written it some time ago. I think that the technique should adapt to what you are doing easily enough.

You could also do it this way (getting a new logger for each excecution of the delegate), using the same NLog.config file:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;

using NLog;
using System.Threading;
using System.Threading.Tasks;

namespace NLogMultiFileTest
{
  class Program
  {
    public static Logger logger = LogManager.GetCurrentClassLogger();

    static void Main(string[] args)
    {

      int totalThreads = 50;
      TaskCreationOptions tco = TaskCreationOptions.None;
      Task task = null;

      logger.Info("Enter Main");

      Task[] allTasks = new Task[totalThreads];
      for (int i = 0; i < totalThreads; i++)
      {
        int ii = i;
        task = Task.Factory.StartNew(() =>
        {
          Logger innerLogger = LogManager.GetLogger(ii.ToString());
          MDC.Set("id", "_" + ii.ToString() + "_");
          innerLogger.Info("Enter delegate.  i = {0}", ii);
          innerLogger.Info("Hello! from delegate.  i = {0}", ii);
          innerLogger.Info("Exit delegate.  i = {0}", ii);
          MDC.Remove("id");
        });

        allTasks[i] = task;
      }

      logger.Info("Wait on tasks");

      Task.WaitAll(allTasks);

      logger.Info("Tasks finished");

      logger.Info("Exit Main");
    }
  }
}

Leave a Comment