Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

Trying to track down gref leak

I'm having problems with with an application reliably crashing after approximately 10 minutes of operation and I'm trying to track down the source of the crash.

The logcat seems to indicate that the crash is due to leaking of grefs based on the following line.

09-14 23:36:48.055 12383 12409 I monodroid-gc: 46080 outstanding GREFs. >Performing a full GC!

This line is followed by a frenzy of repeated GC activity until the application is terminated by the activity manager as shown in the following line following line.

"08-23 11:10:14.393 880 894 I ActivityManager: Killing >1909:WheelchairQuickCollect.WheelchairQuickCollect/u0a220 (adj 0): user request >after error" (Note this line is from an earlier log - I just had it handy)

I've attempted to enable gref logging via the following adb command (as suggested by https://developer.xamarin.com/guides/android/troubleshooting/troubleshooting/)

"adb shell setprop debug.mono.log gref,gc"

However I'm having two problems with logging

1) the log entries don't seem to contain any useful information below is an example of the gref logs. Note that there isn't any stack trace or type information on the objects the grefs point to as is shown in the troubleshooting example on the Xamarin website.

2) Enabling the gref log causes the main ui of my app to freeze. I have replicated this behavior several times but haven't been able to figure out why this is the case. I dont get any uncaught exceptions in the ide, just frozen screen followed by the activity manager force finishing my main activity

(09-14 23:45:30.742 883 909 W ActivityManager: Force finishing activity >WheelchairQuickCollect.WheelchairQuickCollect/md580d5d820f0b3cedc88e4799f6dbbf8c>5.MainActivity )

Anyone have any suggestions on how I might identify what is locking up the UI thread?

Also any thoughts on how can I determine what is using up all of the grefs would be greatly appreciated. Even type information for the .net runtime or java objects linked by these refs would be a good start.


09-14 23:45:30.389 13759 14047 I monodroid-gref: +w+ grefc 1082 gwrefc 4 obj-handle 0x1018c6/G -> new-handle 0x2002d7/W from thread 'finalizer'(14047)

09-14 23:45:30.390 13759 14047 I monodroid-gref: +w+ grefc 1075 gwrefc 11 obj-handle 0x18ea/G -> new-handle 0x2f3/W from thread 'finalizer'(14047)

09-14 23:45:30.390 13759 14047 I monodroid-gref: -g- grefc 1075 gwrefc 11 handle 0x18ea/G from thread 'finalizer'(14047)

UPDATE

Many thanks to SushiHangover for getting me headed down the right path. I've since found the leak to be coming from a c# port of the usb serial for android library. A couple of comments.

  • I was able to avoid locking up the UI by disabling some of my code that requests / processes measurements from the android sensor API. Not sure why this worked but I don't have time to figure it out now.
  • I found the gref.txt log in /data/user/0/package_name_here/files/.__override__/grefs.txt . this is a little bit different than what was given in SushiHangover's answer. Not sure if this is a result of the version of android I'm running (7.1.1). I determined this path by logging the result of this.ApplicationContext.FilesDir.AbsolutePath in my main activities onCreate method.
  • The gref.txt log is quite verbose and doesn't have any sort of summary making it very difficult to determine which objects are actually leaking. If anyone knows of a tool that can summarize this file that would be very helpful. I did however find out that you can force the dalvik cache to dump a summary of the the reference tables (local / global). To dump the table you must use reflection to call the dumpReferenceTables method as is shown below. I ran debugGlobalRefWorker in a dedicated task to print out the table every 10 seconds. From the summary portion of the dump I was able to quickly identify the type of the leaked object. I then used the gref.txt log to get a feel for where the object was most commonly being allocated. Fortunately the leak was large so it was pretty easy to see where it was coming from.

