none
Trace.CorrelationManager.LogicalOperationStack and Parallel.For

    Question

  • I am experimenting with using Trace.CorrelationManager.LogicalOperationStack to help correlate logging messages.  When I use LogicalOperationStack with Parallel.For, it seems that the stack gets "corrupted" in some circumstances.  In particular, if there is already a logical operation in effect before the call to Parallel.For, the logical operation will eventually become invalid.  That is, the number of entries in the LogicalOperationStack will not be equal to the expected number.

    Here is a program that demonstrates the problem.  If you call "UseParallelFor()" in main, the logical operation stack will remain consistent.  If you call "UseParallelFor(true), the logical operation stack will become inconsistent.  Passing "true" indicates that then entire "UseParallelFor" function should be bracketed with StartLogicalOperation/StopLogicalOperation.

    One thing that I found interesting, and this might be common knowledge, is that in a Parallel.For, the calling thread is used by Parallel.For as one of the processing threads.  This may be the best explanation as to why my test gives the results that is does for Paralle.For.  If I put a logical operation into effect by calling Trace.CorrelationManager.StartLogicalOperation before invoking Parallel.For, then the logical operation is in effect on the (in my case) main thread.  Within my delegate code I would like to also have a logical operation in effect so that I can easily correlate logging messages.  Since Parallel.For uses the main thread as one of its "worker" threads, the act of starting a new logical operation in that case causes the main thread's LogicalOperationStack to be affected.  This doesn't seem right.

    Maybe there is a better way to use the LogicalOperationStack with Parallel.For.

    Note that I am just trying to figure how/if I can maintain adequate context information to make it easier to correlate logging messsages.  I want to figure out how/if I can do that with the various threading/Task/Parallel processing options that are available.  I am not actually currently building a solution that requires me to do a lot (or any, yet) threading/Task/Parallel processing, but I want to be ready if/when we do.

     

    using System;
    using System.Collections.Generic;
    using System.Linq;
    using System.Text;
    using System.Diagnostics;
    using System.Threading;
    using System.Threading.Tasks;
    
    namespace CorrelationManagerParallelTest
    {
     class Program 
     {   
      static void Main(string[] args)   
      {     
       //UseTasks();    //Success
       //UseTasks(true); //Success
       //UseParallelFor(); //Success
       UseParallelFor(true); //Will assert
       //UseThreadPool();   //Success
       //UseThreadPool(true);//Success
      }    
      
      private static List<int> threadIds = new List<int>();   
      private static object locker = new object();   
    
      private static int mainThreadId = Thread.CurrentThread.ManagedThreadId;
      
      private static int mainThreadUsedInDelegate = 0;
    
      //
      // baseCount is the number of items already on the 
      // LogicalOperationStack
      //
      private static void DoLongRunningWork(int baseCount)   
      {
       lock (locker)
       {
        //Keep a record of the managed thread used.       
        if (!threadIds.Contains(Thread.CurrentThread.ManagedThreadId))
         threadIds.Add(Thread.CurrentThread.ManagedThreadId);
    
        if (Thread.CurrentThread.ManagedThreadId == mainThreadId)
        {
         mainThreadUsedInDelegate++;
        }
       }     
    
       Guid lo1 = Guid.NewGuid();
       Trace.CorrelationManager.StartLogicalOperation(lo1);
       
       Guid g1 = Guid.NewGuid();     
       Trace.CorrelationManager.ActivityId = g1;
    
       Thread.Sleep(3000);     
       
       Guid g2 = Trace.CorrelationManager.ActivityId;
       Debug.Assert(g1.Equals(g2));
    
       //
       //Will eventually assert here if invoked by Parallel.For AND if a logical 
       //operation is in effect when Parallel.For is started.
       //
       Debug.Assert(Trace.CorrelationManager.LogicalOperationStack.Count == baseCount + 1, string.Format("MainThread = {0}, Thread = {1}, Count = {2}, ExpectedCount = {3}", mainThreadId, Thread.CurrentThread.ManagedThreadId, Trace.CorrelationManager.LogicalOperationStack.Count, baseCount + 1));
       Debug.Assert(Trace.CorrelationManager.LogicalOperationStack.Peek().Equals(lo1), string.Format("MainThread = {0}, Thread = {1}, Count = {2}, ExpectedCount = {3}", mainThreadId, Thread.CurrentThread.ManagedThreadId, Trace.CorrelationManager.LogicalOperationStack.Peek(), lo1));
    
       Trace.CorrelationManager.StopLogicalOperation();
      } 
    
      private static void UseTasks(bool encloseInLogicalOperation = false)
      {
       int totalThreads = 100;
       TaskCreationOptions taskCreationOpt = TaskCreationOptions.None;
       Task task = null;
       Stopwatch stopwatch = new Stopwatch();
       stopwatch.Start();
    
       if (encloseInLogicalOperation)
       {
        Trace.CorrelationManager.StartLogicalOperation();
       }
    
       Task[] allTasks = new Task[totalThreads];
       for (int i = 0; i < totalThreads; i++)
       {
        task = Task.Factory.StartNew(() =>
        {
         DoLongRunningWork(encloseInLogicalOperation ? 1 : 0);
        }, taskCreationOpt);
        allTasks[i] = task;
       }
       Task.WaitAll(allTasks);
    
       if (encloseInLogicalOperation)
       {
        Trace.CorrelationManager.StopLogicalOperation();
       }
    
       stopwatch.Stop();
       Console.WriteLine(String.Format("Completed {0} tasks in {1} milliseconds", totalThreads, stopwatch.ElapsedMilliseconds));
       Console.WriteLine(String.Format("Used {0} threads", threadIds.Count));
       Console.WriteLine(String.Format("Main thread used in delegate {0} times", mainThreadUsedInDelegate));
    
       Console.ReadKey();
      }
    
      private static void UseParallelFor(bool encloseInLogicalOperation = false)
      {
       int totalThreads = 100;
       Stopwatch stopwatch = new Stopwatch();
       stopwatch.Start();
    
       if (encloseInLogicalOperation)
       {
        Trace.CorrelationManager.StartLogicalOperation();
       }
    
       Parallel.For(0, totalThreads, i =>
       {
        DoLongRunningWork(encloseInLogicalOperation ? 1 : 0);
       });
    
       if (encloseInLogicalOperation)
       {
        Trace.CorrelationManager.StopLogicalOperation();
       }
    
       stopwatch.Stop();
       Console.WriteLine(String.Format("Completed {0} tasks in {1} milliseconds", totalThreads, stopwatch.ElapsedMilliseconds));
       Console.WriteLine(String.Format("Used {0} threads", threadIds.Count));
       Console.WriteLine(String.Format("Main thread used in delegate {0} times", mainThreadUsedInDelegate));
    
       Console.ReadKey();
      }
    
      private static void UseThreadPool(bool encloseInLogicalOperation = false)
      {
       int totalThreads = 100;
       Stopwatch stopwatch = new Stopwatch();
       stopwatch.Start();
    
       if (encloseInLogicalOperation)
       {
        Trace.CorrelationManager.StartLogicalOperation();
       }
    
    
       CountdownEvent finish = new CountdownEvent(totalThreads);
    
       for (int i = 0; i < totalThreads; i++)
       {
        int ii = i;
    
        ThreadPool.QueueUserWorkItem(x =>
        {
         DoLongRunningWork(encloseInLogicalOperation ? 1 : 0);
         finish.Signal();
        });
    
       }
    
       finish.Wait();
    
    
       if (encloseInLogicalOperation)
       {
        Trace.CorrelationManager.StopLogicalOperation();
       }
    
       stopwatch.Stop();
       Console.WriteLine(String.Format("Completed {0} tasks in {1} milliseconds", totalThreads, stopwatch.ElapsedMilliseconds));
       Console.WriteLine(String.Format("Used {0} threads", threadIds.Count));
       Console.WriteLine(String.Format("Main thread used in delegate {0} times", mainThreadUsedInDelegate));
    
       Console.ReadKey();
      }
    
     } 
    }
    
    
    Wednesday, January 19, 2011 3:01 PM

