views:

185

answers:

3

Update: Microsoft have now reproduced the bug and are working on a fix.

Whilst evaluating the viability of the .NET platform for low latency software development, we have discovered a serious bug in the .NET 4 concurrent workstation garbage collector that can cause applications to hang for up to several minutes at a time.

On three of our machines the following simple C# program causes the GC to leak memory until none remains and a single mammoth GC cycle kicks in, stalling the program for several minutes (!) while 11Gb of heap is recycled:

    static void Main(string[] args)
    {
        var q = new System.Collections.Generic.Queue<System.Object>();
        while (true)
        {
            q.Enqueue(0);
            if (q.Count > 1000000)
                q.Dequeue();
        }
    }

You need to compile for x64 on a 64-bit Windows OS with .NET 4 and run with the default (concurrent workstation) GC using the default (interactive) latency setting.

Here's what the Task Manager looks like when running this program on this machine:

alt text

Note that 11Gb of heap have been leaked here when this program requires no more than 100Mb of memory.

We have now accumulated around a dozen repros of this bug, written in F# as well as C#, and it appears to be related to a bug in the GC write barrier when most of gen0 survives. However, Microsoft have not yet been able to reproduce it. Can you? If so, can you please describe your setup as accurately as possible so we can try to narrow down exactly what conditions are required for this bug to manifest.

+2  A: 

Running the code in linqpad indeed causes huge memory consumption if running as 64-bit; running as 32-bit works fine.

I've got a windows 7 x64 ultimate install (patched as usual) with 8GB of main memory; VS.NET and other dev tools are installed so there might be some weird debugger hooks which aren't present on an otherwise blank machine.

Odd that they haven't repro'd it. Are you sure there's not some communication breakdown there?

Oh, and using "new object()" rather than a boxed value type causes the same issue (unsurprisingly), so you might want to remove the confounding factor of boxing from your repro case.

Eamon Nerbonne
Thanks! "Are you sure there's not some communication breakdown there?" Perhaps. I've given the repro as a C# solution to someone else at MS to test. "you might want to remove the confounding factor." Good idea, will do.
Jon Harrop
+1  A: 

I blogged about this here and six more people so far, in addition to myself and Eamon, have confirmed that they can also reproduce this bug.

Moreover, Carsten and Michael Robin independently repeated my suspicion that the bug does not manifest immediately on every run but, rather, manifests at random and will sometimes appear after many tens of minutes of normal operation. In other words, the default .NET garbage collector is probabilistic and may cause outages lasting several minutes at random.

Jon Harrop
+1  A: 

I couldn't reproduce it. I tried it on a x64 with 4 gigs ram& compiled as ANY. The maximum memory usage was at around 2.5 gigs. The max GC pause time was around 1084 ms.

Here is the output from my GC ETW stats. alt text

You could also get GC Events by time alt text

Probably a similar trace output from your run could help in understanding what is happening under the covers.

In .NET 4.0 there is Event tracing for Windows (ETW) that provides Framework tracing information. Here is the one specific to GC.

And to get this information there is a tool from the BCL team which is called PerfMonitor

Here are the steps in using the tool to get the GC Information

  1. Start a cmd.exe as an admin , this required to collect ETW tracing
  2. Start the application that you want to trace
  3. Issue the command “PerfMonitor.exe /process:4180 start” where 4180 is the process id
  4. Let the app run for a while
  5. Then issue “PerfMonitor.exe stop”
  6. The command to get the report “PerfMonitor.exe GCTime”. This will generate a report and open it in the browser with GC stats.
Naveen
@Naveen: Thanks for the reference to `PerfMonitor`. According to that tool, the longest pause time is only 618ms here but closer inspection shows regular 18ms pauses every 60-130ms except for a massive 145s gap immediately prior to that longest 618ms GC pause. So my time was not lost to what `PerfMonitor` considers to be GC pause.
Jon Harrop
Maoni Stephens of Microsoft and author of this garbage collector says "It is a GC pause. PerfMonitor doesn’t intrepret enough info to recognize it.".
Jon Harrop
@Jon Thanks for the update from Maoni.
Naveen