Bug 28958 - On Android ARM only, the GC never collects "large objects" above a certain size?
Summary: On Android ARM only, the GC never collects "large objects" above a certain size?
Status: RESOLVED ANSWERED
Alias: None
Product: Android
Classification: Xamarin
Component: Mono runtime / AOT Compiler ()
Version: 5.1
Hardware: PC Mac OS
: --- normal
Target Milestone: ---
Assignee: Mark Probst
URL:
Depends on:
Blocks:
 
Reported: 2015-04-09 20:00 UTC by Brendan Zagaeski (Xamarin Team, assistant)
Modified: 2015-10-04 17:00 UTC (History)
2 users (show)

Tags:
Is this bug a regression?: ---
Last known good build:


Attachments
Test case (43.83 KB, application/zip)
2015-04-09 20:00 UTC, Brendan Zagaeski (Xamarin Team, assistant)
Details
GREF logcat output (85.50 KB, application/octet-stream)
2015-04-09 20:00 UTC, Brendan Zagaeski (Xamarin Team, assistant)
Details


Notice (2018-05-24): bugzilla.xamarin.com is now in read-only mode.

Please join us on Visual Studio Developer Community and in the Xamarin and Mono organizations on GitHub to continue tracking issues. Bugzilla will remain available for reference in read-only mode. We will continue to work on open Bugzilla bugs, copy them to the new locations as needed for follow-up, and add the new items under Related Links.

Our sincere thanks to everyone who has contributed on this bug tracker over the years. Thanks also for your understanding as we make these adjustments and improvements for the future.


Please create a new report on Developer Community or GitHub with your current version information, steps to reproduce, and relevant error messages or log files if you are hitting an issue that looks similar to this resolved bug and you do not yet see a matching new report.

Related Links:
Status:
RESOLVED ANSWERED

Description Brendan Zagaeski (Xamarin Team, assistant) 2015-04-09 20:00:01 UTC
Created attachment 10701 [details]
Test case

On Android ARM only, the GC never collects "large objects" above a certain size?


Regression status: Probably NOT a regression. The behavior is the same on XA 4.20.0-37 (9e05e39) and 5.1.0-100 (7402e0b).



## Steps to reproduce

1. Run the attached test case on a hardware Android armeabi-v7a device.

2. Tap the "Allocate Memory" button. This allocates 25 MB in a `byte[]`, and then assigns the `byte[]` back to `null`.

3. Tap the "Collect" button.

4. Repeat steps 3 and 4 at least 10 times.



## Results

The console log from the app shows that `GC.GetTotalMemory()` increases up to a plateau during the first several repetitions of steps 3 and 4.

### (armeabi-v7a device) Example output

> Total memory: 30505784
> Total memory: 56738656
> Total memory: 82953072
> Total memory: 82953072
> Total memory: 82953072
> Total memory: 82953072
> Total memory: 82953072
> Total memory: 82953072
> Total memory: 82953072


### The last few GC_MAJOR lines from the logcat output show that "los" is stuck at 75 MB

> D/Mono    ( 7584): GC_MAJOR: (user request) pause 2.96ms, total 6.32ms, bridge 47.73ms major 832K/832K los 76808K/102408K
> D/dalvikvm( 7584): WAIT_FOR_CONCURRENT_GC blocked 0ms
> D/dalvikvm( 7584): GC_EXPLICIT freed 0K, 34% free 8279K/12395K, paused 5ms+7ms, total 68ms
> D/Mono    ( 7584): GC_OLD_BRIDGE num-objects 5 num_hash_entries 8 sccs size 8 init 0.00ms df1 0.92ms sort 0.03ms dfs2 0.52ms setup-cb 0.00ms free-data 0.15ms links 5/5/5/1 dfs passes 18/13
> D/Mono    ( 7584): GC_MAJOR: (user request) pause 6.96ms, total 13.58ms, bridge 71.81ms major 832K/832K los 76808K/76808K