Answers

  • Hi wageoghe-

    Thanks for the repro.  I believe you're hitting a bug in LogicalCallContext, which is what's used under the covers by Trace.CorrelationManager.  I put together a small repro to highlight the problem:

    using System;
    using System.Collections;
    using System.Diagnostics;
    using System.Threading;

    class Program
    {
        static void Main()
        {
            Stack one = null, two = null, three = null;

            one = Trace.CorrelationManager.LogicalOperationStack;
            ThreadPool.QueueUserWorkItem(delegate
            {
                two = Trace.CorrelationManager.LogicalOperationStack;
                ThreadPool.QueueUserWorkItem(delegate
                {
                    three = Trace.CorrelationManager.LogicalOperationStack;
                });
            });
            SpinWait.SpinUntil(() => one != null && two != null && three != null);

            Console.WriteLine("One equals two: " + (one == two));
            Console.WriteLine("Two equals three: " + (two == three));
        }
    }

    Both of those WriteLine calls should print out false, but the second one ends up printing out true. In short, the same Stack object ends up being shared across multiple threads, leading to the corruption you're seeing.  It appears that this bug has already been filed and fixed for the next release: https://connect.microsoft.com/VisualStudio/feedback/details/609929/logicalcallcontext-clone-bug-when-correlationmanager-slot-is-present.

    Thanks for letting us know about this.

    Tuesday, February 08, 2011 7:06 PM

