Runtime: Very high latency for GC when using (lots of) ThreadLocal

[ayende]

The problem below reproduce an issue that we have run into in production.

We have a lot of ThreadLocal instances and quite a number of threads and we noticed very high latency for GC / CPU time spent collecting.

The code below creates a large number of ThreadLocal<WeakReference> and uses them from a number of threads. We manually induce GC into the system to measure its costs on a frequent basis.

Our observations is that while we are doing active work, we are seeing GC times that exceed 1 second at times (average of about 500 ms) and when there is _no work at all_, all threads are idle and only the GC is running, we are seeing > 250 ms for GC runs.

Our current assumption is that the lattice like nature of ThreadLocal with thread static arrays with each item linked to the next thread, is causing the GC to spend a lot of time in the mark phase.

```c#
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Runtime;
using System.Text;
using System.Threading;
using System.Threading.Tasks;

namespace RavenTicket
{
class Program
{
static void Main(string[] args)
{
Console.WriteLine($"GC ServerMode: {GCSettings.IsServerGC }, LOH Compact: {GCSettings.LargeObjectHeapCompactionMode}, Latency: {GCSettings.LatencyMode} ");

        int running = 0, stopped = 0;
        var abc = new string('*', 1024*2024);

        var task = Task.Run(() =>
        {
            var foregroundColor = Console.ForegroundColor;
            while (true)
            {
                var sp = Stopwatch.StartNew();
                GC.Collect(2);
                var gc = sp.ElapsedMilliseconds;
                sp.Restart();
                GC.WaitForPendingFinalizers();
                var run = Volatile.Read(ref running);
                var stop = Volatile.Read(ref stopped);
                if (gc > 200)
                {
                    Console.ForegroundColor= ConsoleColor.Red;
                }
                Console.WriteLine($"{gc} - {sp.ElapsedMilliseconds} - {run} - {stop} - {run - stop:#,#;;0}");
                if (gc > 200)
                {
                    Console.ForegroundColor = foregroundColor;
                }
                Thread.Sleep(500);
            }
        });

        var list = new List<ThreadLocal<WeakReference>>();
        var threads = new List<Thread>();

        const int numberOfThreadLocals = 10_000;
        const int numberOfThreads = 2500;
        const int numberOfActiveThreads = 64;


        for (int i = 0; i < numberOfThreadLocals; i++)
        {
            list.Add(new ThreadLocal<WeakReference>());
        }
        var stageOne= new CountdownEvent(numberOfThreads);
        var stageTwo = new SemaphoreSlim(0, numberOfActiveThreads);
        for (int i = 0; i < numberOfThreads; i++)
        {
            var copy = i;
            threads.Add(new Thread(() =>
            {
                for (var index = copy; index < list.Count; index += (copy % 10) + 1)
                {
                    list[index].Value = null;
                }
                stageOne.Signal();
                stageTwo.Wait();
                Interlocked.Increment(ref running);
                string s = null;
                if (copy % 128 == 0)
                    s = AllocateLotsOfMemory();
                for (var index = copy; index < numberOfThreadLocals; index += 16)
                {
                    var t = list[index];
                    if (index % 2 == 0)
                    {
                        t.Value = new WeakReference(list);
                    }
                    else if ((index % 5) == 0)
                    {
                        t.Value = new WeakReference(abc);
                    }
                    else if ((index % 51) == 0)
                    {
                        t.Value =
                            new WeakReference(s);
                    }
                    else
                    {
                        t.Value =
                          new WeakReference(AllocateLotsOfMemory());
                    }
                }

                s = null;
                stageTwo.Release();
                Interlocked.Increment(ref stopped);
                threads[copy].Join();
            })
            {
                IsBackground = true
            });
        }
        threads.ForEach(t => t.Start());
        Console.WriteLine("Init...");
        stageOne.Wait();
        Console.WriteLine("Starting..");
        stageTwo.Release(64);



        Task.Run(() => // force some additional memory traffic
        {
            for (int i = 0; i < 200_000; i++)
            {
                AllocateLotsOfMemory();
            }
        });

        task.Wait();
        Console.WriteLine(abc);
    }

    private static string AllocateLotsOfMemory()
    {
        var sb = new StringBuilder();
        for (int j = 0; j < 10_000; j++)
        {
            sb.Append(j);
        }

        var s1 = sb.ToString();
        return s1;
    }
}

}

```

[ayende]

Here is another reproduction, this time without ThreadLocal or any threading work, which shows interesting results.

