Search code examples
c#multithreadingtask-parallel-librarypostsharp

Unique logger inside Post Sharp attribute used by multiple threads


I have implemented Postsharp attribute as shown below and following are the usage details:

  • Either have static Func<ILog> GetLogger or static ThreadLocal<ILog> TestLogger, which are set-up from the method HelloTask from Main program
  • Aim is to have a separate logger for each thread calling the method DoTask

I was quite wary of setting up a static Func or static ThreadLocal, and thought this will lead to issue (Race condition or corruption) due to multiple threads, but as it could be seen in the Main method even with 100 tasks invoked it works perfectly fine, so is this correct way and which one is better, I assume ThreadLocal would be preferable

Is there a better way to achieve the same ?

    [Serializable]
    public class LogExecutionTimeAttribute : OnMethodBoundaryAspect
    {

    [NonSerialized]
    public static Func<ILog> GetLogger;

    [NonSerialized]
    public static ThreadLocal<ILog> TestLogger;

    public LogExecutionTimeAttribute()
    {
        // Setting AspectPriority explicity avoids undeterministic behaviour 
        // when multiple aspects are applied, and avoids warning messages
        this.AspectPriority = 1;
    }       

    public override void OnEntry(MethodExecutionArgs args)
    {
        args.MethodExecutionTag = Stopwatch.StartNew();
        base.OnEntry(args);
    }

    public override void OnExit(MethodExecutionArgs args)
    {
        Stopwatch sw = (Stopwatch)args.MethodExecutionTag;
        sw.Stop();
        var logger =
     #if Func
           GetLogger();
     #else
        TestLogger.Value;
     #endif 

        logger.DebugFormat(
            "{0}.{1} for Id={2} executed in {3} seconds.", 
            this.className, 
            this.methodName, 
            args.Arguments[0],
            sw.ElapsedMilliseconds / 1000.0);
        base.OnExit(args);
      }
     }

Following is the usage:

 class Program
    {

   static void Main(string[] args)
        {
            var taskList = new List<Task>();

            for (var counter = 0; counter < 100; counter++)
            {
                var localCounter = counter;

                taskList.Add(Task.Factory.StartNew(() => HelloTask(localCounter + 1), TaskCreationOptions.LongRunning));
            }

            Task.WaitAll(taskList.ToArray());
        }

        [LogExecutionTime]
        private static void DoTask(int id)
        {
 #if Func
            LogExecutionTimeAttribute.GetLogger().Info(id);
#else
                LogExecutionTimeAttribute.TestLogger.Value.Info(id);
#endif
        }


        private static void HelloTask(int id)
        {
            var log  = new LogFileLogger(id.ToString()).LogInstance;

            #if Func
                LogExecutionTimeAttribute.GetLogger = () => log;
            #else
                LogExecutionTimeAttribute.TestLogger = new ThreadLocal<ILog>(() => log);
            #endif

            var sw = Stopwatch.StartNew();

            for (var i = 0; i < 50; i++)
            {
                DoTask(i);
            }

            sw.Stop();

        #if Func
            LogExecutionTimeAttribute.GetLogger().Info("Time :: " + sw.ElapsedMilliseconds);
        #else
            LogExecutionTimeAttribute.TestLogger.Value.Info("Time :: " + sw.ElapsedMilliseconds);
        #endif

        }    

    }

Solution

  • As was described in the response to the similar question on Code Review site: when you have a different logger instance for each thread, you should store it in a thread static or thread local field to avoid concurrency issues.

    From the design point of view it would be better to also make aspect independent of how you create your logger instances. So, for example, assign the static GetLogger only once on app start-up, and leave it to aspect consumer to decide whether logger should be created per thread, per instance or per application.

    [Serializable]
    public class LogExecutionTimeAttribute : OnMethodBoundaryAspect
    {
        public static Func<ILog> GetLogger;
        // ...
    }
    
    public static class LoggerFactory
    {
        [ThreadStatic]
        public static ILog Logger;
    
        public static ILog GetLogger()
        {
            return Logger;
        }
    }
    
    class Program
    {
        static void Main(string[] args)
        {
            // Configure factory only once.
            LogExecutionTimeAttribute.GetLogger = LoggerFactory.GetLogger;
            // ...
        }
    
        private static void HelloTask(int id)
        {
            var log  = new LogFileLogger(id.ToString()).LogInstance;
            LoggerFactory.Logger = log;
            // ...
         }
    }
    

    You can read more about consuming dependencies from the aspects on this documentation page: http://doc.postsharp.net/consuming-dependencies