Bug 31621 - WebChromeClient leaks the memory when logs are enabled
Summary: WebChromeClient leaks the memory when logs are enabled
Status: RESOLVED NORESPONSE
Alias: None
Product: Android
Classification: Xamarin
Component: General ()
Version: 5.1
Hardware: PC Mac OS
: High normal
Target Milestone: ---
Assignee: Jonathan Pryor
URL:
Depends on:
Blocks:
 
Reported: 2015-07-03 07:27 UTC by Prashant Cholachagudda
Modified: 2017-09-19 15:54 UTC (History)
4 users (show)

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


Attachments
Testcase (25.55 KB, application/zip)
2015-07-03 07:27 UTC, Prashant Cholachagudda
Details
chromium allocations keep growing (97.61 KB, image/png)
2015-07-17 10:24 UTC, LNieuwmegen
Details
webkit number of allocations stay fixed (51.04 KB, image/png)
2015-07-17 10:24 UTC, LNieuwmegen
Details
Updated proof of concept (18.21 KB, application/force-download)
2015-07-17 10:25 UTC, LNieuwmegen
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 NORESPONSE

Description Prashant Cholachagudda 2015-07-03 07:27:45 UTC
Created attachment 11843 [details]
Testcase

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.

#Version information

=== Xamarin Studio ===

Version 5.9.4 (build 5)
Installation UUID: f8016946-f8ae-41ff-8a6e-6c3d1a711d07
Runtime:
	Mono 4.0.2 ((detached/c99aa0c)
	GTK+ 2.24.23 (Raleigh theme)

	Package version: 400020005

=== Apple Developer Tools ===

Xcode 6.4 (7720)
Build 6E35b

=== Xamarin.iOS ===

Version: 8.10.2.37 (Business Edition)
Hash: ef8c2f7
Branch: master
Build date: 2015-06-22 21:28:32-0400

=== Xamarin.Android ===

Version: 5.1.4.16 (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: 2.0.2.35 (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
    root:xnu-2782.30.5~1/RELEASE_X86_64 x86_64
Comment 1 Jonathan Pryor 2015-07-08 14:57:45 UTC
> 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().

http://developer.xamarin.com/guides/android/advanced_topics/garbage_collection/

> 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.
Comment 2 LNieuwmegen 2015-07-17 10:24:04 UTC
Created attachment 12088 [details]
chromium allocations keep growing
Comment 3 LNieuwmegen 2015-07-17 10:24:35 UTC
Created attachment 12089 [details]
webkit number of allocations stay fixed
Comment 4 LNieuwmegen 2015-07-17 10:25:06 UTC
Created attachment 12090 [details]
Updated proof of concept
Comment 5 LNieuwmegen 2015-07-17 10:28:17 UTC
Hi,

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 5.1.4.16 (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:
Cleanup:
	- Removed the razor view, the webview just serves Page.html straight from the assets
	- Removed the special url handling behavior introduced by HybridWebViewClient
	
Additions
	- Timer that logs console messages from javascript every second (can be started and stopped by two buttons)
	- 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].
	
Real app
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
Comment 7 Jonathan Pryor 2015-07-28 15:32:59 UTC
> 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
> them.

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:

http://developer.xamarin.com/guides/android/troubleshooting/troubleshooting/#Global_Reference_Messages

  $ 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:

http://developer.xamarin.com/releases/android/xamarin.android_5/xamarin.android_5.1/#GREF_Logging_Changes

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.
Comment 8 Jonathan Pryor 2015-07-28 15:40:16 UTC
> 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.
Comment 9 Jon Douglas [MSFT] 2017-09-19 15:54:53 UTC
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!