Challenge: The Loop That Leaks (Answer)

In my previous post, I asked about the following code and what its output will be:

class Program
{
    static ManualResetEvent _produce = new ManualResetEvent(false);
    static ManualResetEvent _consume = new ManualResetEvent(false);
    private static void Run()
    {
        while (true)
        {
            _produce.WaitOne();
            _produce.Reset();

            var b = new byte[1024 * 1024 * 128];
            MD5.Create().ComputeHash(b);
            b = null;
            Console.WriteLine("Done");
            _consume.Set();
        }
    }

    static void Main(string[] args)
    {
        new Thread(Run)
        {
            IsBackground = true,
        }.Start();

        while (true)
        {
            _produce.Set();
            _consume.WaitOne();
            _consume.Reset();
            GC.Collect(2);
            GC.WaitForPendingFinalizers();
            Console.WriteLine(GC.GetTotalMemory(true));
            Console.ReadLine();
        }
    }
}

As it turns out, this code will output two different numbers:

• On Debug – 134,284,904
• On Release – 66,896

The behavior is consistent between these two modes.

I was pretty sure that I knew what was going on, but I asked to verify. You can read the GitHub issue if you want a spoiler.

I attached to the running program in WinDBG and issued the following command:

0:008> !dumpheap -stat
PDB symbol for clr.dll not loaded
Statistics:
              MT    Count    TotalSize Class Name
00007ffd2850a5b0        1           24 System.Collections.Generic.GenericEqualityComparer`1[[System.Int32, System.Private.CoreLib]]
00007ffd284f72a0        1           24 System.Collections.Generic.NonRandomizedStringEqualityComparer

// redacted

00007ffd284b41d8       18         1064 System.String[]
00007ffd284b6a10        6         2840 System.Char[]
00007ffd284b3878        6        17656 System.Object[]
00007ffd284cfba0      135        34874 System.String
000001f81abfe420       30        93806      Free
00007ffd284b6850        9    134221823 System.Byte[]
Total 347 objects

We care about the last line. In particular, we can see that all the memory is indeed in the byte array, as expected.

Next, let’s dump the actual instances that take so much space:

0:008> !DumpHeap /d -mt 00007ffd284b6850
         Address               MT     Size
000001f81c7521b8 00007ffd284b6850       40     
000001f81c7521e0 00007ffd284b6850       40     
000001f81c752408 00007ffd284b6850       27     
000001f81c752570 00007ffd284b6850       26     
000001f81c752590 00007ffd284b6850       26     
000001f81c752bc0 00007ffd284b6850     3608     
000001f81c7539d8 00007ffd284b6850       24     
000001f81c754290 00007ffd284b6850      280     
000001f8350a1020 00007ffd284b6850 134217752     

Statistics:
              MT    Count    TotalSize Class Name
00007ffd284b6850        9    134221823 System.Byte[]
Total 9 objects

There is one large instance here that we care about. Let’s see what is holding on to this fellow, shall we?

0:008> !gcroot 000001f8350a1020
Thread 2f30:
    00000011157ff150 00007ffcd94822c5 ConsoleApp18.Program.Run() [C:\Users\ayende\source\repos\ConsoleApp18\ConsoleApp18\Program.cs @ 15]
        rbp-28: 00000011157ff198
            ->  000001f8350a1020 System.Byte[]

Found 1 unique roots (run '!gcroot -all' to see all roots).

It looks like we have a reference from a local variable. Let’s see if we can verify that, shall we? We will use the clrstack command and ask it to give us the parameters and local variables, like so:

0:007> !clrstack -p -a
OS Thread Id: 0x2f30 (7)
        Child SP               IP Call Site
00000011157ff008 00007ffd8135aa44 [HelperMethodFrame_1OBJ: 00000011157ff008] System.Threading.WaitHandle.WaitOneNative(System.Runtime.InteropServices.SafeHandle, UInt32, Boolean, Boolean)
00000011157ff120 00007ffd2820715b System.Threading.WaitHandle.InternalWaitOne(System.Runtime.InteropServices.SafeHandle, Int64, Boolean, Boolean) [E:\A\_work\164\s\src\mscorlib\src\System\Threading\WaitHandle.cs @ 199]
    PARAMETERS:
        waitableSafeHandle = <no data>
        millisecondsTimeout = <no data>
        hasThreadAffinity = <no data>
        exitContext = <no data>
    LOCALS:
        <no data>

00000011157ff150 00007ffcd94822c5 ConsoleApp18.Program.Run() [C:\Users\ayende\source\repos\ConsoleApp18\ConsoleApp18\Program.cs @ 15]
    LOCALS:
        0x00000011157ff1b0 = 0x0000000000000000
        0x00000011157ff1ac = 0x0000000000000001

00000011157ff1d0 00007ffd76487080 System.Threading.Thread.ThreadMain_ThreadStart() [E:\A\_work\110\s\corefx\src\System.Threading.Thread\src\System\Threading\Thread.cs @ 93]
    PARAMETERS:
        this = <no data>
    LOCALS:
        <no data>

00000011157ff200 00007ffd280ecda9 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [E:\A\_work\164\s\src\mscorlib\shared\System\Threading\ExecutionContext.cs @ 167]
    PARAMETERS:
        executionContext = <no data>
        callback = <no data>
        state = <no data>
    LOCALS:
        <no data>
        0x00000011157ff248 = 0x000001f81c7510e0
        <no data>
        0x00000011157ff240 = 0x0000000000000000
        0x00000011157ff238 = 0x0000000000000000
        0x00000011157ff230 = 0x0000000000000000
        <no data>
        <no data>
        <no data>
        <no data>
        <no data>

00000011157ff468 00007ffd38f53ba3 [GCFrame: 00000011157ff468] 
00000011157ff6e0 00007ffd38f53ba3 [DebuggerU2MCatchHandlerFrame: 00000011157ff6e0] 

The interesting line is 16, which shows:

In other words, here is the local variable, and it is set to null. What is going on? And why don’t we see the same behavior on release mode?

As mentioned in the issue, the problem is that the JIT introduce a temporary local variable here, which the GC is obviously aware of, but WinDBG is not. This cause the program to hold on to the value for a longer period of time than expected.

In general, this should only be a problem if you have a long running loop. In fact, we do in some case, and in debug mode, that actually caused our memory utilization to go through the roof and led to this investigation.

In release mode, these temporary variables are rarer (but can still happen, it seems).