Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Cache/NetworkDispatcher leaking finished requests #114

Closed
Dayanand515 opened this issue Oct 31, 2017 · 19 comments
Closed

Cache/NetworkDispatcher leaking finished requests #114

Dayanand515 opened this issue Oct 31, 2017 · 19 comments
Milestone

Comments

@Dayanand515
Copy link

Hi Team,
com.android.volley.Request#finish is not clearing mErrorListener, not its calling onFinish as is the case with https://github.com/mcxiaoke/android-volley/blob/master/src/main/java/com/android/volley/Request.java finish.
due to which error listener is not getting cleared and memory leak is there.

Dayanand515 referenced this issue Oct 31, 2017
Since this release introduces new APIs to support migrating off Apache
HTTP and handling multiple headers, the minor version should be
bumped. These changes are all backwards compatible so there is no need
to bump the major version.
@Dayanand515
Copy link
Author

Please refer mcxiaoke/android-volley@c111d14 , onFinish() should be there so that any class extending Request can clear api listeners.

@jpd236
Copy link
Collaborator

jpd236 commented Oct 31, 2017

At a glance, I can't understand why this should be necessary.

After Request#finish, the Request object goes out of scope - nothing inside Volley's internals should be holding onto it. That means it should be eligible for GC, as should all of its children, including any listeners.

Do you have more information about the leak you are seeing? In particular, do you have a sample app that reproduces it? Are you using LeakCanary and can provide the leak information? What device and Android version are you using to test with, and does it reproduce on other versions?

@Dayanand515
Copy link
Author

Hi Team,
I have created a sample app for the same at
https://github.com/Dayanand515/TestVolley

  1. Please install app, and click on "Click Me" text,
  2. After some time when on another screen "Api Error Occurred" text is shown , press back,
  3. wait for sometime.

Leak is shown by leak canary.

