Missing log statements in parallel foreach loop

Question

I'm using parallel foreach/for loop, in particular case I need to go with nested parallel foreach/for loop. While I tried to print the values in my collection, sometimes console statements are not being printed which is not consistent. See the piece of code below.

Parallel.For(0, RunModuleConfigVariables.Count, new ParallelOptions { MaxDegreeOfParallelism = 3 }, index => {
                string log = null;
                int count = 0;
                log += "Module Name " + RunModuleConfigVariables.Keys.ElementAt(index) + " thread: " + Thread.CurrentThread.ManagedThreadId + "\n";
                Parallel.ForEach(RunModuleConfigVariables[RunModuleConfigVariables.Keys.ElementAt(index)], new ParallelOptions { MaxDegreeOfParallelism = 10 }, eachendpoint => {

                    log += "\t" + count + " Endpoint Name " + eachendpoint + "\n";
                    count++;
                });
                Console.WriteLine(log);
            });

Collection:

Collection type is ConcurrentDictionary<string, HashSet>()

RunModuleConfigVariables:
        {
      "Module_1": [
        "Module_1_Endpoint_1",
        "Module_1_Endpoint_2",
        "Module_1_Endpoint_3",
        "Module_1_Endpoint_4",
        "Module_1_Endpoint_5",
        "Module_1_Endpoint_6",
        "Module_1_Endpoint_7",
        "Module_1_Endpoint_8",
        "Module_1_Endpoint_9",
        "Module_1_Endpoint_10",
        "Module_1_Endpoint_11",
        "Module_1_Endpoint_12",
        "Module_1_Endpoint_13",
        "Module_1_Endpoint_14",
        "Module_1_Endpoint_15",
        "Module_1_Endpoint_16",
        "Module_1_Endpoint_17",
        "Module_1_Endpoint_18",
        "Module_1_Endpoint_19"
      ],
      "Module_2": [
        "Module_2_Endpoint_1",
        "Module_2_Endpoint_2",
        "Module_2_Endpoint_3"
      ],
      "Module_3": [
        "Module_3_Endpoint_1"
      ]
    }

Actual Output:

Module Name Module_1 thread: 4
        0 Endpoint Name Module_1_Endpoint_2
        1 Endpoint Name Module_1_Endpoint_1
        2 Endpoint Name Module_1_Endpoint_4
        3 Endpoint Name Module_1_Endpoint_5
        4 Endpoint Name Module_1_Endpoint_6
        5 Endpoint Name Module_1_Endpoint_7
        6 Endpoint Name Module_1_Endpoint_8
        18 Endpoint Name Module_1_Endpoint_9

Module Name Module_3 thread: 5
        0 Endpoint Name Module_3_Endpoint_1

Module Name Module_2 thread: 1
        0 Endpoint Name Module_2_Endpoint_2
        1 Endpoint Name Module_2_Endpoint_3
        2 Endpoint Name Module_2_Endpoint_1

