Challenge: The Loop That Leaks (Answer)
Let's explore the answer to yesterday's code ''riddle'' on the loop that leaks in this C# code snippet.
Join the DZone community and get the full member experience.
Join For FreeIn 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).
Published at DZone with permission of Oren Eini, DZone MVB. See the original article here.
Opinions expressed by DZone contributors are their own.
Comments