Notice (2018-05-24): bugzilla.xamarin.com is now in
Please join us on
Visual Studio Developer Community and in the
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
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.
Created attachment 11843 [details]
Customer has a hybrid app that logs using console.log and they persist those log through a custom WebChromeClient.
The behaviour can be reproduced by running the WebView app wizard and adding a WebChromeClient.
They have modified the button clicks handler to log to console.log. If you run this app, click the button (a couple of times) and use 'Cause GC' to update the stats you will see the numbers increase as well (in Android Device Monitor). It look like the ConsoleMessage objects that are created are not released.
=== Xamarin Studio ===
Version 5.9.4 (build 5)
Installation UUID: f8016946-f8ae-41ff-8a6e-6c3d1a711d07
Mono 4.0.2 ((detached/c99aa0c)
GTK+ 2.24.23 (Raleigh theme)
Package version: 400020005
=== Apple Developer Tools ===
Xcode 6.4 (7720)
=== Xamarin.iOS ===
Version: 18.104.22.168 (Business Edition)
Build date: 2015-06-22 21:28:32-0400
=== Xamarin.Android ===
Version: 22.214.171.124 (Business Edition)
Android SDK: /Users/prashantvc/Library/Developer/Xamarin/android-sdk-mac_x86
Supported Android versions:
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: /usr
java version "1.8.0_20"
Java(TM) SE Runtime Environment (build 1.8.0_20-b26)
Java HotSpot(TM) 64-Bit Server VM (build 25.20-b23, mixed mode)
=== Xamarin Android Player ===
Version: Unknown version
Location: /Applications/Xamarin Android Player.app
=== Xamarin.Mac ===
Version: 126.96.36.199 (Business Edition)
=== Build Information ===
Release ID: 509040005
Git revision: 8010a90f6e246b32364e3fb46ef2c9d1be9c9a2b
Build date: 2015-06-08 16:52:06-04
Xamarin addins: 7e93e9c3503f28770f23ce1b7eafd829919f18e8
=== Operating System ===
Mac OS X 10.10.4
Darwin Prashant-MBPr.local 14.4.0 Darwin Kernel Version 14.4.0
Thu May 28 11:35:04 PDT 2015
> It look like the ConsoleMessage objects that are created are not released.
This is expected: managed references to the ConsoleMessage instances won't be collected until a Mono-side GC occurs, and there is no code in the sample to call System.GC.Collect().
> The GC will run when the minor heap has run out of memory for new allocations.
> If there are no allocations, it will not run.
Created attachment 12088 [details]
chromium allocations keep growing
Created attachment 12089 [details]
webkit number of allocations stay fixed
Created attachment 12090 [details]
Updated proof of concept
My collegue who initially reported this is on holiday and I have been asked to take over. I'm under the impression that the 'android.webkit.ConsoleMessage' are not garbage collected in android versions >= 4.4 using Xamarin.Android 188.8.131.52 (Xamarin 3.11.666.0). This seems to only occur when an android version is used that uses chromium for rendering html pages in a webview (4.4 and up), 'webkit webviews' are not affected.
To demonstrate I changed the proof of concept program:
- Removed the razor view, the webview just serves Page.html straight from the assets
- Removed the special url handling behavior introduced by HybridWebViewClient
- Abitility to trigger a C# GC minor and major collection (by pressing a button)
For the updated source see the attachment.
Proof of concept scenario to repro issue:
On a 'chromium android device' (for testing purposes I used a 5.1.1 atom x86 emulator; 5.0 and 4.4.4 have the same behaviour):
1. Launch the app
2. Open Android Device Monitor and for 'WebViewApp.WebViewApp' enable 'update heap'
3. In allocation tracker click start tracking and for the filter type 'console'
4. In the app click 'Start Log Timer'
5. While the app is logging repeatedly press 'get allocations' in ADM you will notice the number of 'android.webkit.ConsoleMessage' grows quickly. See [511_ADM_allocations_keeps_growing.png] for an image of the list after rougly 1 minute of logging.
6. After a while press 'Stop Log Timer', the generation of ConsoleMessages when pressing get allocations should stop
7. Since these are peer objects causing a Java GC by pressing 'Cause GC' in ADM does not cause any of the objects to be removed. (expected)
8. Now in the app press 'Cause C# GC' to forcefully perform a gen0 and gen1 gc in mono.
9. Press 'get allocations' again: NONE of the ConsoleMessages are removed. Even triggering a Java side GC afterwards by pressing 'Cause GC' does not clear them.
On a 'webkit android device' (we used 4.0.4 x86 emulator)
When the scenario is followed at (5) you will notice the list of ConsoleMessage allocations stays fixed or only varies lightly in amount, see [404_ADM_allocations_stay_fixed.png].
Our real-world app uses console.log extensively to log events in the app. This 'bug' causes the app to slow down intensively. In about 20 minutes of normal usage the app gets so slow that it feels unresponsive; at the same time these messages appear in the log:
07-16 10:16:09.969: I/monodroid-gc(1896): 21407 outstanding GREFs. Performing a full GC!
07-16 10:16:10.199: I/monodroid-gc(1896): 21408 outstanding GREFs. Performing a full GC!
07-16 10:16:10.415: I/monodroid-gc(1896): 21409 outstanding GREFs. Performing a full GC!
07-16 10:16:10.627: I/monodroid-gc(1896): 21410 outstanding GREFs. Performing a full GC!
07-16 10:16:10.855: I/monodroid-gc(1896): 21411 outstanding GREFs. Performing a full GC!
07-16 10:16:11.071: I/monodroid-gc(1896): 21412 outstanding GREFs. Performing a full GC!
(Note how quickly they succeed eachother)
It doesnt matter what kind of actions are performed in the app, it slows down in any case. Whenever we stop logging using console.log() in js, memory usage stays consistent and the sluggyness does NOT happen. For this reason we think the sluggyness is caused by these ConsoleMessage objects filling up the device memory.
I hope this gives enough information for further investigation.
Thanks in advance
> Proof of concept scenario to repro issue:
> 9. Press 'get allocations' again: NONE of the ConsoleMessages are removed.
> Even triggering a Java side GC afterwards by pressing 'Cause GC' does not clear
Unfortunately, this isn't actually relevant. The Get Allocations button returns all allocations; it does *not* hide or remove any collected instances. Consequently, if you compare the Get Allocations output from two different times T1 and T2 where T2 > T1, T2 will *always* have at least as many allocations as were present in T1; the number WILL NOT DECREASE.
You're measuring the wrong thing.
Instead, you should measure via GREF logging. To enable GREF logging, set the debug.mono.log system property:
$ adb shell setprop debug.mono.log gref
When GREF logging is enabled, creation and destruction of every JNI Global Reference and Weak Global Reference will be tracked to `adb logcat` and to a `grefs.txt` file:
When I run your app with GREF logging enabled, I see the GREF count increase:
> monodroid-gref: +g+ grefc 16 gwrefc 0 obj-handle 0x20001d/L -> new-handle 0x1005c6/G from thread '(null)'(1)
A count of 16 is the initial "app ready" state.
Within the app, tap the Start Log Timer button, and the GREF count increases:
> monodroid-gref: +g+ grefc 17 gwrefc 0 obj-handle 0xbea8d590/L -> new-handle 0x612/G from thread '(null)'(1)
> monodroid-gref: +g+ grefc 76 gwrefc 0 obj-handle 0xbea8d590/L -> new-handle 0x1006fe/G from thread '(null)'(1)
Within the app, tap the Stop Log Timer button and tap the Cause C# GC button, and you'll see the GREF count decrease:
> monodroid-gref: +w+ grefc 76 gwrefc 1 obj-handle 0x100686/G -> new-handle 0x1006db/W from thread 'finalizer'(26506)
> monodroid-gref: -g- grefc 76 gwrefc 1 handle 0x100686/G from thread 'finalizer'(26506)
> monodroid-gref: -w- grefc 12 gwrefc 63 handle 0x1006db/W from thread 'finalizer'(26506)
> monodroid-gref: -w- grefc 17 gwrefc 0 handle 0x2007c7/W from thread 'finalizer'(26506)
The first three monodroid-gref fragments show that handle 0x100686 IS collected: the GREF becomes a weak GREF (+w+), the GREF is destroyed (-g-), and then the Weak GREF is destroyed (-w-) without a corresponding +g+.
By the end of the GC, we see that we're down to 17 GREFs, which is (close to) what we started with.
> at the same time these messages appear in the log:
> I/monodroid-gc(1896): 21407 outstanding GREFs. Performing a full GC!
That's very odd. Do you have the initial `adb logcat` output?
In particular, I'm looking for a message similar to:
> W/monodroid-gc: GREF GC Threshold: 46080
There are only two values printed for the GC Threshold: 1800 or something over 46000. (The high-end value changed with 5.1, as ART reduced the GREF limit.)
Note that 21407 is nowhere near either, AND that you're constantly getting that message.
What I suspect is happening is that our runtime thinks you're on an emulator, and the Android emulator has a hard limit of 2000 GREFs (and will abort the process if you exceed that limit), but your actual device supports the hardware limit of tens-of-thousands.
The result is that once your app has more than 1800 live concurrent GREFs, there will be constant GC's as we try to get lower than 1800, and these constant GCs will have a noticeable, negative, performance impact.
Please check for the "GREF GC Threshold" value. If this is the problem, there are only two "fixes" I can think of:
1. Find a better hardware device that doesn't report itself as an emulator.
2. Work on your app so that it doesn't require 21000+ GREFs be alive and uncollectable at the same time.
Because we have not received a reply to our request for more information we are closing this issue. If you are still encountering this issue, please reopen the ticket with the requested information. Thanks!