We created a lattice like structure, many arrays that are forming doubly linked list to other nodes in the same index on the other arrays.

The cost of GC here is around 250 ms.
Removing the Prev / Next references removes 20% of the cost, and removing the Array as well reduce the cost by half.

```c#
class Program
{
struct Item
{
public Node Node;
}

class Node
{
    public Node Next, Prev;
    public Item[] Array;
}

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

    const int x = 4096;
    const int y = 8192;

    for (int i = 0; i < x; i++)
    {
        lattice.Add(new Item[y]);
    }

    for (int i = 0; i < x; i++)
    {
        var cur = new Node
        {
            Array = lattice[i]
        };
        lattice[i][0] = new Item { Node = cur };
        for (int j = 1; j < y; j += 2)
        {
            var next = new Node
            {
                Prev = cur,
                Array = lattice[i],
            };

            lattice[i][j] = new Item { Node = next };

            cur.Next = next;
            cur = next;
        }
    }

    for (int i = 0; i < 5; i++)
    {
        var sp = Stopwatch.StartNew();

        GC.Collect(2);

        System.Console.WriteLine(sp.ElapsedMilliseconds);
    }

    Console.ReadLine();
    GC.KeepAlive(lattice);

}

}
```

[janvorli]

cc: @Maoni0

[Maoni0]

@cshung could you please take a look?

[cshung]

I am taking a first look at the issue using the 2nd repro. First, I am able to reproduce the described latency, on my machine, it is around 300ms.

