Debugging a memory increase, using Generational Analysis

    November 19th, 2013 Posted by: - posted under:Articles » Tutorials

    I was recently working on an internal project for Burnside Digital, and decided it was time to do some memory profiling to make sure that I didn’t have any leaks. I ran the program with the ‘Leaks’ tool of instruments, and as I was watching the Live Bytes column, I saw the number of Bytes being used, slowly but surely increasing as time went on. Instruments wasn’t detecting any leaks, so I knew this wasn’t going to be a straightforward leak to debug.

    At that point I decided to use the very handy “Mark Generation” button in instruments. For those of you that haven’t used this button before, what it does is take a snapshot of all the active objects when you tap it. As objects get deallocated, they get removed from the snapshot. The usefulness of this snapshot is for doing a generational analysis of your application. Taking subsequent snapshots of the memory state of your application will show you what objects are still hanging around when they are supposed to be deallocated.

    As you can see in the screenshots, the first Generation will be all the objects currently in memory. On each subsequent generation, it is only the objects that have been created, and not deallocated yet, that are shown. In Generation H this screenshot was right after I created the generation so it shows a larger growth. Waiting a few more seconds, it’s growth also dropped to 1.58 KB, with 32 objects.

    Immediately I realized, that indeed, I have a fairly large issue, in that roughly every 10 seconds, I was creating and not destroying 1.5 KB… In a long running app, this could really add up.

    Now I had to try to debug these increases. If you tap on the grey right arrow next to a generation, it will expand out and show you all the objects still hanging around.

    Hrmm, lots of Core Foundation objects, some NSURL’s, and a bunch of strings. None of this is my code. Let’s dig deeper. You can expand each of the types of objects to see all the addresses that are hanging around, and see the stack trace for each of those objects. You do this by looking at the extended detail of the objects, by selecting the third button on the right in the View area to open the Extended Detail.

    Screen Shot 2013-11-19 at 9.28.34 AM

    Looking at the stack traces for a bunch of objects, I see a lot of internal Core Foundation traces, which don’t help, but then I came across a helpful stack trace pointing me at PNReachability. Looking through all the traces of the objects hanging around, the only user land code, was pointing at PNReachability.

    Going one level further down, we can see all the retain / release and autoreleases that this object has experienced. Also lets look at the code

    One of the components we use is a pub/sub implementation called PubNub. Since this bug seemed to be in that component, I decided to see if I couldn’t replicate it with the demo example of PubNub from https://github.com/pubnub/objective-c/tree/master/iOS at commit  f9e7d59.

    Profiling the demo, I was able to see the same 1.58 kb increases every 10 seconds, so I knew that my app wasn’t at fault.

    Screen Shot 2013-11-19 at 9.56.05 AM

    Looking at the code for handleOriginLookupTimer, i see the pretty standard dispatch_async on a background thread, running a synchronous network call, and then calling back to the main thread on another dispatch_async. They are even doing a weak reference to self properly.

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    28
    29
    30
    
    - (void)handleOriginLookupTimer {
     
        // In case if reachability report that connection is available (not on cellular) we should launch additional lookup service which will
        // allow to check network state for sure
    #if __IPHONE_OS_VERSION_MIN_REQUIRED
        BOOL shouldSuspectWrongState = self.reachabilityStatus != PNReachabilityStatusReachableViaCellular;
    #else
        BOOL shouldSuspectWrongState = YES;
    #endif
     
        // In case if server report that there is connection
        if ([self isServiceAvailableForStatus:self.reachabilityStatus] && shouldSuspectWrongState) {
     
            __block __pn_desired_weak __typeof(self) weakSelf = self;
            dispatch_async(dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_DEFAULT, 0), ^{
     
                NSError *requestError;
                NSHTTPURLResponse *response;
                NSMutableURLRequest *timeTokenRequest = [[NSMutableURLRequest alloc] initWithURL:[NSURL URLWithString:[PNNetworkHelper originLookupResourcePath]]];
                timeTokenRequest.timeoutInterval = kPNReachabilityOriginLookupTimeout;
                NSData *downloadedTimeTokenData = [NSURLConnection sendSynchronousRequest:timeTokenRequest returningResponse:&response error:&requestError];
    //            [[NSURLCache sharedURLCache] removeCachedResponseForRequest:timeTokenRequest];
     
                dispatch_async(dispatch_get_main_queue(), ^{
     
                    [weakSelf handleOriginLookupCompletionWithData:downloadedTimeTokenData response:response error:requestError];
                });
            });
        }
    }

    All pretty standard, but since the bug was there, and I know that blocks within blocks can lead to retain cycles, I tried to make sure there weren’t any, that were causing this issue.

    I went through several iterations of turning the requestError, response, and downloadedTimeTokenData into weak references, and then back into strong ones, to see if any change to those would fix this 1.58 kb leak. I tried moving the declarations of the objects outside both blocks, and several other things that would break a retain cycle if it existed, but nothing I was doing worked.  The problem didn’t seem to be a retain cycle.

    My next step was the always helpful google searching. I searched for  various combinations of sendSynchronousRequest, dispatch_async, iOS Block… and so on trying to see if anyone else had this strange issue.

    I finally found  which the comments pointed to NSURLCache as being the culprit.

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    
    diff --git a/iOS/iPadDemoApp/pubnub/libs/PubNub/Network/PNReachability.m b/iOS/iPadDemoApp/pubnub/libs/PubNub/Network/PNReachability.m
    index ee4fdcc..bf457d5 100644
    --- a/iOS/iPadDemoApp/pubnub/libs/PubNub/Network/PNReachability.m
    +++ b/iOS/iPadDemoApp/pubnub/libs/PubNub/Network/PNReachability.m
    @@ -476,6 +476,7 @@ void PNReachabilityCallback(SCNetworkReachabilityRef reachability __unused, SCNe
                 NSMutableURLRequest *timeTokenRequest = [[NSMutableURLRequest alloc] initWithURL:[NSURL URLWithString:[PNNetworkHelper originLookupResourcePath]]];
                 timeTokenRequest.timeoutInterval = kPNReachabilityOriginLookupTimeout;
                 NSData *downloadedTimeTokenData = [NSURLConnection sendSynchronousRequest:timeTokenRequest returningResponse:&response error:&requestError];
    +            [[NSURLCache sharedURLCache] removeCachedResponseForRequest:timeTokenRequest];
     
                 dispatch_async(dispatch_get_main_queue(), ^{

    After a simple addition of removeCachedResponseForRequest, after the sendSynchronousRequest I was able to fix the 1.58kb heap growth every 10 seconds.

    For more information on using the Mark Generation tool, or instruments in general, check out the WWDC 2013 session 410 “Fixing Memory Issues”.