In testvolley.dn.java.testvolley:1.0:1.

  • testvolley.dn.java.testvolley.ApiActivity has leaked:

  • GC ROOT com.android.volley.CacheDispatcher.

  • references testvolley.dn.java.testvolley.ApiRequest.mListener

  • references testvolley.dn.java.testvolley.ApiActivity$1.this$0 (anonymous subclass of testvolley.dn.java.testvolley.ApiListeners)

  • leaks testvolley.dn.java.testvolley.ApiActivity instance

  • Retaining: 44 KB.

  • Reference Key: 3dff8f1a-d489-4efa-ab82-0a70fdad72d5

  • Device: Google google Android SDK built for x86 sdk_google_phone_x86

  • Android Version: 7.0 API: 24 LeakCanary: 1.5.4 74837f0

  • Durations: watch=5010ms, gc=113ms, heap dump=8480ms, analysis=9607ms

  • Details:

  • Instance of com.android.volley.CacheDispatcher
    | static $classOverhead = byte[441]@717252609 (0x2ac06801)
    | static DEBUG = true
    | mCache = com.android.volley.toolbox.DiskBasedCache@717964288 (0x2acb4400)
    | mCacheQueue = java.util.concurrent.PriorityBlockingQueue@717226360 (0x2ac00178)
    | mDelivery = com.android.volley.ExecutorDelivery@717972272 (0x2acb6330)
    | mNetworkQueue = java.util.concurrent.PriorityBlockingQueue@717226400 (0x2ac001a0)
    | mQuit = false
    | mWaitingRequestManager = com.android.volley.CacheDispatcher$WaitingRequestManager@718148064 (0x2ace11e0)
    | blocker = null
    | blockerLock = java.lang.Object@717259704 (0x2ac083b8)
    | contextClassLoader = dalvik.system.PathClassLoader@717328928 (0x2ac19220)
    | daemon = false
    | eetop = 0
    | group = java.lang.ThreadGroup@1864813784 (0x6f26ccd8)
    | inheritableThreadLocals = null
    | inheritedAccessControlContext = java.security.AccessControlContext@717259712 (0x2ac083c0)
    | lock = java.lang.Object@717258840 (0x2ac08058)
    | name = java.lang.String@718138816 (0x2acdedc0)
    | nativeParkEventPointer = 0
    | nativePeer = 2653233408
    | parkBlocker = java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@717238432 (0x2ac030a0)
    | parkState = 3
    | priority = 5
    | single_step = false
    | stackSize = 0
    | started = true
    | stillborn = false
    | target = null
    | threadLocalRandomProbe = 0
    | threadLocalRandomSecondarySeed = 0
    | threadLocalRandomSeed = 0
    | threadLocals = java.lang.ThreadLocal$ThreadLocalMap@718152968 (0x2ace2508)
    | threadQ = null
    | threadStatus = 0
    | tid = 1171
    | uncaughtExceptionHandler = null
    | shadow$klass = com.android.volley.CacheDispatcher
    | shadow$monitor = 0

  • Instance of testvolley.dn.java.testvolley.ApiRequest
    | static $classOverhead = byte[512]@717876225 (0x2ac9ec01)
    | static NETWORK_TIME_MILLIS = java.lang.String@717285800 (0x2ac0e9a8)
    | static PROTOCOL_CHARSET = java.lang.String@1866504416 (0x6f4098e0)
    | static $change = null
    | static GSON = com.google.gson.Gson@717330944 (0x2ac19a00)
    | static serialVersionUID = -7557160610015252903
    | static PROTOCOL_CONTENT_TYPE = java.lang.String@717992112 (0x2acbb0b0)
    | clazz = testvolley.dn.java.testvolley.User
    | data = android.os.Bundle@718328592 (0x2ad0d310)
    | formData = null
    | headers = null
    | mListener = testvolley.dn.java.testvolley.ApiActivity$1@718193072 (0x2acec1b0)
    | mLock = java.lang.Object@718282872 (0x2ad02078)
    | mRequestBody = null
    | mCacheEntry = null
    | mCanceled = false
    | mDefaultTrafficStatsTag = -1504897081
    | mErrorListener = testvolley.dn.java.testvolley.ApiActivity$1@718193072 (0x2acec1b0)
    | mEventLog = com.android.volley.VolleyLog$MarkerLog@718193824 (0x2acec4a0)
    | mLock = java.lang.Object@718282864 (0x2ad02070)
    | mMethod = 0
    | mRequestCompleteListener = com.android.volley.CacheDispatcher$WaitingRequestManager@718148064 (0x2ace11e0)
    | mRequestQueue = com.android.volley.RequestQueue@717330848 (0x2ac199a0)
    | mResponseDelivered = false
    | mRetryPolicy = com.android.volley.DefaultRetryPolicy@718328616 (0x2ad0d328)
    | mSequence = java.lang.Integer@1865173152 (0x6f2c48a0)
    | mShouldCache = true
    | mShouldRetryServerErrors = false
    | mTag = java.lang.String@717270032 (0x2ac0ac10)
    | mUrl = java.lang.String@717279328 (0x2ac0d060)
    | shadow$klass = testvolley.dn.java.testvolley.ApiRequest
    | shadow$monitor = -1928631308

  • Instance of testvolley.dn.java.testvolley.ApiActivity$1
    | static $classOverhead = byte[344]@717868097 (0x2ac9cc41)
    | static serialVersionUID = 2031432410671757167
    | static $change = null
    | this$0 = testvolley.dn.java.testvolley.ApiActivity@717956704 (0x2acb2660)
    | shadow$klass = testvolley.dn.java.testvolley.ApiActivity$1
    | shadow$monitor = 0

  • Instance of testvolley.dn.java.testvolley.ApiActivity
    | static $classOverhead = byte[2064]@717987841 (0x2acba001)
    | static url = java.lang.String@717279328 (0x2ac0d060)
    | static $change = null
    | static serialVersionUID = 705608175010244991
    | userApiListeners = testvolley.dn.java.testvolley.ApiActivity$1@718193072 (0x2acec1b0)
    | mActionBar = null
    | mActionModeTypeStarting = 0
    | mActivityInfo = android.content.pm.ActivityInfo@717782896 (0x2ac87f70)
    | mActivityTransitionState = android.app.ActivityTransitionState@718225584 (0x2acf40b0)
    | mApplication = testvolley.dn.java.testvolley.MyApplication@717967168 (0x2acb4f40)
    | mCalled = true
    | mChangeCanvasToTranslucent = false
    | mChangingConfigurations = false
    | mComponent = android.content.ComponentName@718237776 (0x2acf7050)
    | mConfigChangeFlags = 0
    | mCurrentConfig = android.content.res.Configuration@718287200 (0x2ad03160)
    | mDecor = null
    | mDefaultKeyMode = 0
    | mDefaultKeySsb = null
    | mDestroyed = true
    | mDoReportFullyDrawn = false
    | mEatKeyUpEvent = false
    | mEmbeddedID = null
    | mEnableDefaultActionBarUp = false
    | mEnterTransitionListener = android.app.SharedElementCallback$1@1871514504 (0x6f8d0b88)
    | mExitTransitionListener = android.app.SharedElementCallback$1@1871514504 (0x6f8d0b88)
    | mFinished = true
    | mFragments = android.app.FragmentController@718193040 (0x2acec190)
    | mHandler = android.os.Handler@718209312 (0x2acf0120)
    | mHasCurrentPermissionsRequest = false
    | mIdent = 19746635
    | mInstanceTracker = android.os.StrictMode$InstanceTracker@718193056 (0x2acec1a0)
    | mInstrumentation = android.app.Instrumentation@717314872 (0x2ac15b38)
    | mIntent = android.content.Intent@718229624 (0x2acf5078)
    | mLastNonConfigurationInstances = null
    | mMainThread = android.app.ActivityThread@717242624 (0x2ac04100)
    | mManagedCursors = java.util.ArrayList@718197040 (0x2aced130)
    | mManagedDialogs = null
    | mMenuInflater = null
    | mParent = null
    | mReferrer = java.lang.String@718234256 (0x2acf6290)
    | mResultCode = 0
    | mResultData = null
    | mResumed = false
    | mSearchEvent = null
    | mSearchManager = null
    | mStartedActivity = false
    | mStopped = true
    | mTaskDescription = android.app.ActivityManager$TaskDescription@718209344 (0x2acf0140)
    | mTemporaryPause = false
    | mTitle = java.lang.String@717968576 (0x2acb54c0)
    | mTitleColor = 0
    | mTitleReady = true
    | mToken = android.os.BinderProxy@718245984 (0x2acf9060)
    | mTranslucentCallback = null
    | mUiThread = java.lang.Thread@1944190976 (0x73e20000)
    | mVisibleBehind = false
    | mVisibleFromClient = true
    | mVisibleFromServer = true
    | mVoiceInteractor = null
    | mWindow = com.android.internal.policy.PhoneWindow@718009248 (0x2acbf3a0)
    | mWindowAdded = true
    | mWindowManager = android.view.WindowManagerImpl@718197352 (0x2aced268)
    | mInflater = com.android.internal.policy.PhoneLayoutInflater@718201184 (0x2acee160)
    | mOverrideConfiguration = null
    | mResources = android.content.res.Resources@718217552 (0x2acf2150)
    | mTheme = android.content.res.Resources$Theme@718193216 (0x2acec240)
    | mThemeResource = 2131492869
    | mBase = android.app.ContextImpl@718278784 (0x2ad01080)
    | shadow$klass = testvolley.dn.java.testvolley.ApiActivity
    | shadow$monitor = -1954971875

  • Excluded Refs:
    | Field: android.view.inputmethod.InputMethodManager.mNextServedView
    | Field: android.view.inputmethod.InputMethodManager.mServedView
    | Field: android.view.inputmethod.InputMethodManager.mServedInputConnection
    | Field: android.view.textservice.SpellCheckerSession$1.this$0
    | Field: android.view.Choreographer$FrameDisplayEventReceiver.mMessageQueue (always)
    | Thread:FinalizerWatchdogDaemon (always)
    | Thread:main (always)
    | Thread:LeakCanary-Heap-Dump (always)
    | Class:java.lang.ref.WeakReference (always)
    | Class:java.lang.ref.SoftReference (always)
    | Class:java.lang.ref.PhantomReference (always)
    | Class:java.lang.ref.Finalizer (always)
    | Class:java.lang.ref.FinalizerReference (always)

