ChallengeThe loop that leaks–Answer
In my previous post, I asked about the following code and what its output will be:
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters. Learn more about bidirectional Unicode characters
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 the spoiler.
I attached to the running program in WinDBG and issued the following command:
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters. Learn more about bidirectional Unicode characters
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:
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters. Learn more about bidirectional Unicode characters
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?
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters. Learn more about bidirectional Unicode characters
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:
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters. Learn more about bidirectional Unicode characters
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).
More posts in "Challenge" series:
- (03 Feb 2025) Giving file system developer ulcer
- (20 Jan 2025) What does this code do?
- (01 Jul 2024) Efficient snapshotable state
- (13 Oct 2023) Fastest node selection metastable error state–answer
- (12 Oct 2023) Fastest node selection metastable error state
- (19 Sep 2023) Spot the bug
- (04 Jan 2023) what does this code print?
- (14 Dec 2022) What does this code print?
- (01 Jul 2022) Find the stack smash bug… – answer
- (30 Jun 2022) Find the stack smash bug…
- (03 Jun 2022) Spot the data corruption
- (06 May 2022) Spot the optimization–solution
- (05 May 2022) Spot the optimization
- (06 Apr 2022) Why is this code broken?
- (16 Dec 2021) Find the slow down–answer
- (15 Dec 2021) Find the slow down
- (03 Nov 2021) The code review bug that gives me nightmares–The fix
- (02 Nov 2021) The code review bug that gives me nightmares–the issue
- (01 Nov 2021) The code review bug that gives me nightmares
- (16 Jun 2021) Detecting livelihood in a distributed cluster
- (21 Apr 2020) Generate matching shard id–answer
- (20 Apr 2020) Generate matching shard id
- (02 Jan 2020) Spot the bug in the stream
- (28 Sep 2018) The loop that leaks–Answer
- (27 Sep 2018) The loop that leaks
- (03 Apr 2018) The invisible concurrency bug–Answer
- (02 Apr 2018) The invisible concurrency bug
- (31 Jan 2018) Find the bug in the fix–answer
- (30 Jan 2018) Find the bug in the fix
- (19 Jan 2017) What does this code do?
- (26 Jul 2016) The race condition in the TCP stack, answer
- (25 Jul 2016) The race condition in the TCP stack
- (28 Apr 2015) What is the meaning of this change?
- (26 Sep 2013) Spot the bug
- (27 May 2013) The problem of locking down tasks…
- (17 Oct 2011) Minimum number of round trips
- (23 Aug 2011) Recent Comments with Future Posts
- (02 Aug 2011) Modifying execution approaches
- (29 Apr 2011) Stop the leaks
- (23 Dec 2010) This code should never hit production
- (17 Dec 2010) Your own ThreadLocal
- (03 Dec 2010) Querying relative information with RavenDB
- (29 Jun 2010) Find the bug
- (23 Jun 2010) Dynamically dynamic
- (28 Apr 2010) What killed the application?
- (19 Mar 2010) What does this code do?
- (04 Mar 2010) Robust enumeration over external code
- (16 Feb 2010) Premature optimization, and all of that…
- (12 Feb 2010) Efficient querying
- (10 Feb 2010) Find the resource leak
- (21 Oct 2009) Can you spot the bug?
- (18 Oct 2009) Why is this wrong?
- (17 Oct 2009) Write the check in comment
- (15 Sep 2009) NH Prof Exporting Reports
- (02 Sep 2009) The lazy loaded inheritance many to one association OR/M conundrum
- (01 Sep 2009) Why isn’t select broken?
- (06 Aug 2009) Find the bug fixes
- (26 May 2009) Find the bug
- (14 May 2009) multi threaded test failure
- (11 May 2009) The regex that doesn’t match
- (24 Mar 2009) probability based selection
- (13 Mar 2009) C# Rewriting
- (18 Feb 2009) write a self extracting program
- (04 Sep 2008) Don't stop with the first DSL abstraction
- (02 Aug 2008) What is the problem?
- (28 Jul 2008) What does this code do?
- (26 Jul 2008) Find the bug fix
- (05 Jul 2008) Find the deadlock
- (03 Jul 2008) Find the bug
- (02 Jul 2008) What is wrong with this code
- (05 Jun 2008) why did the tests fail?
- (27 May 2008) Striving for better syntax
- (13 Apr 2008) calling generics without the generic type
- (12 Apr 2008) The directory tree
- (24 Mar 2008) Find the version
- (21 Jan 2008) Strongly typing weakly typed code
- (28 Jun 2007) Windsor Null Object Dependency Facility
Comments
I didn't realise from your previous post you were interested in debug mode vs release. Here is an updated version, forcing the large object to be released in debug mode: https://gist.github.com/slang25/39acdb0f404bad691e72f450d9266885
The JIT has a lot of trouble with local variables. Different ways of writing the same program by just adding or inlining local variables can make a difference. This is because the JIT is originally designed by people who don't know how to write a compiler. It does not use SSA form where locals easily fall away. It is based on statement trees and the JITs handling of those trees is pretty awful. They made a lot of hacks to compile common code patterns in an OK way.
LLVM uses a very clean SSA based IR for example.
People on the JIT team agree that the codebase has really nasty qualities. On the GitHub issue tracker there are many comments in the spirit of "oh well, here's another bug that's very hard to fix due to the nasty misdesign that took place 10 years ago".
@tobi: The JIT compiler has been rewritten with RyuJIT. I was under the impression that there things have been done right? The old x86 JIT compiler was a really nasty thing written by one really smart guy with no respect for software design. But it was and is still very fast ...
Comment preview