ChallengeThe loop that leaks–Answer

time to read 2 min | 328 words

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();
}
}
}
view raw mem.cs hosted with ❤ by GitHub

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 the 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
view raw heap.txt hosted with ❤ by GitHub

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
view raw arrays.txt hosted with ❤ by GitHub

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).
view raw gcroot.txt hosted with ❤ by GitHub

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]
view raw clrstack.txt hosted with ❤ by GitHub

The interesting line is 16, which shows:

image

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).

More posts in "Challenge" series:

  1. (03 Feb 2025) Giving file system developer ulcer
  2. (20 Jan 2025) What does this code do?
  3. (01 Jul 2024) Efficient snapshotable state
  4. (13 Oct 2023) Fastest node selection metastable error state–answer
  5. (12 Oct 2023) Fastest node selection metastable error state
  6. (19 Sep 2023) Spot the bug
  7. (04 Jan 2023) what does this code print?
  8. (14 Dec 2022) What does this code print?
  9. (01 Jul 2022) Find the stack smash bug… – answer
  10. (30 Jun 2022) Find the stack smash bug…
  11. (03 Jun 2022) Spot the data corruption
  12. (06 May 2022) Spot the optimization–solution
  13. (05 May 2022) Spot the optimization
  14. (06 Apr 2022) Why is this code broken?
  15. (16 Dec 2021) Find the slow down–answer
  16. (15 Dec 2021) Find the slow down
  17. (03 Nov 2021) The code review bug that gives me nightmares–The fix
  18. (02 Nov 2021) The code review bug that gives me nightmares–the issue
  19. (01 Nov 2021) The code review bug that gives me nightmares
  20. (16 Jun 2021) Detecting livelihood in a distributed cluster
  21. (21 Apr 2020) Generate matching shard id–answer
  22. (20 Apr 2020) Generate matching shard id
  23. (02 Jan 2020) Spot the bug in the stream
  24. (28 Sep 2018) The loop that leaks–Answer
  25. (27 Sep 2018) The loop that leaks
  26. (03 Apr 2018) The invisible concurrency bug–Answer
  27. (02 Apr 2018) The invisible concurrency bug
  28. (31 Jan 2018) Find the bug in the fix–answer
  29. (30 Jan 2018) Find the bug in the fix
  30. (19 Jan 2017) What does this code do?
  31. (26 Jul 2016) The race condition in the TCP stack, answer
  32. (25 Jul 2016) The race condition in the TCP stack
  33. (28 Apr 2015) What is the meaning of this change?
  34. (26 Sep 2013) Spot the bug
  35. (27 May 2013) The problem of locking down tasks…
  36. (17 Oct 2011) Minimum number of round trips
  37. (23 Aug 2011) Recent Comments with Future Posts
  38. (02 Aug 2011) Modifying execution approaches
  39. (29 Apr 2011) Stop the leaks
  40. (23 Dec 2010) This code should never hit production
  41. (17 Dec 2010) Your own ThreadLocal
  42. (03 Dec 2010) Querying relative information with RavenDB
  43. (29 Jun 2010) Find the bug
  44. (23 Jun 2010) Dynamically dynamic
  45. (28 Apr 2010) What killed the application?
  46. (19 Mar 2010) What does this code do?
  47. (04 Mar 2010) Robust enumeration over external code
  48. (16 Feb 2010) Premature optimization, and all of that…
  49. (12 Feb 2010) Efficient querying
  50. (10 Feb 2010) Find the resource leak
  51. (21 Oct 2009) Can you spot the bug?
  52. (18 Oct 2009) Why is this wrong?
  53. (17 Oct 2009) Write the check in comment
  54. (15 Sep 2009) NH Prof Exporting Reports
  55. (02 Sep 2009) The lazy loaded inheritance many to one association OR/M conundrum
  56. (01 Sep 2009) Why isn’t select broken?
  57. (06 Aug 2009) Find the bug fixes
  58. (26 May 2009) Find the bug
  59. (14 May 2009) multi threaded test failure
  60. (11 May 2009) The regex that doesn’t match
  61. (24 Mar 2009) probability based selection
  62. (13 Mar 2009) C# Rewriting
  63. (18 Feb 2009) write a self extracting program
  64. (04 Sep 2008) Don't stop with the first DSL abstraction
  65. (02 Aug 2008) What is the problem?
  66. (28 Jul 2008) What does this code do?
  67. (26 Jul 2008) Find the bug fix
  68. (05 Jul 2008) Find the deadlock
  69. (03 Jul 2008) Find the bug
  70. (02 Jul 2008) What is wrong with this code
  71. (05 Jun 2008) why did the tests fail?
  72. (27 May 2008) Striving for better syntax
  73. (13 Apr 2008) calling generics without the generic type
  74. (12 Apr 2008) The directory tree
  75. (24 Mar 2008) Find the version
  76. (21 Jan 2008) Strongly typing weakly typed code
  77. (28 Jun 2007) Windsor Null Object Dependency Facility