@jpd236
Copy link
Collaborator

jpd236 commented Nov 1, 2017

Thank you for all of the detailed information and especially the sample app! I can at least reproduce the leak now, although I'm not yet sure why it's happening. I think this came up previously in #19 and was closed as we didn't have needed details.

While it was definitely necessary to have Requests clear their listeners on cancel, because Volley internals are still holding onto the Request object while the request is being dispatched, it should not be necessary for Requests to have to do anything after the request is finished. The bug would be that something in Volley is holding a reference to a finished Request as it shouldn't be doing so.

That being said, I can't make sense of why CacheDispatcher/NetworkDispatcher are seen as holding references to the finished request. In the heap dumps / LeakCanary output it just shows up as "Java local" without a variable name. But I don't see what local variable is holding onto the request.

@jpd236 jpd236 changed the title mErrorlistener not null after finish called Cache/NetworkDispatcher leaking finished requests Nov 1, 2017
@joebowbeer
Copy link
Contributor

joebowbeer commented Nov 2, 2017

I don't see any indication that the ApiRequest instance is finished.

Regarding the reported leak of ApiActivity, either:

  1. There is a bug in RequestQueue.cancelAll() -or-
  2. LeakCanary is fooled by a delayed call to Activity.onDestroy()

Assuming RequestQueue.cancelAll() is correct, one way to avoid this false alarm would be to move cancelAll() from ApiActivity's onDestroy method to either onStop or onPause, perhaps preceded by a call to isFinishing().