All replies

  • Hi wageoghe-

    Thanks for the repro.  I believe you're hitting a bug in LogicalCallContext, which is what's used under the covers by Trace.CorrelationManager.  I put together a small repro to highlight the problem:

    using System;
    using System.Collections;
    using System.Diagnostics;
    using System.Threading;

    class Program
    {
        static void Main()
        {
            Stack one = null, two = null, three = null;

            one = Trace.CorrelationManager.LogicalOperationStack;
            ThreadPool.QueueUserWorkItem(delegate
            {
                two = Trace.CorrelationManager.LogicalOperationStack;
                ThreadPool.QueueUserWorkItem(delegate
                {
                    three = Trace.CorrelationManager.LogicalOperationStack;
                });
            });
            SpinWait.SpinUntil(() => one != null && two != null && three != null);

            Console.WriteLine("One equals two: " + (one == two));
            Console.WriteLine("Two equals three: " + (two == three));
        }
    }

    Both of those WriteLine calls should print out false, but the second one ends up printing out true. In short, the same Stack object ends up being shared across multiple threads, leading to the corruption you're seeing.  It appears that this bug has already been filed and fixed for the next release: https://connect.microsoft.com/VisualStudio/feedback/details/609929/logicalcallcontext-clone-bug-when-correlationmanager-slot-is-present.

    Thanks for letting us know about this.

    Tuesday, February 08, 2011 7:06 PM
  • Stephen,

    Thanks for the info.  I wonder if this could still be a problem with Parallel.For, even with a fix for the problem as described in the bug report.  The bug describes a problem with the LogicalOperationStack becoming shared across threads when an object in the LogicalCallContext is cloned and then cloned again.  I can reproduce a similar problem with Parallel.For where there should only be one level of cloning.  Here is a sample program:

     

    using System;
    using System.Collections;
    
    using System.Diagnostics;
    using System.Threading;
    using System.Threading.Tasks;
    
    namespace LogicalOperationStackParallel
    {
     class Program
     {
     static void Main(string[] args)
     {
      int numIterations = 25;
    
      Guid outerOperation = Guid.NewGuid();
      Stack outerStack = Trace.CorrelationManager.LogicalOperationStack;
      int mainThread = Thread.CurrentThread.ManagedThreadId;
    
      Console.WriteLine("main thread = {0}", mainThread);
    
      Trace.CorrelationManager.StartLogicalOperation(outerOperation);
    
      Parallel.For(0, numIterations, i => 
      {
      int ii = i;
      Stack innerStack = Trace.CorrelationManager.LogicalOperationStack;
      int workerThread = Thread.CurrentThread.ManagedThreadId;
    
      if (innerStack.Count != 1) 
      {
       Console.WriteLine("1. iteration = {0}, thread = {1}, innerStack.count = {2}, expected = 1", ii, workerThread, innerStack.Count);
      }
    
      Guid innerOperation = Guid.NewGuid();
      Trace.CorrelationManager.StartLogicalOperation(innerOperation);
    
      if (innerStack.Count != 2)
      {
       Console.WriteLine("2. iteration = {0}, thread = {1}, innerStack.count = {2}, expected = 2", ii, workerThread, innerStack.Count);
      }
    
      Thread.Sleep(1000);
    
      if (innerStack.Count != 2)
      {
       Console.WriteLine("3. iteration = {0}, thread = {1}, innerStack.count = {2}, expected = 2", ii, workerThread, innerStack.Count);
      }
    
      Trace.CorrelationManager.StopLogicalOperation();
    
      if (innerStack.Count != 1)
      {
       Console.WriteLine("4. iteration = {0}, thread = {1}, innerStack.count = {2}, expected = 1", ii, workerThread, innerStack.Count);
      }
      });
    
      if (Trace.CorrelationManager.LogicalOperationStack.Count != 1)
      {
      Console.WriteLine("5. LogicalOperationStack.Count = {0}", Trace.CorrelationManager.LogicalOperationStack.Count);
      }
    
      Console.ReadKey();
     }
     }
    }
    
    

    Please forgive the Console.WriteLines, they help keep track of what is going on.  In essence, the program does this (in pseudocode):

    main()
    {
     StartLogicalOperation()
     Parallel.For(0,25, i=>
     {
     StartLogicalOperation()
     Sleep(1000);
     StopLogicalOperation()
     }
     StopLogicalOperation()
    }
    

    (Actually, I just noticed that my test program does not call StopLogicalOperation after the Parallel.For.  For the purposes of the problem I am illustrating, that doesn't matter).

    I would expect that in any execution of the delegate in the parallellized loop the LogicalOperationStack would have 1 item on entry (the operation started in the main thread), 2 items after the "inner" StartLogicalOperation, 1 item after the "inner" StopLogicalOperation. Finally, the "outer" LogicalOperationStack should have 1 item after the Parallel.For loop is completed (but before stopping the "outer" logical operation).

    Instead, when I run my sample program, the "inner" LogicalOperationStack has as many as 5 items on the stack on entry to the delegate when the expected number is 1.  My guess is that this is because Parallel.For uses the main thread as one of the "worker" threads.  So, while the main thread's LogicalOperationStack might be cloned for some executions of the delegate, it will not be cloned for the executions of the delegate that occur on the main thread (i.e. when the "worker" thread is the same as the main thread).  Also, if the main thread's LogicalOperationStack is cloned for another thread while the delegate is executing on the "main" thread, then the cloned LogicalOperationStack will have not only the "outer" logical operation but also the "inner" operation of the "worker" thread (that is the same as the main thread).

    It seems to me that the expected fix for the bug you linked above would probably be to ensure that the m_IsCorrelationMgr member variable is cloned (or copied) when a clone of a clone is made.  I'm not sure that would help in the Parallel.For case.

     Does what I am saying make sense? 

     PS My code didn't format as nicely as yours (mainly syntax coloring is not so good).

    Tuesday, February 08, 2011 8:03 PM
  • Hi wageoghe-

    re: "The bug describes a problem with the LogicalOperationStack becoming shared across threads when an object in the LogicalCallContext is cloned and then cloned again.  I can reproduce a similar problem with Parallel.For where there should only be one level of cloning."

    Parallel.For doesn't actually work the way you're assuming it works.  Specifically, it doesn't just spin up tasks that are all in effect peers.  Rather, it spins up a single task, and if/when that task starts running it spins up another task, and that task spins up another task, and so on.  This allows a parallel loop to spread out over however many cores threads the underlying scheduler gives it, and that's why it's close in nature to the repro I provided, where a work item is creating a work item is creating a work item.  It's true that the first task executes on the current thread, but that's largely immaterial to this issue, as the ExecutionContext is still captured for the task and used to process the task's body, temporarily overwriting the current logical call context that was there before (ExecutionContext.Run handles the temporary replacement and then putting back the original before exiting).

    Tuesday, February 08, 2011 11:07 PM
  • Stephen,

    Thanks for the great information.  I appreciate the original answer as well as the extra information in your most recent response.

    Willie.

    Wednesday, February 09, 2011 2:40 PM