My code for dumping the reference tables

    public void debugGlobalRefWorker()
    {
        while(true)
        {
            dumpGlobalRefTable();
            Task.Delay(10000).Wait();
        }
    }

    //dont create these in dumpGlobalRefTable otherwise they will clutter up the gref log
    Java.Lang.Reflect.Method dumpGREFTableMethod = Java.Lang.Class.ForName("dalvik.system.VMDebug").GetDeclaredMethod("dumpReferenceTables");
    Java.Lang.Object[] args = new Java.Lang.Object[0];

    public void dumpGlobalRefTable()
    {
        //          Java.Lang.Class cls = Java.Lang.Class.ForName("android.os.Debug");
        //          Java.Lang.Class cls = Java.Lang.Class.ForName("dalvik.system.VMDebug");
        //      var method = cls.GetDeclaredMethod("dumpReferenceTables");
        dumpGREFTableMethod.Invoke(null,args);
    }

Example Table

09-18 12:20:36.091 29146 29174 I art     : global reference table dump:

09-18 12:20:36.091 29146 29174 I art     :   Last 10 entries (of 677):

09-18 12:20:36.091 29146 29174 I art     :       676: 0x7106a800 java.lang.Class<android.hardware.SensorEvent>

09-18 12:20:36.091 29146 29174 I art     :       675: 0x32c023c0 android.hardware.SensorEvent

09-18 12:20:36.091 29146 29174 I art     :       674: 0x32c04520 android.os.Bundle

09-18 12:20:36.091 29146 29174 I art     :       673: 0x32c06070 com.google.android.gms.internal.zzary

09-18 12:20:36.091 29146 29174 I art     :       672: 0x7104b448 java.lang.Class<android.widget.Toast>
...

09-18 12:20:36.091 29146 29174 I art     :   Summary:

09-18 12:20:36.091 29146 29174 I art     :         1 of android.runtime.UncaughtExceptionHandler

09-18 12:20:36.091 29146 29174 I art     :         2 of md57dcfd83abf19bfc45de0a46e73444d92.ServiceConnectionHelper (2 unique instances)

09-18 12:20:36.092 29146 29174 I art     :         1 of md526b7ac14cffc1a788e82c7b73f3add08.GoogleApiClientConnectionCallbacksImpl

09-18 12:20:36.092 29146 29174 I art     :         1 of md580d5d820f0b3cedc88e4799f6dbbf8c5.WheelchairConnectService_FLPCallbackHelper

09-18 12:20:36.092 29146 29174 I art     :         1 of md5e34b7f0d2ba7321e77528f2c21447828.AndroidBaroMeasurementProvider

09-18 12:20:36.092 29146 29174 I art     :         1 of md5e34b7f0d2ba7321e77528f2c21447828.AndroidMagUncalMeasurementProvider
like image 425
kabla002 Avatar asked Sep 15 '17 05:09

kabla002


1 Answers

The gref documentation is a little lacking in the fine details of how to acquire the details as things have changed overtime.

Enabling gref logging:

Logcat output (filtering via adb logcat -s monodroid-gref):

adb shell setprop debug.mono.log gref

Note: I have never seen it hang the UI thread or cause a termination, but try enabling it before you run your app

~~~~ 
09-14 23:40:19.656  4053  4053 I monodroid-gref: +g+ grefc 291 gwrefc 0 obj-handle 0x100019/I -> new-handle 0x100786/G from thread '(null)'(1)           
~~~~

Gref Details are in grefs.txt:

