GC is forced when working with small images (<=4k pixel data)?
Asked Answered
S

4

16

I'm seeing the performance counter "# Induced GC" (which should stay at zero in a perfect app) increasing rapidly when processing small files (<= 32x32) via WriteableBitmap.

While this isn't a significant bottleneck inside a small app, it becomes a very huge problem (app freezing at 99.75% "% Time in GC" for several seconds at each step) when there exist some thousand objects in memory (ex: EntityFramework context loaded with many entities and relationships).

Synthetic test:

var objectCountPressure = (
    from x in Enumerable.Range(65, 26)
    let root = new DirectoryInfo((char)x + ":\\")
    let subs = 
        from y in Enumerable.Range(0, 100 * IntPtr.Size)
        let sub =new {DI = new DirectoryInfo(Path.Combine(root.FullName, "sub" + y)), Parent = root}
        let files = from z in Enumerable.Range(0, 400) select new {FI = new FileInfo(Path.Combine(sub.DI.FullName, "file" + z)), Parent = sub}
        select new {sub, files = files.ToList()}
    select new {root, subs = subs.ToList()}
    ).ToList();

const int Size = 32;
Action<int> handler = threadnr => {
    Console.WriteLine(threadnr + " => " + Thread.CurrentThread.ManagedThreadId);
    for (int i = 0; i < 10000; i++)    {
        var wb = new WriteableBitmap(Size, Size, 96, 96, PixelFormats.Bgra32, null);
        wb.Lock();
        var stride = wb.BackBufferStride;
        var blocks = stride / sizeof(int);
        unsafe {
            var row = (byte*)wb.BackBuffer;
            for (int y = 0; y < wb.PixelHeight; y++, row += stride)
            {
                var start = (int*)row;
                for (int x = 0; x < blocks; x++, start++)
                    *start = i;
            }
        }
        wb.Unlock();
        wb.Freeze();     }
};
var sw = Stopwatch.StartNew();
Console.WriteLine("start: {0:n3} ms", sw.Elapsed.TotalMilliseconds);
Parallel.For(0, Environment.ProcessorCount, new ParallelOptions{MaxDegreeOfParallelism = Environment.ProcessorCount}, handler);
Console.WriteLine("stop : {0:n2} s", sw.Elapsed.TotalSeconds);

GC.KeepAlive(objectCountPressure);

I can run this test using "const int Size = 48" a dozen times: It always returns in ~1.5s and "# Induced GC" sometimes increases by 1 or 2.