### (armeabi-v7a device) `log:heapshot` shows an extra `System.Byte[]` object created in Heap Shot 4 that never goes away

(Collected using the workaround from bug 28956, comment 2.)

> Heap shot 0 at 4.637 secs: size: 26312304, object count: 1632, class count: 141, roots: 0
>   26215168          7  3745024 System.Byte[]
> Heap shot 1 at 4.729 secs: size: 26312272, object count: 1630, class count: 140, roots: 0
>   26215168          7  3745024 System.Byte[] (bytes: +0, count: +0)
> Heap shot 2 at 5.449 secs: size: 52545176, object count: 1747, class count: 162, roots: 0
>   52437832         16  3277364 System.Byte[] (bytes: +26222664, count: +9)
> Heap shot 3 at 5.515 secs: size: 52545144, object count: 1745, class count: 161, roots: 0
>   52437832         16  3277364 System.Byte[] (bytes: +0, count: +0)
> Heap shot 4 at 6.240 secs: size: 78759592, object count: 1748, class count: 162, roots: 0
>   78652248         17  4626602 System.Byte[] (bytes: +26214416, count: +1)
> Heap shot 5 at 6.300 secs: size: 78759560, object count: 1746, class count: 161, roots: 0
>   78652248         17  4626602 System.Byte[] (bytes: +0, count: +0)
> Heap shot 6 at 6.986 secs: size: 78759592, object count: 1748, class count: 162, roots: 0
>   78652248         17  4626602 System.Byte[] (bytes: +0, count: +0)
> Heap shot 7 at 7.029 secs: size: 78759560, object count: 1746, class count: 161, roots: 0
>   78652248         17  4626602 System.Byte[] (bytes: +0, count: +0)
> Heap shot 8 at 7.708 secs: size: 78759592, object count: 1748, class count: 162, roots: 0
>   78652248         17  4626602 System.Byte[] (bytes: +0, count: +0)


### (ARM Google API 16 emulator) Example output

> Total memory: 30506432
> Total memory: 56739304
> Total memory: 82953720
> Total memory: 82953720
> Total memory: 109168136
> Total memory: 135382552
> Total memory: 135382552
> Total memory: 135382552
> Total memory: 135382552
> Total memory: 135382552


### (x86 Xamarin Android Player) Example output 

> Total memory: 4291712
> Total memory: 4331728
> Total memory: 4331728
> Total memory: 4331728
> Total memory: 4331728
> Total memory: 4331728
> Total memory: 4331728
> Total memory: 4331728
> Total memory: 4331728
> Total memory: 4331728


### (x86 Xamarin Android Player) `log:heapshot`

> Heap shot 0 at 2.335 secs: size: 97200, object count: 1615, class count: 140, roots: 0
>        752          6      125 System.Byte[]
> Heap shot 1 at 2.352 secs: size: 97200, object count: 1615, class count: 140, roots: 0
>        752          6      125 System.Byte[] (bytes: +0, count: +0)
> Heap shot 2 at 3.067 secs: size: 137216, object count: 2170, class count: 165, roots: 0
>       9024         15      601 System.Byte[] (bytes: +8272, count: +9)
> Heap shot 3 at 3.078 secs: size: 137216, object count: 2170, class count: 165, roots: 0
>       9024         15      601 System.Byte[] (bytes: +0, count: +0)
> Heap shot 4 at 3.756 secs: size: 137216, object count: 2170, class count: 165, roots: 0
>       9024         15      601 System.Byte[] (bytes: +0, count: +0)
> Heap shot 5 at 3.764 secs: size: 137216, object count: 2170, class count: 165, roots: 0
>       9024         15      601 System.Byte[] (bytes: +0, count: +0)
> Heap shot 6 at 4.370 secs: size: 137216, object count: 2170, class count: 165, roots: 0
>       9024         15      601 System.Byte[] (bytes: +0, count: +0)
> Heap shot 7 at 4.382 secs: size: 137216, object count: 2170, class count: 165, roots: 0
>       9024         15      601 System.Byte[] (bytes: +0, count: +0)
> Heap shot 8 at 4.972 secs: size: 137216, object count: 2170, class count: 165, roots: 0
>       9024         15      601 System.Byte[] (bytes: +0, count: +0)


