Leakcanary: DisplayLeakService never completes

Created on 9 Jul 2018  路  21Comments  路  Source: square/leakcanary

I've been on 1.6-SNAPSHOT for some time now, but I never tried it with a fresh install of my app until today. After doing so, LeakCanary detects a leak, and posts a notification showing that it's analyzing it, and then changes the notification to say "Reporting LeakCanary result LeakCanary is working..." with an indeterminate progress bar.

I noticed 10 minutes later it was still stuck on that notification, and tapping on it did nothing. So I went to the Leak App to see what was going on, and there was no DisplayLeakActivity! I verified by uninstalling my app on another device that had 1.6-SNAPSHOT and a DisplayLeakActivity, and observed that after re-installing it, there was still no DisplayLeakActivity.

Update: I am using the latest snapshot that there is in sonatype (Fri Jun 29 17:20:51 UTC 2018)

picture eygraber

All 21 comments

~Calling LeakCanary.enableDisplayLeakActivity(context) explicitly fixes this, but I think the idea was this would get called automatically the first time a leak was detected.~

Calling LeakCanary.enableDisplayLeakActivity(context) explicitly makes the DisplayLeakActivity show up, but the leak result is never picked up (i.e. the notification shows "Reporting LeakCanary result LeakCanary is working..." with an indeterminate progress bar).

eygraber picture eygraber on 9 Jul 2018

I tried putting some breakpoints in DisplayLeakService to figure out what's going on, but it seems like if the debugger is enabled, LeakCanary won't run at all.

eygraber picture eygraber on 10 Jul 2018

Thx! Can you repro with the example app?

Debugger: you can customize the "debugger control" on the ref watcher builder to enable heap dumps even when the debugguer is on.

pyricau picture pyricau on 10 Jul 2018
👍1

I can't repro it in the sample project, and it seems to have happened after I updated my DI library, which touched almost every file in my project, so it's hard to roll back. None of the changes should have affected LeakCanary though.

I got debugging working, but the debugger detaches itself as soon as any breakpoint on ForegroundService is hit from onCreate onwards. This doesn't happen before my DI update commit.

I downgraded LeakCanary to 1.5.4 and this is still happening, although the mechanism is different. In that case, the notification never shows at all, and the leak never shows up in DisplayLeakActivity.

I'm still combing through my change set, trying to find anything that might affect it, but it's taking some time (3k+ changes).

Here are the logs from 1.5.4 from when the app starts:

I/zygote64: Late-enabling -Xcheck:jni
<truncated>
2018-07-11 01:17:36.997 26294-26303/com.myapp I/zygote64: Do partial code cache collection, code=30KB, data=21KB
2018-07-11 01:17:36.997 26294-26303/com.myapp I/zygote64: After code cache collection, code=30KB, data=21KB
2018-07-11 01:17:36.997 26294-26303/com.myapp I/zygote64: Increasing code cache capacity to 128KB
2018-07-11 01:17:37.045 26294-26347/com.myapp W/zygote64: Unsupported class loader
2018-07-11 01:17:37.046 26294-26347/com.myapp W/zygote64: Skipping duplicate class check due to unsupported classloader
<truncated>
2018-07-11 01:17:37.062 26294-26347/com.myapp W/zygote64: Unsupported class loader
<truncated>
2018-07-11 01:17:37.109 26294-26303/com.myapp I/zygote64: Do partial code cache collection, code=61KB, data=41KB
2018-07-11 01:17:37.113 26294-26303/com.myapp I/zygote64: After code cache collection, code=61KB, data=41KB
2018-07-11 01:17:37.113 26294-26303/com.myapp I/zygote64: Increasing code cache capacity to 256KB
<truncated>
2018-07-11 01:17:37.349 26294-26303/com.myapp I/zygote64: Do full code cache collection, code=124KB, data=82KB
2018-07-11 01:17:37.350 26294-26303/com.myapp I/zygote64: After code cache collection, code=95KB, data=51KB
2018-07-11 01:17:37.404 26294-26303/com.myapp I/zygote64: Do partial code cache collection, code=109KB, data=61KB
2018-07-11 01:17:37.404 26294-26303/com.myapp I/zygote64: After code cache collection, code=106KB, data=60KB
2018-07-11 01:17:37.404 26294-26303/com.myapp I/zygote64: Increasing code cache capacity to 512KB
2018-07-11 01:17:37.479 26294-26395/com.myapp I/zygote64: The ClassLoaderContext is a special shared library.
2018-07-11 01:17:37.480 26294-26395/com.myapp I/zygote64: The ClassLoaderContext is a special shared library.
<truncated>
2018-07-11 01:17:37.486 26294-26395/com.myapp I/zygote64: The ClassLoaderContext is a special shared library.
<truncated>
2018-07-11 01:17:37.630 26294-26411/com.myapp I/zygote64: android::hardware::configstore::V1_0::ISurfaceFlingerConfigs::hasWideColorDisplay retrieved: 1
2018-07-11 01:17:37.630 26294-26411/com.myapp I/OpenGLRenderer: Initialized EGL, version 1.4
<truncated>
2018-07-11 01:17:38.289 26294-26303/com.myapp I/zygote64: Do full code cache collection, code=250KB, data=182KB
2018-07-11 01:17:38.290 26294-26303/com.myapp I/zygote64: After code cache collection, code=224KB, data=127KB
<truncated>
2018-07-11 01:17:38.870 26294-26303/com.myapp I/zygote64: Do partial code cache collection, code=245KB, data=160KB
2018-07-11 01:17:38.871 26294-26303/com.myapp I/zygote64: After code cache collection, code=245KB, data=160KB
2018-07-11 01:17:38.871 26294-26303/com.myapp I/zygote64: Increasing code cache capacity to 1024KB
<truncated>
2018-07-11 01:17:41.143 26294-26303/com.myapp I/zygote64: Compiler allocated 7MB to compile void android.widget.TextView.<init>(android.content.Context, android.util.AttributeSet, int, int)
2018-07-11 01:17:41.215 26294-26303/com.myapp I/zygote64: Do full code cache collection, code=502KB, data=337KB
2018-07-11 01:17:41.215 26294-26303/com.myapp I/zygote64: After code cache collection, code=434KB, data=240KB
<truncated>
2018-07-11 01:17:44.021 26294-26341/com.myapp I/zygote64: Explicit concurrent copying GC freed 43071(1623KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 5MB/11MB, paused 161us total 77.361ms
2018-07-11 01:17:44.162 26294-26341/com.myapp D/LeakCanary: WRITE_EXTERNAL_STORAGE permission not granted
2018-07-11 01:17:44.198 26294-26341/com.myapp I/zygote64: hprof: heap dump "/data/user/0/com.myapp/files/leakcanary/130d0de9-7267-4165-aef9-6f367b103bf2_pending.hprof" starting...
2018-07-11 01:17:45.576 26294-26341/com.myapp I/zygote64: hprof: heap dump completed (18MB) in 1.377s objects 351962 objects with stack traces 0
2018-07-11 01:17:46.732 26294-26341/com.myapp I/zygote64: Explicit concurrent copying GC freed 4553(371KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 5MB/11MB, paused 174us total 70.595ms
2018-07-11 01:17:46.844 26294-26341/com.myapp D/LeakCanary: Could not dump heap, previous analysis still is in progress.
<truncated>
2018-07-11 01:17:56.935 26294-26341/com.myapp I/zygote64: Explicit concurrent copying GC freed 4467(364KB) AllocSpace objects, 2(104KB) LOS objects, 49% free, 5MB/11MB, paused 222us total 80.275ms
2018-07-11 01:17:57.045 26294-26341/com.myapp D/LeakCanary: Could not dump heap, previous analysis still is in progress.
2018-07-11 01:18:17.145 26294-26341/com.myapp I/zygote64: Explicit concurrent copying GC freed 11304(729KB) AllocSpace objects, 1(20KB) LOS objects, 49% free, 5MB/11MB, paused 191us total 77.181ms
2018-07-11 01:18:17.258 26294-26341/com.myapp D/LeakCanary: Could not dump heap, previous analysis still is in progress.
<truncated>
2018-07-11 01:18:57.345 26294-26341/com.myapp I/zygote64: Explicit concurrent copying GC freed 10367(601KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 5MB/11MB, paused 197us total 77.883ms
2018-07-11 01:18:57.454 26294-26341/com.myapp D/LeakCanary: Could not dump heap, previous analysis still is in progress.

And here are the logs from 1.6-SNAPSHOT:

2018-07-11 01:43:24.480 30021-30021/? I/zygote64: Late-enabling -Xcheck:jni
<truncated>
2018-07-11 01:43:24.702 30021-30032/com.myapp I/zygote64: Do partial code cache collection, code=30KB, data=21KB
2018-07-11 01:43:24.703 30021-30032/com.myapp I/zygote64: After code cache collection, code=29KB, data=21KB
2018-07-11 01:43:24.703 30021-30032/com.myapp I/zygote64: Increasing code cache capacity to 128KB
2018-07-11 01:43:24.757 30021-30121/com.myapp W/zygote64: Unsupported class loader
2018-07-11 01:43:24.763 30021-30121/com.myapp W/zygote64: Skipping duplicate class check due to unsupported classloader
<truncated>
2018-07-11 01:43:24.785 30021-30121/com.myapp W/zygote64: Unsupported class loader
<truncated>
2018-07-11 01:43:24.876 30021-30032/com.myapp I/zygote64: Do partial code cache collection, code=61KB, data=38KB
2018-07-11 01:43:24.876 30021-30032/com.myapp I/zygote64: After code cache collection, code=61KB, data=38KB
2018-07-11 01:43:24.876 30021-30032/com.myapp I/zygote64: Increasing code cache capacity to 256KB
<truncated>
2018-07-11 01:43:25.100 30021-30032/com.myapp I/zygote64: Do full code cache collection, code=123KB, data=80KB
2018-07-11 01:43:25.101 30021-30032/com.myapp I/zygote64: After code cache collection, code=97KB, data=52KB
<truncated>
2018-07-11 01:43:25.174 30021-30032/com.myapp I/zygote64: Do partial code cache collection, code=122KB, data=77KB
2018-07-11 01:43:25.174 30021-30032/com.myapp I/zygote64: After code cache collection, code=115KB, data=74KB
2018-07-11 01:43:25.174 30021-30032/com.myapp I/zygote64: Increasing code cache capacity to 512KB
2018-07-11 01:43:25.242 30021-30180/com.myapp I/zygote64: The ClassLoaderContext is a special shared library.
<truncated>
2018-07-11 01:43:25.245 30021-30180/com.myapp I/zygote64: The ClassLoaderContext is a special shared library.
2018-07-11 01:43:25.254 30021-30180/com.myapp I/zygote64: The ClassLoaderContext is a special shared library.
<truncated>
2018-07-11 01:43:25.425 30021-30196/com.myapp I/zygote64: android::hardware::configstore::V1_0::ISurfaceFlingerConfigs::hasWideColorDisplay retrieved: 1
<truncated>
2018-07-11 01:43:26.156 30021-30032/com.myapp I/zygote64: Do full code cache collection, code=250KB, data=186KB
2018-07-11 01:43:26.156 30021-30032/com.myapp I/zygote64: After code cache collection, code=225KB, data=127KB
<truncated>
2018-07-11 01:43:26.955 30021-30032/com.myapp I/zygote64: Do partial code cache collection, code=243KB, data=160KB
2018-07-11 01:43:26.955 30021-30032/com.myapp I/zygote64: After code cache collection, code=243KB, data=160KB
2018-07-11 01:43:26.955 30021-30032/com.myapp I/zygote64: Increasing code cache capacity to 1024KB
<truncated>
2018-07-11 01:43:27.247 30021-30032/com.myapp I/zygote64: Compiler allocated 6MB to compile void android.view.ViewRootImpl.performTraversals()
<truncated>=346KB
2018-07-11 01:43:31.619 30021-30032/com.myapp I/zygote64: After code cache collection, code=419KB, data=259KB
<truncated>
2018-07-11 01:43:32.111 30021-30105/com.myapp I/zygote64: Explicit concurrent copying GC freed 77932(3MB) AllocSpace objects, 20(2024KB) LOS objects, 50% free, 6MB/13MB, paused 78us total 47.857ms
<truncated>
2018-07-11 01:43:32.241 30021-30105/com.myapp D/LeakCanary: WRITE_EXTERNAL_STORAGE permission not granted
2018-07-11 01:43:32.387 30021-30105/com.myapp I/zygote64: hprof: heap dump "/data/user/0/com.myapp/files/leakcanary/8f5d8e12-8668-448e-9093-9f872949f760_pending.hprof" starting...
2018-07-11 01:43:33.753 30021-30105/com.myapp I/zygote64: hprof: heap dump completed (20MB) in 1.366s objects 425776 objects with stack traces 0
2018-07-11 01:43:33.865 30021-30105/com.myapp I/zygote64: Explicit concurrent copying GC freed 5285(534KB) AllocSpace objects, 3(124KB) LOS objects, 50% free, 6MB/13MB, paused 65us total 40.490ms
2018-07-11 01:43:33.967 30021-30105/com.myapp D/LeakCanary: Could not dump heap, previous analysis still is in progress.
<truncated>
2018-07-11 01:43:37.197 30021-30105/com.myapp I/zygote64: Explicit concurrent copying GC freed 37706(1341KB) AllocSpace objects, 2(104KB) LOS objects, 49% free, 5MB/11MB, paused 40us total 33.664ms
2018-07-11 01:43:37.299 30021-30105/com.myapp D/LeakCanary: Could not dump heap, previous analysis still is in progress.
<truncated>
2018-07-11 01:43:44.131 30021-30105/com.myapp I/zygote64: Explicit concurrent copying GC freed 4147(288KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 5MB/11MB, paused 169us total 74.448ms
2018-07-11 01:43:44.239 30021-30105/com.myapp D/LeakCanary: Could not dump heap, previous analysis still is in progress.
2018-07-11 01:43:47.375 30021-30105/com.myapp I/zygote64: Explicit concurrent copying GC freed 799(159KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 5MB/11MB, paused 207us total 74.715ms
2018-07-11 01:43:47.481 30021-30105/com.myapp D/LeakCanary: Could not dump heap, previous analysis still is in progress.
eygraber picture eygraber on 11 Jul 2018

While looking for the problem, I connected the Android Studio profiler to look for the disappearing IntentService, and lo and behold, leaks get reported.

Leaks continued to get reported for the remainder of that app session, even after the profiler is disconnected. Restarting the app without the profiler causes the "Reporting LeakCanary result LeakCanary is working..." with an indeterminate progress bar issue to come back.

Is it possible that this is a timing issue that got exacerbated by my DI update?

eygraber picture eygraber on 11 Jul 2018

OK was able to get it to work without connecting the profiler. The new version of DI uses lifecycle components (specifically, it uses a LifecycleObserver to determine when a LifecycleOwner is destroyed). Not sure how that would affect LeakCanary, but that seems to be the issue.

eygraber picture eygraber on 11 Jul 2018

OK I found the issue. There was a leak in the DI library. I fixed it and now LeakCanary works fine. Not sure why a leak would break it though...

Here's the PR for the memory leak fix in the DI library

eygraber picture eygraber on 11 Jul 2018

Thx for the details. A few things to unpack:

  • DisplayLeakCanary and the LeakAnalysis service all run in the separate leakcanary process. So if you attach the debugger to your app, you should likely also attach the debugger to the leakcanary process when that one starts.

  • If I understand correctly, when you have a leak in your app you see the notification going through the progress back all the way to the end, then it gets dismissed and replaced with the notification that says Reporting LeakCanary result.

  • Can you confirm that you see the Reporting LeakCanary result ? If yes, it means that the analysis completed and the reporting (which happens in the main app process) blocked

  • Do you set a custom AbstractAnalysisResultService? https://github.com/square/leakcanary/wiki/Customizing-LeakCanary#uploading-to-a-server
pyricau picture pyricau on 17 Jul 2018

  1. I got the debugging working, up until the last step when the debugger automatically disconnects

  2. Correct

  3. Confirmed

  4. No

eygraber picture eygraber on 17 Jul 2018

That's weird. If the notification sticks around, it's probably that the Foreground service is not destroyed (since the notification is removed in onDestroy with stopForeground(true);).

I'm still unclear on which service you were able to debug through. ForegroundService is the parent class, what was the implementation?

pyricau picture pyricau on 17 Jul 2018

DisplayLeakService was the implementation.

eygraber picture eygraber on 17 Jul 2018

Ok.

So, summary of the problem:

  • in your app, when a leak is detected, LeakCanary detects it and runs the analysis
  • Then it starts the DisplayLeakService to report the leak.
  • The notification associated to DisplayLeakService is displayed and never removed
  • The "X leaked" notification never shows up
  • DisplayLeakActivity is never enabled

Provided that there is actually a leak and that it was correctly detected, it sounds like the DisplayLeakService either doesn't finish or is blocked somewhere.

If you can repro, maybe a thread dump would help (if it's a deadlock / thread locked issue). Maybe also a dump of running services.

pyricau picture pyricau on 21 Jul 2018

I'll try to repro in the sample app, and will update.

eygraber picture eygraber on 24 Jul 2018

I haven't been able to repro it in the sample, and after I updated the offending library in my app the issue went away.

eygraber picture eygraber on 15 Aug 2018

I have the same issue on latest LeakCanary 1.6.1
I've done a bit of debugging and noticed that onHandleIntentInForeground method inside DisplayLeakService is never called.
Android 8.1

IlyaGulya picture IlyaGulya on 18 Sep 2018

Looks like I found what is causing this problem in logs.

09-20 16:19:18.949 1988-3736/? E/JavaBinder: !!! FAILED BINDER TRANSACTION !!!  (parcel size = 685628)
09-20 16:19:18.950 1988-3736/? W/ActivityManager: Failed delivering service starts
    android.os.TransactionTooLargeException: data parcel size 685628 bytes
        at android.os.BinderProxy.transactNative(Native Method)
        at android.os.BinderProxy.transact(Binder.java:764)
        at android.app.IApplicationThread$Stub$Proxy.scheduleServiceArgs(IApplicationThread.java:1446)
        at com.android.server.am.ActiveServices.sendServiceArgsLocked(ActiveServices.java:2359)
        at com.android.server.am.ActiveServices.bringUpServiceLocked(ActiveServices.java:2062)
        at com.android.server.am.ActiveServices.startServiceInnerLocked(ActiveServices.java:536)
        at com.android.server.am.ActiveServices.startServiceLocked(ActiveServices.java:478)
        at com.android.server.am.ActivityManagerService.startService(ActivityManagerService.java:18292)
        at android.app.IActivityManager$Stub.onTransact(IActivityManager.java:528)
        at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:2924)
        at android.os.Binder.execTransact(Binder.java:697)
09-20 16:19:18.950 1988-3736/? E/JavaBinder: *** Uncaught remote exception!  (Exceptions are not yet supported across processes.)
    java.lang.RuntimeException: android.os.TransactionTooLargeException: data parcel size 685628 bytes
        at android.os.Parcel.writeException(Parcel.java:1882)
        at android.os.Binder.execTransact(Binder.java:710)
     Caused by: android.os.TransactionTooLargeException: data parcel size 685628 bytes
        at android.os.BinderProxy.transactNative(Native Method)
        at android.os.BinderProxy.transact(Binder.java:764)
        at android.app.IApplicationThread$Stub$Proxy.scheduleServiceArgs(IApplicationThread.java:1446)
        at com.android.server.am.ActiveServices.sendServiceArgsLocked(ActiveServices.java:2359)
        at com.android.server.am.ActiveServices.bringUpServiceLocked(ActiveServices.java:2062)
        at com.android.server.am.ActiveServices.startServiceInnerLocked(ActiveServices.java:536)
        at com.android.server.am.ActiveServices.startServiceLocked(ActiveServices.java:478)
        at com.android.server.am.ActivityManagerService.startService(ActivityManagerService.java:18292)
        at android.app.IActivityManager$Stub.onTransact(IActivityManager.java:528)
        at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:2924)
        at android.os.Binder.execTransact(Binder.java:697)
IlyaGulya picture IlyaGulya on 20 Sep 2018

It happens when DisplayLeakService is starting. Seems that we should not put serialized HeapDump inside Intent at AbstractAnalysisResultService and should save it somewhere on storage and put the file location instead. Or implement ContentProvider for heap dump file.

IlyaGulya picture IlyaGulya on 20 Sep 2018
👍1

Hmm, it does not seem that HeapDump object really can grow so big. I'll try to catch it again and check the size of HeapDump.

IlyaGulya picture IlyaGulya on 20 Sep 2018

Looks like AnalysisResult has very big size (in my case 643581 bytes)

IlyaGulya picture IlyaGulya on 20 Sep 2018

@eygraber @pyricau Hello, guys. Could you please test my fix? #1102

IlyaGulya picture IlyaGulya on 24 Sep 2018

@IlyaGulya I'll see if I can repro on an old version of my app, and try your fix.

eygraber picture eygraber on 26 Sep 2018
👍1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

smallgirl picture smallgirl  路  3Comments
ltym2016 picture ltym2016  路  4Comments
arctouch-carlosottoboni picture arctouch-carlosottoboni  路  4Comments
pyricau picture pyricau  路  4Comments
divyenduz picture divyenduz  路  6Comments