When I change "const int Size = 48" into "const int Size = 32" then something very very bad is happening: "# Induced GC" increases by 10 per second and the overall runtime now is more than a minute: ~80s ! [Tested on Win7x64 Core-i7-2600 with 8GB RAM // .NET 4.0.30319.237 ]

WTF!?

Either the Framework has a very bad bug or I'm doing something entirely wrong.

BTW:
I came around this problem not by doing image processing but by just using a Tooltip containing an Image against some database entities via a DataTemplate: This worked fine (fast) while there didn't exist very much objects in RAM -- but when there existed some million other objects (totally unrelated) then showing the Tooltip always delayed for several seconds, while everything else just was working fine.

Shamanism answered 7/9, 2011 at 9:41 Comment(11)
The amount of memory allocated even for the "good" sizes is much(factor 10 or so) higher than what one would expect from 4*width*heightGalligan
using Reflector on WritableBitmap.GetEstimatedSize it is return (long) ((((pixelWidth * pixelHeight) * pixelFormat.InternalBitsPerPixel) / 8) * 2); -> so it is exactly 0x2000 (8kb) for 32x32. Further down the chain the ctor of SafeMILHandleMemoryPressure decides to do something different at > 0x2000 -- below or equal to 0x2000 it always calls GC.AddMemoryPressure(long) which always seems to trigger a GC.Collect(2); even if it's happening a thousand times per second.Shamanism
I suspect that under certain circumstances they forget to pair their GC.AddMemoryPressure call with a GC.RemoveMemoryPressure. Thus the memory pressure continues to rise and once it exceeds a certain level every call to AddMemoryPressure triggers a full GC.Galligan
Interesting, when I run in LinqPad the effect is much larger than when running a normal version of the program.Galligan
The same thing (doing many many GC collections) is not caused by the memory pressure. You can skip the pressure (remove objectCountPressure at all) and you will still see the same amount of collections -- the only difference is that these collections won't take up time cause GC.Collect(2) then returns in parts of milliseconds instead locking up everything for half a second or longer.Shamanism
These frequent GCs only happen if you have the Freeze call in there. Thus I suspect that freeze either allocates a lot of managed memory, or forgets manages to leak a AddMemoryPressure call(i.e. it misses the paired RemoveMemoryPressure call. And if those don't match up bad things happen.Galligan
In can't imagine this being 'by design'. It has to be a bug. I think reporting this to MS-CONNECT is a good thing to do.Chelicera
That commenting out Freeze helps seems to be coincidence. Interestingly the number of concurrent threads has a huge influence on the number of collections. Perhaps the memory held by one thread causes GCs triggered by other threads to be promoted and thus causes higher generation GCs.Galligan
The number of gen0 GCs is very high too. About every 5th iteration causes one.Galligan
@springy76: did you ever find a proper solution to this issue?Memoried
@Dunken: Before Jasons answer https://mcmap.net/q/371926/-gc-is-forced-when-working-with-small-images-lt-4k-pixel-data I used a thread which allocates a small image every 500ms so the 850ms timer was never triggered. Starting with .NET 4.6.2 this problem is entirely gone.Shamanism
F
8

Under all of the SafeMILHandleMemoryPressure and SafeMILHandle nonsense is a call to a method on MS.Internal.MemoryPressure, which uses the static field "_totalMemory" to keep track of how much memory WPF thinks is allocated. When it hits a (rather small) limit, the induced GCs start and never end.

You can stop WPF from behaving this way entirely using a little reflection magic; just set _totalMemory to something appropriately negative so the limit is never reached and the induced GCs never happen:

typeof(BitmapImage).Assembly.GetType("MS.Internal.MemoryPressure")
    .GetField("_totalMemory", BindingFlags.NonPublic | BindingFlags.Static)
    .SetValue(null, Int64.MinValue / 2);
Fizz answered 22/5, 2012 at 3:36 Comment(4)
While I commonly don't like string based reflection work -- especially on private members -- I definitely will give that one a try.Shamanism
Gladfully 5 years later starting with .net 4.6.2 Microsoft removed this bullshit MemoryPressure class entirely so now there are no forced garbage collections any more and this hack isn't needed any more.Shamanism
Could this have any dangerous side-effects? Why are the induced GCs there?Lorrainelorrayne
I'm surprised this is still relevant, but a company I worked for relied quite heavily on this in a production environment for months before I left, and I assume they continued using it after I had left. Our assumption was that it was just a rookie mistake by some intern or something.Fizz
B
13

TL;DR: Probably the best solution would be to create a small pool of WriteableBitmaps and reuse them rather than creating them and throwing them away.

So I started spelunking around with WinDbg to see what was causing the collections to happen.

First I added a call to Debugger.Break() to the start of Main to make things easier. I also added my own call to GC.Collect() as a sanity check to make sure my breakpoint worked ok. Then in WinDbg:

0:000> .loadby sos clr
0:000> !bpmd mscorlib.dll System.GC.Collect
Found 3 methods in module 000007feee811000...
MethodDesc = 000007feee896cb0
Setting breakpoint: bp 000007FEEF20E0C0 [System.GC.Collect(Int32)]
MethodDesc = 000007feee896cc0
Setting breakpoint: bp 000007FEEF20DDD0 [System.GC.Collect()]
MethodDesc = 000007feee896cd0
Setting breakpoint: bp 000007FEEEB74A80 [System.GC.Collect(Int32, System.GCCollectionMode)]
Adding pending breakpoints...
0:000> g
Breakpoint 1 hit
mscorlib_ni+0x9fddd0:
000007fe`ef20ddd0 4154            push    r12
0:000> !clrstack
OS Thread Id: 0x49c (0)
Child SP         IP               Call Site
000000000014ed58 000007feef20ddd0 System.GC.Collect()
000000000014ed60 000007ff00140388 ConsoleApplication1.Program.Main(System.String[])

So the breakpoint worked OK, but when I let the program continue it was never hit again. It seemed the GC routine was being called from somewhere deeper. Next I stepped into the GC.Collect() function to see what it was calling. To do this more easily I added a second call to GC.Collect() immediately after the first and stepped into the second one. This avoided stepping through all the JIT compilation:

Breakpoint 1 hit
mscorlib_ni+0x9fddd0:
000007fe`ef20ddd0 4154            push    r12
0:000> p
mscorlib_ni+0x9fddd2:
000007fe`ef20ddd2 4155            push    r13
0:000> p
...
0:000> p
mscorlib_ni+0x9fde00:
000007fe`ef20de00 4c8b1d990b61ff  mov     r11,qword ptr [mscorlib_ni+0xe9a0 (000007fe`ee81e9a0)] ds:000007fe`ee81e9a0={clr!GCInterface::Collect (000007fe`eb976100)}

After a little stepping I noticed a reference to clr!GCInterface::Collect which sounded promising. Unfortunately a breakpoint on it never triggered. Digging further into GC.Collect() I found clr!WKS::GCHeap::GarbageCollect which proved to be the real method. A breakpoint on this revealed the code that was triggering the collection:

0:009> bp clr!WKS::GCHeap::GarbageCollect
0:009> g
Breakpoint 4 hit
clr!WKS::GCHeap::GarbageCollect:
000007fe`eb919490 488bc4          mov     rax,rsp
0:006> !clrstack
OS Thread Id: 0x954 (6)
Child SP         IP               Call Site
0000000000e4e708 000007feeb919490 [NDirectMethodFrameStandalone: 0000000000e4e708] System.GC._AddMemoryPressure(UInt64)
0000000000e4e6d0 000007feeeb9d4f7 System.GC.AddMemoryPressure(Int64)
0000000000e4e7a0 000007fee9259a4e System.Windows.Media.SafeMILHandle.UpdateEstimatedSize(Int64)
0000000000e4e7e0 000007fee9997b97 System.Windows.Media.Imaging.WriteableBitmap..ctor(Int32, Int32, Double, Double, System.Windows.Media.PixelFormat, System.Windows.Media.Imaging.BitmapPalette)
0000000000e4e8e0 000007ff00141f92 ConsoleApplication1.Program.<Main>b__c(Int32)

So WriteableBitmap's constructor indirectly calls GC.AddMemoryPressure, which eventually results in collections (incidentally, GC.AddMemoryPressure is an easier way to simulate memory usage). This doesn't explain the sudden change in behaviour when going from a size of 33 to 32 though.

ILSpy helps out here. In particular, if you look at the constructor for SafeMILHandleMemoryPressure (invoked by SafeMILHandle.UpdateEstimatedSize) you'll see that it only uses GC.AddMemoryPressure if the pressure to add is <= 8192. Otherwise it uses its own custom system for tracking memory pressure and triggering collections. A bitmap size of 32x32 with 32-bit pixels falls under this limit because WriteableBitmap estimates the memory use as 32 * 32 * 4 * 2 (I'm not sure why the extra factor of 2 is there).

In summary, it looks like the behaviour you're seeing is the result of a heuristic in the framework that doesn't work so well for your case. You might be able to work around it by creating a bitmap with bigger dimensions or a bigger pixel format than you need so that the estimated memory size of the bitmap is > 8192.

Afterthought: I guess this also suggests that collections triggered as a result of GC.AddMemoryPressure are counted under "# Induced GC"?

Bruit answered 7/9, 2011 at 13:55 Comment(10)
I noticed this 8192 switch when I commented @CodeInChaos -- but why is GC.AddMemoryPressure always doing a GC.Collect(2)? When I'm on 64-bit using approx. 1.5-2 GB of RAM (where 8 GB are available and 7 of them unused) then even loading a fairly sized image (640x480) gets delayed by several seconds because GC.Collect(2) is analyzing my objects graph containing thousands or millions of objects for just no reason. My application is running fine (allocating much more RAM) if I don't do anything image related. Can you confirm this is some kind of bug which should be posted to MS-CONNECT?Shamanism
Can you count how often AddMemoryPressure gets called compared to how often RemoveMemoryPressure gets called?Galligan
You're right, AddMemoryPressure seems to be triggering full collections regardless of how much memory is used. Raising the issue with MS sounds like a good idea.Bruit
I just tested this inside LINQPad: var ctr = 0; while(true) { GC.AddMemoryPressure(8192); if (++ctr % 163840 == 0) Console.WriteLine(ctr); } after 1 second the induced GC counter jumped to 150 but then slowly increased 2-3 per second. I stopped after 5 seconds and the last output line says "332595200" -- that's far away from 1 full collection per AddMemoryPressure call.Shamanism
In my tests the original program triggers only about 100 collections total. This does mean that only every few hundredth iteration triggers a GC.Galligan
Sorry, yeah scratch my last comment. GCs aren't triggered on every call to AddMemoryPressure, although they do occur quite frequently. RemoveMemoryPressure is called in the finalizer of SafeMILHandle so I don't think there's a problem there. Memory (pressure) builds up, GC triggered, finalizers called, memory pressure decreases, rinse, repeat. I think everything's working as designed. GCs are happening more than might be expected, but that's an implementation detail of the GC ;). Still worth reporting your original case to MS though I think.Bruit
Actually, considering this again I think the garbage collection really is working as normal. What's abnormal is the behaviour for larger bitmaps, where the GC is sneakily suppressed. Probably the best solution would be to create a small pool of WriteableBitmaps and reuse them rather than creating them and throwing them away.Bruit
I don't think calling GC.Collect(2) (we've been told often enough not to call GC.Collect() ourselves) just because someone allocated native memory (which we can't collect anyway) could or should be considered "working as normal".Shamanism
Well it doesn't look like the library is calling GC.Collect at all for small bitmaps. It just calls the Add/RemoveMemoryPressure methods and leaves the rest to the GC itself.Galligan
The most annoying fact about this problem is: Given a simple application -- Listbox with files plus ImageControl showing the selected file (all > 4kb Pixeldata) : Selecting a file and waiting a second before selecting next file does a full GC between each file. But if I select 2 or 3 files per second then only one GC happens for the first file and then no more GC occurs until I pause again. I really consider creating a background thread which just keeps WriteableBitmap busy all the time (a bad hack but since Microsoft says "by design" then I'm forced to workaround this shitty design).Shamanism
F
8

Under all of the SafeMILHandleMemoryPressure and SafeMILHandle nonsense is a call to a method on MS.Internal.MemoryPressure, which uses the static field "_totalMemory" to keep track of how much memory WPF thinks is allocated. When it hits a (rather small) limit, the induced GCs start and never end.

You can stop WPF from behaving this way entirely using a little reflection magic; just set _totalMemory to something appropriately negative so the limit is never reached and the induced GCs never happen:

typeof(BitmapImage).Assembly.GetType("MS.Internal.MemoryPressure")
    .GetField("_totalMemory", BindingFlags.NonPublic | BindingFlags.Static)
    .SetValue(null, Int64.MinValue / 2);
Fizz answered 22/5, 2012 at 3:36 Comment(4)
While I commonly don't like string based reflection work -- especially on private members -- I definitely will give that one a try.Shamanism
Gladfully 5 years later starting with .net 4.6.2 Microsoft removed this bullshit MemoryPressure class entirely so now there are no forced garbage collections any more and this hack isn't needed any more.Shamanism
Could this have any dangerous side-effects? Why are the induced GCs there?Lorrainelorrayne
I'm surprised this is still relevant, but a company I worked for relied quite heavily on this in a production environment for months before I left, and I assume they continued using it after I had left. Our assumption was that it was just a rookie mistake by some intern or something.Fizz
M
1

Running Markus' code on Win7 x86 (T4300, 2.1GHz, 3GB):
(notice the huge difference between 33 and 32)

Is64BitOperatingSystem: False
Is64BitProcess: False
Version: 4.0.30319.237

Running Test with 40: 3,20 s
Running Test with 34: 1,14 s
Running Test with 33: 1,06 s
Running Test with 32: 64,41 s

Running Test with 30: 53,32 s
Running Test with 24: 29,01 s

Another machine Win7 x64 (Q9550, 2.8GHz, 8GB):

Is64BitOperatingSystem: True
Is64BitProcess: False
Version: 4.0.30319.237

Running Test with 40: 1,41 s
Running Test with 34: 1,24 s
Running Test with 33: 1,19 s
Running Test with 32: 1.554,45 s

Running Test with 30: 1.489,31 s
Running Test with 24: 842,66 s
Once again with 40: 7,21 s

The Q9550 CPU has a lot more power than the T4300, but it's running on 64bit OS.
This seems to slow down the whole thing.

Monolith answered 7/9, 2011 at 10:17 Comment(7)
@Steven: you're right - but formatting comments is nearly impossible ;-)Monolith
I'm wondering what the numbers are when running this on .NET 2.0.Chelicera
It took some of your tests half an hour to complete? wtfGalligan
@Sascha: What is the relationship between the OP's problem and Tasks?Chelicera
@Steven: He's using Parallel.For - it's located in System.Threading.TasksMonolith
Ahh.. I see. Wouldn't be to hard to rewrite it though :-)Chelicera
For .NET 2 you can replace Action<int> handler with ParameterizedThreadStart handler and the line containing Parallel.For with var threads = Enumerable.Range(1, Environment.ProcessorCount).Select(i => new Thread(handler)).ToList(); for (int i = 0; i < threads.Count; i++) threads[i].Start(i); foreach(var thread in threads) thread.Join(); -- then it should work there, too.Shamanism
F
0

Try this simple workaround:

Call GC.AddMemoryPressure(128 * 1024) once, this will numb the memory pressure mechanism.

If it's not numb enough, give a bigger number.

Floris answered 20/7, 2012 at 16:48 Comment(0)

© 2022 - 2024 — McMap. All rights reserved.