I also notice that the anonymous listeners class holds a strong reference to ApiActivity. For robustness, I recommend using a static nested class with a weak reference to the target Activity. This might be enough to assuage LeakCanary.

Looking at the instances reported by LeakCanary, I think the following two objects are, respectively, the current instance of ApiActivity and its userApiListeners instance:

ApiActivity@717956704
  userApiListeners -> ApiActivity$1@717868097

ApiActivity$1@717868097
  this$0 -> ApiActivity@717956704

The interesting instances where the leak occurs are:

CacheDispatcher -> ApiRequest@717876225

ApiRequest@717876225
  mListener -> ApiActivity$1@718193072
  mErrorListener -> ApiActivity$1@718193072

ApiActivity$1@718193072
  this$0 -> ApiActivity@717987841

ApiActivity@717987841 [LEAKED]
  userApiListeners -> ApiActivity$1@718193072

Observations:

  1. The leaked Activity is finished (mFinished = true). This means that finish() has been called, but onDestroy may not have been called. In fact, I believe onDestroy may not be called until after the new Activity's onCreate has been called.

  2. The leaked Activity does not cancel its requests until onDestroy is called.

  3. The ApiRequest instance has not been canceled (mCanceled = false).

@Dayanand515
Copy link
Author

I don't see any indication that the ApiRequest instance is finished.

This can be conformed from logcat logs , use filter 'logs'

Regarding the reported leak of ApiActivity, either:

There is a bug in RequestQueue.cancelAll() -or-

Since request is finised and removed from com.android.volley.RequestQueue#mCurrentRequests hence cancel on request is not called.

LeakCanary is fooled by a delayed call to Activity.onDestroy()

As per logs onDestroy is getting called within short duration.