### The last few GC_MAJOR lines from the logcat output show that "los" has been mostly cleared

> D/Mono    ( 3554): GC_MAJOR: (user request) pause 0.91ms, total 1.55ms, bridge 6.32ms major 864K/864K los 8K/25608K
> D/dalvikvm( 3554): GC_EXPLICIT freed 0K, 5% free 3200K/3360K, paused 0ms+1ms, total 5ms
> D/Mono    ( 3554): GC_OLD_BRIDGE num-objects 5 num_hash_entries 8 sccs size 8 init 0.00ms df1 0.05ms sort 0.00ms dfs2 0.18ms setup-cb 0.00ms free-data 0.04ms links 5/5/5/1 dfs passes 18/13
> D/Mono    ( 3554): GC_MAJOR: (user request) pause 1.51ms, total 2.14ms, bridge 7.95ms major 864K/864K los 8K/8K


### Results on iOS and Mac match the results on the Xamarin Android Player

The test case includes iOS and Mac apps with closely-matched logic. In my tests, both of those apps behaved like the Xamarin Android Player: the "los" is cleared after each GC.



## One way to change the behavior

If you decrease the value of `int size = 25 * 1024 * 1024`, for example to 1 MB, the problem no longer happens. Based on preliminary testing, it seems the threshold value might depend on the particular device.



## Version information

=== Xamarin Studio ===