+g+ grefc 291 gwrefc 0 obj-handle 0x100019/I -> new-handle 0x100786/G from thread '(null)'(1)
  at Android.Runtime.AndroidObjectReferenceManager.CreateGlobalReference (Java.Interop.JniObjectReference value) [0x00000] in <05a8ec13540f42fc8ec62ef099f948d3>:0
  at Java.Interop.JniObjectReference.NewGlobalRef () [0x00000] in <548a126e175845e0999036cd7abdeb57>:0
  at Android.Runtime.JNIEnv.NewGlobalRef (System.IntPtr jobject) [0x00000] in <05a8ec13540f42fc8ec62ef099f948d3>:0
  at Java.Lang.Object.RegisterInstance (Android.Runtime.IJavaObject instance, System.IntPtr value, Android.Runtime.JniHandleOwnership transfer, System.IntPtr& handle) [0x00000] in <05a8ec13540f42fc8ec62ef099f948d3>:0
  at Java.Lang.Object.SetHandle (System.IntPtr value, Android.Runtime.JniHandleOwnership transfer) [0x00000] in <05a8ec13540f42fc8ec62ef099f948d3>:0
  at Java.Lang.Object..ctor () [0x00000] in <05a8ec13540f42fc8ec62ef099f948d3>:0
  at Android_Gref_Test.JavaObjectWrapper..ctor () [0x00000] in /Users/Sushi/code/Projects/Android_Gref_Test/Android_Gref_Test/MainActivity.cs:45
  at Android_Gref_Test.MainActivity.Button_Click (System.Object sender, System.EventArgs e) [0x0003b] in /Users/Sushi/code/Projects/Android_Gref_Test/Android_Gref_Test/MainActivity.cs:33
  at Android.Views.View+IOnClickListenerImplementor.OnClick (Android.Views.View v) [0x00000] in <05a8ec13540f42fc8ec62ef099f948d3>:0
  at Android.Views.View+IOnClickListenerInvoker.n_OnClick_Landroid_view_View_ (System.IntPtr jnienv, System.IntPtr native__this, System.IntPtr native_v) [0x00000] in <05a8ec13540f42fc8ec62ef099f948d3>:0
  at System.Object.cf56947b-b824-4d0d-839a-1d6dd87a5b7c (System.IntPtr , System.IntPtr , System.IntPtr ) [0x00000] in <896ad1d315ca4ba7b117efb8dacaedcf>:0
handle 0x100786; key_handle 0x2ef9890: Java Type: `md505d171be8e81cafbccfb3a52eeebc2c5/JavaObjectWrapper`; MCW type: `Android_Gref_Test.JavaObjectWrapper`

These details are in a hidden directory within your app's data files (files/.__override__/grefs.txt). At one point in time this directory was world accessible and thus a reported security vulnerability and was patched (Xamarin.Android 5.1.x) so you now need app level or root access to obtain it. Also Android will drop logcat messages if too many are being written and thus the gref listing in logcat could be dropped, so the details are stored in a separate file.

Use adb pull if you have root access

Note: Obtain root access with your non-production build based emulators via abd root.

adb pull /data/data/com.sushihangover.Android_Gref_Test/files/.__override__/grefs.txt ~/Desktop/grefs.txt

Or using a root shell:

adb shell 
cd /data/data/com.sushihangover.Android_Gref_Test/files/.__override__/
cat grefs.txt

Or if your app package is flagged as debuggable:

adb shell
run-as com.sushihangover.Android_Gref_Test
cd files/.__override__
cat grefs.txt

Copy the Grefs.txt to a public dir:

Note: This is just a simple continuous background thread, drop it into your Activity.OnCreate or set it up in some Debug-based app settings, etc...

#if DEBUG
    Task.Run(async () =>
    {
        const int seconds = 30;
        const string grefTag = "monodroid-gref";
        const string grefsFile = "grefs.txt";
        while (true)
        {
            var appDir = Application.ApplicationInfo.DataDir;
            var grefFile = Path.Combine("/data/data", PackageName, "files/.__override__", grefsFile);
            var grefFilePublic = Path.Combine(Environment.GetExternalStoragePublicDirectory(Environment.DirectoryDownloads).AbsolutePath, grefsFile);
            if (File.Exists(grefFile))
            {
                File.Copy(grefFile, grefFilePublic, true);
                Log.Debug(grefTag, $"adb pull {grefFilePublic} {grefsFile}");
            }
            else
                Log.Debug(grefTag, "no grefs.txt found, gref logging enabled? (adb shell setprop debug.mono.log gref)");
            await Task.Delay(seconds * 1000);
        }
    });
#endif

You can also force the output to a different directory via:

adb shell setprop debug.mono.log gref=/some/writable/path/grefs.txt
like image 88
SushiHangover Avatar answered Nov 14 '22 01:11

SushiHangover