Even then cache dispatcher is referencing request listner.

@joebowbeer
Copy link
Contributor

@Dayanand515 thanks for correcting my analysis.

@Dayanand515
Copy link
Author

@joebowbeer what do you recommend to fix this leak.
I believe we can add onStop method and clears listener inside onStop as handled at mcxiaoke/android-volley@c111d14

@joebowbeer
Copy link
Contributor

@Dayanand515 The response for the ApiRequest that is retained by CacheDispatcher has not yet been delivered:

mResponseDelivered = false

Are you sure this request is finished?

@jpd236
Copy link
Collaborator

jpd236 commented Nov 3, 2017

@joebowbeer markDelivered looks like its only called for successful responses. This sample app gets an error response by intentionally hitting a bogus URL.

@Dayanand515 we need to figure out why something is holding a reference to the Request inside Volley. Requiring every Request subclass to clear the listener when a request is finished is not ideal at all (we had to do it to cover the cancel case, but it shouldn't be necessary here), and still means we're leaking the Request object even if the listeners aren't leaked. The CL you linked covers the error listener, but presumably in most cases the response listener is also affected and that is out of the scope of Request itself.

Need to look at this more, likely by trying to strip down the code to the minimum possible reproduceable case. It's possible this is a Volley bug... but it's also possible this is something wrong at a lower level (which might or might not be something we can work around).

@jpd236
Copy link
Collaborator

jpd236 commented Nov 4, 2017

What I'm observing is very strange. I can not reproduce the issue if I comment out the call to mCurrentRequests.remove(request) in RequestQueue#finish. I can't possibly see how that would be causing a leak as it's supposed to be removing a reference to the request. But as far as I can tell, it's 100% reliable.

@joebowbeer
Copy link
Contributor

@jpd236 that would suggest a deadlock or long wait was needed to acquire the mCurrentRequests lock?

Without a body the lock acquisition may be elided.

@joebowbeer
Copy link
Contributor

This anonymous inner Runnable in CacheDispatcher is a little fishy:

    mDelivery.postResponse(request, response, new Runnable() {
        @Override
        public void run() {
            try {
                mNetworkQueue.put(request);
            } catch (InterruptedException e) {
                // Restore the interrupted status
                Thread.currentThread().interrupt();
            }
        }
    });

It references the final request local variable inside the thread's run() method. A static nested class with explicit request and networkQueue fields would make this more explicit.

@jpd236
Copy link
Collaborator

jpd236 commented Nov 6, 2017

  • I don't follow why lock acquisition would be related here, but anyway I can remove the lock but keep the remove call and the leak still reproduces.

  • The runnable pointed out only runs if something is being pulled from the cache, which is not the case here; indeed you can replace the entire loop of CacheDispatcher with a hard-coded call to post the error directly to the response delivery and still reproduce the issue.

I think the way forward here will be to try to distill this into a minimal repro case.

@jpd236
Copy link
Collaborator

jpd236 commented Nov 8, 2017

OK, I have a fairly minimal repro case which is attached here. This isolates this from all of Volley's internals and any actual network activity / switches between activities. Still investigating.
TestVolley.zip

@jpd236 jpd236 added this to the 1.1.0 milestone Nov 8, 2017
jpd236 added a commit to jpd236/volley that referenced this issue Nov 8, 2017
Android has a long-standing known issue where local variables aren't
explicitly cleared even when they go out of scope, which can cause
their contents to leak. Clearing the variable explicitly is not a
sufficient fix because the clear is optimized out as it's not
observable. The best we can do is extract the contents of the loops in
question to helper methods and hope that they are complex enough that
code optimizers like Proguard won't inline them.

Should contain no functional changes otherwise.

Verified against provided sample app.

Fixes google#114
@jpd236
Copy link
Collaborator

jpd236 commented Nov 8, 2017

OK. This does indeed appear to have been the same as #19. Contrary to the linked blog post there, this issue was not actually fully resolved and has resurfaced in recent versions of the platform, even with ART.

The workaround from the blog post of posting an empty item to the queue every second is not ideal as that would churn threads that should otherwise be idle. Instead we can try the tack of extracting the body of the loop to a helper method. It's not a 100% guarantee since Proguard could theoretically optimize it, but in practice it's probably good enough and is likely the best we can do.

Here's an example of that workaround in practice: https://android.googlesource.com/platform/frameworks/support/+/cd07a0cfd9c9501a03c574d2d48df51c82b73e33

PR coming shortly.

jpd236 added a commit to jpd236/volley that referenced this issue Nov 8, 2017
Android has a long-standing known issue where local variables aren't
explicitly cleared even when they go out of scope, which can cause
their contents to leak. Clearing the variable explicitly is not a
sufficient fix because the clear is optimized out as it's not
observable. Extracting the loop contents to a helper function is
likely to work but risks being inlined by a code optimizer. So we
poll() once (which is non-blocking) before waiting to ensure that the
previous request is always cleared expediently.

Should contain no functional changes otherwise.

Verified against provided sample app.

Fixes google#114
jpd236 added a commit to jpd236/volley that referenced this issue Nov 10, 2017
Android has a long-standing known issue where local variables aren't
explicitly cleared even when they go out of scope, which can cause
their contents to leak. Since BlockingQueue#take() blocks
forever until a new item is ready, this means the last
request will remain in memory until a new request pushes it
out. Extracting a helper method is a workaround for this - see, for
example, the following CL in the Android support lib:

https://android.googlesource.com/platform/frameworks/support/+/cd07a0cfd9c9501a03c574d2d48df51c82b73e33

The following other solutions were attempted but were not sufficient:

- Clear the variable prior to take() - optimized out because the write
  is not observable, so it has no impact on the bytecode.

- Call poll() prior to take() - for some reason, this doesn't work
  when proguard optimization is on.

With code optimization, there's no guarantee that this will work.
However, it appears to be the best we can do and follows precedent /
advice from the ART team.

Should contain no functional changes otherwise as this is just
extracting code to a helper method, and thus should be safe for 1.1.0.

Verified against provided sample app.

Fixes google#114
jpd236 added a commit that referenced this issue Nov 10, 2017
* Workaround memory leak in dispatchers.

Android has a long-standing known issue where local variables aren't
explicitly cleared even when they go out of scope, which can cause
their contents to leak. Since BlockingQueue#take() blocks
forever until a new item is ready, this means the last
request will remain in memory until a new request pushes it
out. Extracting a helper method is a workaround for this - see, for
example, the following CL in the Android support lib:

https://android.googlesource.com/platform/frameworks/support/+/cd07a0cfd9c9501a03c574d2d48df51c82b73e33

The following other solutions were attempted but were not sufficient:

- Clear the variable prior to take() - optimized out because the write
  is not observable, so it has no impact on the bytecode.

- Call poll() prior to take() - for some reason, this doesn't work
  when proguard optimization is on.

With code optimization, there's no guarantee that this will work, though
we now provide a Proguard config that should prevent inlining. However, it
appears to be the best we can do and follows precedent / advice from the
ART team.

Should contain no functional changes otherwise as this is just
extracting code to a helper method, and thus should be safe for 1.1.0.

Verified against provided sample app.

Fixes #114
@jpd236
Copy link
Collaborator

jpd236 commented Nov 10, 2017

@Dayanand515 - could you try compiling against the latest 1.1.0-SNAPSHOT from the https://oss.jfrog.org/artifactory/oss-snapshot-local/ repository to verify that it resolves the issue in your full app?

@Dayanand515
Copy link
Author

@jpd236 / @joebowbeer 1.1.0-SNAPSHOT from oss-snapshot-local works as expected, doesn't reproduce any memory leaks.
Thanks.

@mitpjones
Copy link

I have also tested and seems to be fixed.

Thanks

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
4 participants