Version 5.9 (build 388)
Installation UUID: 2c0ea975-8f73-4920-8414-3e9ae359fbf4
Runtime:
	Mono 4.0.0 ((detached/21d849b)
	GTK+ 2.24.23 (Raleigh theme)

	Package version: 400000121

=== Apple Developer Tools ===

Xcode 6.1.1 (6611)
Build 6A2008a

=== Xamarin.Mac ===

Version: 2.0.0.197 (Business Edition)

=== Xamarin.iOS ===

Version: 8.10.0.197 (Business Edition)
Hash: 4dac6bf
Branch: master
Build date: 2015-04-01 21:55:11-0400

=== Xamarin.Android ===

Version: 5.1.0.100 (Business Edition)
Android SDK: /Users/macuser/Library/Developer/Xamarin/android-sdk-macosx
	Supported Android versions:
		2.3    (API level 10)
		4.0.3  (API level 15)
		4.1    (API level 16)
		4.2    (API level 17)
		4.3    (API level 18)
		4.4    (API level 19)
		4.4.87 (API level 20)
		5.0    (API level 21)
Java SDK: /Users/macuser
java version "1.6.0_65"
Java(TM) SE Runtime Environment (build 1.6.0_65-b14-462-11M4609)
Java HotSpot(TM) 64-Bit Server VM (build 20.65-b04-462, mixed mode)

=== Xamarin Android Player ===

Version: Unknown version
Location: /Applications/Xamarin Android Player.app

=== Build Information ===

Release ID: 509000388
Git revision: 027c5efa6f92249fd2e614535965159c0a7c0fe6
Build date: 2015-04-01 19:12:53-04
Xamarin addins: a6779639267bbe31df3fd6958be4ecae82665b7e

=== Operating System ===

Mac OS X 10.9.5
Comment 1 Brendan Zagaeski (Xamarin Team, assistant) 2015-04-09 20:00:43 UTC
Created attachment 10702 [details]
GREF logcat output
Comment 3 Jonathan Pryor 2015-04-10 16:44:17 UTC
@Ben: Can you be more specific about your "armeabi-v7a device"? I tried this on a Nexus 5 and I don't observe this behavior.

This appears to be target-specific. :-(
Comment 4 Brendan Zagaeski (Xamarin Team, assistant) 2015-04-10 16:59:08 UTC
Ah yes, I should have listed my devices in the Version Information.

The hardware device I was able to reproduce on was an LG Optimus L9, Android 4.1.2, API 16.


I didn't test as extensively on the Google ARM API 16 emulator. But in case it's helpful, it seems to reproduce there too:


### (ARM Google API 16 emulator) Example debug output

> Total memory: 30508440
> [Mono] GC_OLD_BRIDGE num-objects 3 num_hash_entries 6 sccs size 6 init 0.00ms df1 0.51ms sort 0.02ms dfs2 0.70ms setup-cb 0.02ms free-data 0.08ms links 4/4/4/1 dfs passes 13/10
> [Mono] GC_MAJOR: (user request) pause 5.73ms, total 9.75ms, bridge 45.24ms major 688K/640K los 51200K/51200K
> [Mono] GC_OLD_BRIDGE num-objects 3 num_hash_entries 6 sccs size 6 init 0.00ms df1 1.34ms sort 0.02ms dfs2 0.75ms setup-cb 0.02ms free-data 0.08ms links 4/4/4/1 dfs passes 13/10
> [Mono] GC_MAJOR: (user request) pause 5.87ms, total 10.44ms, bridge 45.83ms major 688K/688K los 51200K/51200K
> Total memory: 56744680
> [Mono] GC_OLD_BRIDGE num-objects 3 num_hash_entries 6 sccs size 6 init 0.00ms df1 0.32ms sort 0.02ms dfs2 0.79ms setup-cb 0.02ms free-data 0.09ms links 4/4/4/1 dfs passes 13/10
> [Mono] GC_MAJOR: (user request) pause 3.75ms, total 14.56ms, bridge 104.51ms major 688K/688K los 76800K/76800K
> [Mono] GC_OLD_BRIDGE num-objects 3 num_hash_entries 6 sccs size 6 init 0.00ms df1 0.35ms sort 0.02ms dfs2 0.71ms setup-cb 0.02ms free-data 0.09ms links 4/4/4/1 dfs passes 13/10
> [Mono] GC_MAJOR: (user request) pause 5.76ms, total 9.75ms, bridge 46.34ms major 688K/688K los 76800K/76800K
> Total memory: 82959096
> [Mono] GC_OLD_BRIDGE num-objects 3 num_hash_entries 6 sccs size 6 init 0.00ms df1 0.33ms sort 0.02ms dfs2 0.68ms setup-cb 0.02ms free-data 0.09ms links 4/4/4/1 dfs passes 13/10
> [Mono] GC_MAJOR: (user request) pause 3.85ms, total 7.36ms, bridge 44.21ms major 688K/688K los 102400K/102400K
> [Mono] GC_OLD_BRIDGE num-objects 3 num_hash_entries 6 sccs size 6 init 0.00ms df1 0.33ms sort 0.02ms dfs2 0.71ms setup-cb 0.02ms free-data 0.09ms links 4/4/4/1 dfs passes 13/10
> [Mono] GC_MAJOR: (user request) pause 4.85ms, total 8.41ms, bridge 47.71ms major 688K/688K los 102400K/102400K
> Total memory: 109173512
> [Mono] GC_OLD_BRIDGE num-objects 3 num_hash_entries 6 sccs size 6 init 0.00ms df1 0.31ms sort 0.02ms dfs2 0.69ms setup-cb 0.02ms free-data 0.09ms links 4/4/4/1 dfs passes 13/10
> [Mono] GC_MAJOR: (user request) pause 3.84ms, total 7.41ms, bridge 44.89ms major 688K/688K los 128000K/128000K
> [Mono] GC_OLD_BRIDGE num-objects 3 num_hash_entries 6 sccs size 6 init 0.00ms df1 0.32ms sort 0.02ms dfs2 0.69ms setup-cb 0.02ms free-data 0.13ms links 4/4/4/1 dfs passes 13/10
> [Mono] GC_MAJOR: (user request) pause 5.65ms, total 9.98ms, bridge 44.43ms major 688K/688K los 128000K/128000K
> Total memory: 135387928
> [Mono] GC_OLD_BRIDGE num-objects 3 num_hash_entries 6 sccs size 6 init 0.00ms df1 0.40ms sort 0.02ms dfs2 0.72ms setup-cb 0.02ms free-data 0.09ms links 4/4/4/1 dfs passes 13/10
> [Mono] GC_MAJOR: (user request) pause 4.29ms, total 8.10ms, bridge 43.77ms major 688K/688K los 153600K/153600K
> [Mono] GC_OLD_BRIDGE num-objects 3 num_hash_entries 6 sccs size 6 init 0.00ms df1 0.35ms sort 0.03ms dfs2 0.70ms setup-cb 0.02ms free-data 0.08ms links 4/4/4/1 dfs passes 13/10
> [Mono] GC_MAJOR: (user request) pause 6.17ms, total 11.30ms, bridge 45.70ms major 688K/688K los 153600K/153600K
> Total memory: 161602344
> [Mono] GC_OLD_BRIDGE num-objects 3 num_hash_entries 6 sccs size 6 init 0.00ms df1 0.35ms sort 0.02ms dfs2 0.99ms setup-cb 0.02ms free-data 0.09ms links 4/4/4/1 dfs passes 13/10
> [Mono] GC_MAJOR: (user request) pause 4.12ms, total 7.74ms, bridge 123.54ms major 688K/688K los 153600K/179200K
> [Mono] GC_OLD_BRIDGE num-objects 3 num_hash_entries 6 sccs size 6 init 0.00ms df1 0.39ms sort 0.05ms dfs2 0.65ms setup-cb 0.02ms free-data 0.09ms links 4/4/4/1 dfs passes 13/10
> [Mono] GC_MAJOR: (user request) pause 10.80ms, total 24.74ms, bridge 61.66ms major 688K/688K los 153600K/153600K
> Total memory: 161602344
> [Mono] GC_OLD_BRIDGE num-objects 3 num_hash_entries 6 sccs size 6 init 0.00ms df1 0.39ms sort 0.02ms dfs2 0.70ms setup-cb 0.02ms free-data 0.09ms links 4/4/4/1 dfs passes 13/10
> [Mono] GC_MAJOR: (user request) pause 4.20ms, total 7.61ms, bridge 43.55ms major 688K/688K los 153600K/179200K
> [Mono] GC_OLD_BRIDGE num-objects 3 num_hash_entries 6 sccs size 6 init 0.00ms df1 0.32ms sort 0.04ms dfs2 1.54ms setup-cb 0.03ms free-data 0.17ms links 4/4/4/1 dfs passes 13/10
> [Mono] GC_MAJOR: (user request) pause 4.41ms, total 10.05ms, bridge 47.63ms major 688K/688K los 153600K/153600K
> Total memory: 161602344


## (ARM Google API 16 emulator) corresponding `log:heapshot` profiling

> Heap shot 0 at 5.005 secs: size: 26314432, object count: 1428, class count: 125, roots: 0
>   26214872          6  4369145 System.Byte[]
> Heap shot 1 at 5.084 secs: size: 26314432, object count: 1428, class count: 125, roots: 0
>   26214872          6  4369145 System.Byte[] (bytes: +0, count: +0)
> Heap shot 2 at 6.242 secs: size: 52550672, object count: 1529, class count: 145, roots: 0
>   52439928         15  3495995 System.Byte[] (bytes: +26225056, count: +9)
> Heap shot 3 at 6.299 secs: size: 52550672, object count: 1529, class count: 145, roots: 0
>   52439928         15  3495995 System.Byte[] (bytes: +0, count: +0)
> Heap shot 4 at 7.098 secs: size: 78765088, object count: 1530, class count: 145, roots: 0
>   78654344         16  4915896 System.Byte[] (bytes: +26214416, count: +1)
> Heap shot 5 at 7.221 secs: size: 78765088, object count: 1530, class count: 145, roots: 0
>   78654344         16  4915896 System.Byte[] (bytes: +0, count: +0)
> Heap shot 6 at 7.959 secs: size: 104979504, object count: 1531, class count: 145, roots: 0
>  104868760         17  6168750 System.Byte[] (bytes: +26214416, count: +1)
> Heap shot 7 at 8.019 secs: size: 104979504, object count: 1531, class count: 145, roots: 0
>  104868760         17  6168750 System.Byte[] (bytes: +0, count: +0)
> Heap shot 8 at 8.790 secs: size: 131193920, object count: 1532, class count: 145, roots: 0
>  131083176         18  7282398 System.Byte[] (bytes: +26214416, count: +1)
> Heap shot 9 at 8.845 secs: size: 131193920, object count: 1532, class count: 145, roots: 0
>  131083176         18  7282398 System.Byte[] (bytes: +0, count: +0)
> Heap shot 10 at 9.580 secs: size: 157408336, object count: 1533, class count: 145, roots: 0
>  157297592         19  8278820 System.Byte[] (bytes: +26214416, count: +1)
> Heap shot 11 at 9.636 secs: size: 157408336, object count: 1533, class count: 145, roots: 0
>  157297592         19  8278820 System.Byte[] (bytes: +0, count: +0)
> Heap shot 12 at 10.390 secs: size: 157408336, object count: 1533, class count: 145, roots: 0
>  157297592         19  8278820 System.Byte[] (bytes: +0, count: +0)
> Heap shot 13 at 10.530 secs: size: 157408336, object count: 1533, class count: 145, roots: 0
>  157297592         19  8278820 System.Byte[] (bytes: +0, count: +0)
> Heap shot 14 at 11.248 secs: size: 157408336, object count: 1533, class count: 145, roots: 0
>  157297592         19  8278820 System.Byte[] (bytes: +0, count: +0)
> Heap shot 15 at 11.302 secs: size: 157408336, object count: 1533, class count: 145, roots: 0
>  157297592         19  8278820 System.Byte[] (bytes: +0, count: +0)
Comment 5 Mark Probst 2015-05-11 20:28:47 UTC
This is false pinned, most likely from the stack.  It's reproducible on 32-bit desktop Mono, too, provided the arrays are big enough.  If I allocate 128M arrays I reliably get 5 or 6 of them pinned from the stack, so the heap never shrinks below 640+M.

The only way to properly fix this would be to implement precise stack scanning.
Comment 6 Brendan Zagaeski (Xamarin Team, assistant) 2015-05-11 21:45:29 UTC
Ah ha. Thanks! So a few quick follow-up questions:


1. If I'm understanding correctly, the memory that is false pinned by the stack behaves like any other pinned memory. So it could in principle contribute to an out-of-memory error. Correct?


2. If you managed the memory "by hand" completely outside of the garbage collector, that could be one way to work around the issue, yes? For example, if I replace the contents of the `Allocate()` method in the test case with the following, that seems to let me allocate and free memory without interacting with the GC at all:

> IntPtr mem = Marshal.AllocHGlobal(size);
> Marshal.FreeHGlobal(mem);
Comment 7 Mark Probst 2015-05-12 15:57:42 UTC
1. Correct.

2. Yes.  Of course you'll also have to manage its lifetime by hand.
Comment 8 Brendan Zagaeski (Xamarin Team, assistant) 2015-05-12 18:43:31 UTC
Excellent. Thanks again!