Expected Output: (Needn't be in same order)

Module Name Module_1 thread: 5
        0 Endpoint Name Module_1_Endpoint_2
        1 Endpoint Name Module_1_Endpoint_3
        2 Endpoint Name Module_1_Endpoint_4
        3 Endpoint Name Module_1_Endpoint_5
        4 Endpoint Name Module_1_Endpoint_6
        5 Endpoint Name Module_1_Endpoint_7
        6 Endpoint Name Module_1_Endpoint_8
        7 Endpoint Name Module_1_Endpoint_9
        8 Endpoint Name Module_1_Endpoint_10
        9 Endpoint Name Module_1_Endpoint_11
        10 Endpoint Name Module_1_Endpoint_12
        11 Endpoint Name Module_1_Endpoint_13
        12 Endpoint Name Module_1_Endpoint_14
        13 Endpoint Name Module_1_Endpoint_15
        14 Endpoint Name Module_1_Endpoint_16
        15 Endpoint Name Module_1_Endpoint_17
        16 Endpoint Name Module_1_Endpoint_18
        17 Endpoint Name Module_1_Endpoint_19
        18 Endpoint Name Module_1_Endpoint_1

Module Name Module_2 thread: 4
        0 Endpoint Name Module_2_Endpoint_2
        1 Endpoint Name Module_2_Endpoint_3
        2 Endpoint Name Module_2_Endpoint_1

Module Name Module_3 thread: 1
        0 Endpoint Name Module_3_Endpoint_1

Note: Output is not consistent. Sometimes able to see all sub-childs and sometimes not. How can I understand this, and what can be done to overcome this?

score 4 · Answer 1 · edited Sep 13 '20 at 19:25

How can I understand this?

Parallel processing means multiple threads are doing things at the same time. This leads to all kinds of weird things that you have to be careful of.

Consider the line:

count++;

This one C# instruction actually represents multiple operations:

load the value from the count variable from memory into the processor.
add 1 to the value of the value loaded into the processor.
store the new value into the memory location for the count variable.

Now imagine two threads doing these three instructions at the same time. There's a slight possibility that both of them will complete step 1 before either completes step 3. That means if count started at zero, both threads will now set count to 1, which isn't what you intended.

This line has many more steps between the point where log is read and the point where it is written:

log += "\t" + count + " Endpoint Name " + eachendpoint + "\n";

Therefore, you'll find that it's much more frequent for one thread to overwrite (rather than add to) the value already written by another thread. That's the behavior you're noticing.

... and let me know, what can be done to overcome this.

First, avoid parallel processing whenever possible.

If things are going fast enough with a simple foreach loop, don't try to optimize them.

If things are not going fast enough with a simple foreach loop, figure out why. Most of the time, it'll be because of I/O operations (disk or network accesses). In those cases, use concurrent execution of asynchronous tasks rather than multithreading. See https://stackoverflow.com/a/14130314/120955 and What is the difference between asynchronous programming and multithreading?.

If you're performing operations that require CPU power, and you really need them to run in parallel to squeeze that extra bit of performance out of them, try to avoid changing state in each one (e.g. setting values for shared variables, like count++). One good strategy for this is Command/Query Separation, where you do your parallel processing on immutable data structures to produce "answers", and then use those answers to make the changes that must be made all on the same thread. Here's how that might look in your code:

var logs = RunModuleConfigVariables
    .AsParallel()
    .WithDegreeOfParallelism(3)
    .Select(e =>
        "Module Name " + e.Key + " thread: " + Thread.CurrentThread.ManagedThreadId + "\n"
            + string.Join("\n",
                e.Value
                    .AsParallel()
                    .WithDegreeOfParallelism(10)
                    .Select((eachendpoint, index) => "\t" + index + " Endpoint Name " + eachendpoint)

    ));

Console.WriteLine(string.Join("\n", logs));

Finally, if you absolutely must change state in parallel, you need to take the time to learn about locks, Mutexes, Concurrent Collections, atomic operations, and other similar tools, and make sure you're only using thread-safe methods in parallel contexts, in order to make sure you're doing it "right."

That might lead to something like this:

Parallel.ForEach(RunModuleConfigVariables, new ParallelOptions { MaxDegreeOfParallelism = 3 }, pair =>
{
    Console.WriteLine("Module Name " + pair.Key + " thread: " + Thread.CurrentThread.ManagedThreadId);
    var count = 0;
    Parallel.ForEach(pair.Value, new ParallelOptions { MaxDegreeOfParallelism = 10 }, eachendpoint =>
    {
        var thisCount = Interlocked.Increment(ref count);
        Console.WriteLine("\t" + thisCount + " Endpoint Name " + eachendpoint + "\n");
    });
});

good explanation. I have a set of instructions that need to be implemented in inner parallel loop. Each iteration is an independent task, so I'm thinking asynchronous multi threaded will work. "count" variable is just to verify whether all items are displayed (something like serial number which would be easy to validate). I tried to remove that variable and excute again, but no luck. Reason for adding log variable to get console log statements endpoint wise(inner loop) because simple console statements will create a mess with order of steps in each endpoint. — Krishna Barri, Aug 25 '20 at 18:46
@KrishnaBarri: If you're dealing with asynchronous Tasks, I would suggest _not_ doing multithreading. Instead, gather a collection of the Tasks and use `await Task.WhenAll()` to get their results. That'll avoid the thread safety issues, while still probably giving you the performance boost you're looking for. — StriplingWarrior, Aug 25 '20 at 19:55
My requirement is, I have a set of endpoints in every module which I need to execute module wise, respective endpoints in parallel. In this case, both my module and endpoints should execute parallely which will cut down my execution time (have more than 25k cases overall). I thought, running parallel for loop would make satisfy my expectation, is there any better way that I can achieve? (need to copy endpoint level console log as well) — Krishna Barri, Aug 26 '20 at 09:13
@KrishnaBarri: When you say "endpoints", my mind goes to asynchronous calls: is that what you're talking about? So most of the time is spent waiting for those asynchronous calls to complete? In that case, following the advice in my previous comment above will probably give you an equal (possibly greater) performance boost while only using one thread. (See my paragraph and links about concurrent async versus parallel/multithreading in my answer.) [Here's a code sample](https://stackoverflow.com/a/61758546/120955) showing that pattern, to give you an idea of what I'm talking about. — StriplingWarrior, Aug 26 '20 at 15:56

gmiley · Answer 2 · 2020-08-25T17:13:48.373

1

The problem is that your variable log is being assigned to by multiple threads. You need to lock it before you attempt to write to it.

Parallel.For(0, RunModuleConfigVariables.Count, new ParallelOptions { MaxDegreeOfParallelism = 3 }, index => {
                string log = null;
                int count = 0;
                log += "Module Name " + RunModuleConfigVariables.Keys.ElementAt(index) + " thread: " + Thread.CurrentThread.ManagedThreadId + "\n";
                object locker = new object();
                Parallel.ForEach(RunModuleConfigVariables[RunModuleConfigVariables.Keys.ElementAt(index)], new ParallelOptions { MaxDegreeOfParallelism = 10 }, eachendpoint => {
                    lock(locker)
                        log += "\t" + (count++) + " Endpoint Name " + eachendpoint + "\n";
                });
                Console.WriteLine(log);
            });

edited Aug 25 '20 at 17:13

answered Aug 25 '20 at 15:42

gmiley

6,531
1
13
25

2

Your assessment of the problem is right, but I don't know if I'd recommend locking the parallel process while appending to a string. How about using a PLINQ query that returns the log message from each parallel task, and then joining all those messages at the end before logging? Or using a real logging framework that can handle multithreaded writes? – StriplingWarrior Aug 25 '20 at 15:46
`Console.WriteLine` is perfectly threadsafe, and limiting the scope of the lock to the specific instruction is acceptable practice. You could return a value, but does that really change the speed in any measurable way? There are more instructions being added by doing that than simply locking for the time it takes to reassign the value of the variable. – gmiley Aug 25 '20 at 15:50
I should add, that in this example it might make a difference as the only instruction is to append and reassign a variable then increment and reassign one more variable. In practice though, running things in parallel would make more sense for larger operations in which a quick lock is going to be negligible. – gmiley Aug 25 '20 at 15:53
Good point on Console.WriteLine being threadsafe. Why not just move that into the ForEach rather than build up the string, I wonder? – StriplingWarrior Aug 25 '20 at 16:06
The output would be garbled from the desired output is the only reason, but yes, that would be the better approach and just preface the output with the stack of threads it belongs to. – gmiley Aug 25 '20 at 16:08
Why create `locker`? Surely `lock(log) { log+=... }` is fine? – Matthew1680 Aug 02 '23 at 13:02

Missing log statements in parallel foreach loop

2 Answers2