The profile indicates that these two functions are using most of the time (The time range to analyze is set to be the duration of GC.Collect.

| Name | Exc % | Exc | Inc % | Inc |
| --- | --- | --- | --- | --- |
| coreclr!WKS::gc_heap::mark_object_simple1 | 69.6 | 1,340 | 69.8 | 1,343 |
| coreclr!WKS::gc_heap::plan_phase | 25.0 | 482 | 25.5 | 491|

These functions do not call anything else, and together they spend 95.3% of the time.

Roughly speaking, the mark_object_simple1 function spend time proportional to the size of the object graph (i.e. the number of objects + number of references), and the plan_phase is spending time proportional to the number of objects.

You are creating approximately 4k x 8k = 32M objects, and the algorithm is processing them in 250ms. Therefore the speed is 32M/250m, which is approximately 0.1 objects per nanosecond.

That number looks like a very high speed to me. I am not sure how much more we could speed this up.

The garbage collector is obligated to manage the memory at the object level. With many objects, it is going to be slow. Is there a way to reduce the number of objects?

[Maoni0]

are you looking at the 2nd or the 1st case? I'm guessing the 2nd?

the 1st case sounds more interesting to me especially this:

Our observations is that while we are doing active work, we are seeing GC times that exceed 1 second at times (average of about 500 ms) and when there is no work at all, all threads are idle and only the GC is running, we are seeing > 250 ms for GC runs.

would be good to see what active work would cause GC to be so much longer? also is this using WKS or SVR GC?

[cshung]

@Maoni0, the analysis above is based on the 2nd repro.
For the 1st repro, the analysis is not as clear cut, but it is more or less than the same conclusion.

The repro code is measuring the time spent during GC.Collect(). These induced GC should not run concurrently with user code?

I tried to set the time range so that GC.Collect() is on the stack. The process is spending 22.5% of its time doing garbage collection, out of that, 19.3% of time is spent on coreclr!WKS::gc_heap::mark_object_simple1.

Again, we have the same problem of having too many objects.

One thing that catches my eyes is the abundance of Allocated too much during BGC, waiting for BGC to finish. This happens a lot.

[Maoni0]

The repro code is measuring the time spent during GC.Collect(). These induced GC should not run concurrently with user code?

it doesn't run concurrently with the managed threads in the same process; there can be native threads running in the same process; or threads from other processes can be running of course.

if it's WKS GC, it's just a normal priority thread so other threads could be affecting it, if it runs on the same core.

One thing that catches my eyes is the abundance of Allocated too much during BGC, waiting for BGC to finish. This happens a lot.

yes this is by design - for a test that just does allocation it's not surprising.

[ayende]

This is running on SVR GC, I believe that my test case here is basically doing nothing, and causing high GC because of the number of objects / references we see.

When we run it for real, we aren't running GC constantly but letting it run at its own pace. The server is loaded, so when we need to do a real GC run, it has real work to do. I think that the real work + the lattice structure I have here is causing it to stall for a very long time.

Note that this is something that we typically see after multiple weeks of running on a high load scenario, so it is hard to reproduce the 1+ sec stall times. In my tests, especially with the thread local, I did see some 1+ sec pause times, but they aren't consistent.

We have a proc dump (linux, 100+GB) of the real situation, and will be happy to provide any information from it you need.

[ayende]

I don't know if anything can be done with regards to the second case. I think that this is just a case where we put a lot of work on the GC.
But for the second case, with ThreadLocal is more concerning. The problem is that if you have lots of instances of that / lots of threads, you end up in this situation.

This can happen easily if you are running using ConcurrentBag to do something, which will end up causing slowdowns.

[cshung]

Running the first repro with server GC, here is a profile with the time range set to a particular induced GC.

Name | Exc % | Exc | Inc % | Inc
-- | -- | -- | -- | --
coreclr!SVR::gc_heap::mark_object_simple1 | 47.0 | 1,423 | 47.6 | 1,441
coreclr!SVR::gc_heap::relocate_address | 16.1 | 486 | 16.1 | 487
coreclr!SVR::gc_heap::relocate_in_large_objects | 14.3 | 433 | 21.1 | 639
coreclr!SVR::gc_heap::relocate_survivor_helper | 8.4 | 253 | 17.3 | 523
coreclr!SVR::gc_heap::plan_phase | 6.8 | 207 | 47.8 | 1,445.182

Nothing stands out in the trace related to the use of ThreadLocal. Taking a deeper look into what is actually happening in a debugger.

[cshung]

Using List<ThreadLocal<WeakReference>> seems to blow up the number of objects quite a bit.

Ignoring the objects like the List and the underlying array, the FinalizerHelper in ThreadLocal, and so on. These objects don't have a high count.

Assuming there are T threads and all threads have some thread-specific value.

A ThreadLocal<T> internally manages a linked list of slots for each value it manages. So ThreadLocal<T> translates into T objects.
Now each of them the T is a WeakReference, which is a class, so we have 2T values.
A WeakReference has a target, so we have 3T values.
Repeat this for L instances of ThreadLocal<WeakReference>, you have 3LT objects.

Looking into the ConcurrentBag<T>'s implementation, there is a single instance of ThreadLocal<WorkStealingQueue> is indeed used there. The application code might have created a list of ConcurrentBag<T>s.

ThreadLocal<T> implements IDisposable. The idea is that you can dispose of a ThreadLocal<T> instance and it will reclaim the thread static slot for others. Normally you expect only one thread to call Dispose(), but all the values for all threads should be available for garbage collection. It is for this reason why we needed to keep a linked list for all the slots so that we can null out the values. The ConcurrentBag<T> implementation never dispose of the ThreadLocal<WorkStealingQueue> it owns, so that level of bookkeeping is wasted. (And the slot is forever leaked)

After researching for a while already, I stumbled upon this paper, which basically validated what I just said.

When I search about ConcurrentBag<T> leak, I found this too.

At the end of the day, GC performance in your scenario is basically dictated by the number of objects. Reducing object count seems to be the way to go (it may be hard, I don't know ...)

The same scenario can probably be implemented with a ThreadStatic weak GCHandle array. GCHandle being a struct, you have only 1 thread static array with LT objects that you need.

[ayende]

We wrote a different impl of thread local, you can see it here:
https://github.com/ravendb/ravendb/blob/v4.2/src/Sparrow/Threading/LightWeightThreadLocal.cs

The idea here is to avoid the kind of lattice structure and help to deal with large number of ThreadLocal instances.

[cshung]

I am glad to share with this thread some numbers I achieved with my change for scenario 1.

https://github.com/dotnet/runtime/pull/31940#issuecomment-585365740

The GC latency reduced significantly.

@ayende, if you could take my patch and see if that improves your real scenario and report that, that would be great.

Here is my plan:

The last few CI failures are hard, I am looking for expert to help. Since you implemented your own ThreadLocal<T> as well, if you could figure out what gone wrong there, that would be great.

Next, I plan to wait for you to report back the result and see if my fix helped with your actual scenario.

If it helped with your actual scenario, and the CI failures are fixed, we will merge the PR, together with that, I will close this issue.

Is this plan good for you?

Since you were developing benchmarks, you might be interested in our performance repo. There we keep all the benchmark we cared about to keep them running fast. If you wanted to make sure your scenario stays fast too, you might consider contributing there.

[ayende]

This looks good to me.