Can NSLog change program output?


#1

I was doing the exercise on page 71 where NSLog is used to report calculator’s container. The code ran as described, with the following output:

2012-07-29 09:23:55.601 RandomPossessions[38510:403] Destroyed: Backpack (): Worth $0, recorded on 2012-07-29 13:23:55 +0000 2012-07-29 09:23:55.602 RandomPossessions[38510:403] Container: (null) 2012-07-29 09:23:55.604 RandomPossessions[38510:403] Destroyed: Calculator (): Worth $0, recorded on 2012-07-29 13:23:55 +0000

When I inserted a copy of the NSLog line to see what [calculator container] reported before the backpack was dealloc’d:

        NSLog(@"Container: %@",[calculator container]);
        backpack = nil;
        
        NSLog(@"Container: %@",[calculator container]);
        calculator = nil;

It changed the NSLog output unexpectedly. The calculator’s container isn’t reported as null anymore and it acts like the second NSLog statement is executed before setting backpack to nil even though it comes afterward in the code. Had I written the code this way originally, the NSLog output would lead me to believe backpack wasn’t getting the dealloc message.

2012-07-29 09:29:35.501 RandomPossessions[38603:403] Container: Backpack (): Worth $0, recorded on 2012-07-29 13:29:35 +0000 2012-07-29 09:29:35.502 RandomPossessions[38603:403] Container: Backpack (): Worth $0, recorded on 2012-07-29 13:29:35 +0000 2012-07-29 09:29:35.504 RandomPossessions[38603:403] Destroyed: Backpack (): Worth $0, recorded on 2012-07-29 13:29:35 +0000 2012-07-29 09:29:35.505 RandomPossessions[38603:403] Destroyed: Calculator (): Worth $0, recorded on 2012-07-29 13:29:35 +0000
I don’t understand why this happens and would welcome an explanation from anyone who can provide one.

Thanks.


#2

I’ll take an educated guess on what is happening here…

When an object has no owners, it will be destroyed, but that doesn’t mean the OS will drop everything it is doing and destroy the object immediately. There may be a time delay between when an object CAN be destroyed and when it actually IS destroyed. Your two NSLog() statements are both executing within that delay time, before the backpack object is actually destroyed.

It is possible that if you ran this program multiple times, you would see different results; sometimes the backpack would still exist, other times it would be destroyed. You can increase the likelihood that the backpack will be destroyed by adding some time-consuming code statements between the two NSLog() statements.

I am 99% certain that this is what is happening with your program.


#3

I am wondering about this one too. Even if I add some time-consuming code between the two NSLog() statements, it is still the same.
I have tried to put a breakpoint to each statement and run/debug each step, the “calculator’s container” does not become NULL (but if you remove the first NSLog() statement, it does).


#4

Nothing to do with time, really, but to do with ARC. ARC automatically inserts code into your code to handling retaining and releasing objects.

If ARC sees this:

- (void)method {
    NSObject *obj = [[NSObject alloc] init];

    [self doSomethingWithObject:obj];

    [self backflip];
}

Then it knows that the last time obj is used in this method is the doSomethingWithObject: statement, so it is safe to release it after that. It inserts that code:

- (void)method {
    NSObject *obj = [[NSObject alloc] init];

    [self doSomethingWithObject:obj];
    [obj release];
    [self backflip];
}

Of course, if you used it somewhere else down the line in that method, ARC won’t release it until then.

- (void)method {
    NSObject *obj = [[NSObject alloc] init];

    [self doSomethingWithObject:obj];

    [self backflip];
 
    NSLog(@"%@", obj); // obj referenced again!
    [obj release]; // has to happen here
} 

#5

This is so strange.

The output should have been:
2013-06-16 22:07:11.885 BNRItem[3180:303]BACKPACK( ) having as cost.Date of listing: 2013-06-16 16:37:11 +0000
2013-06-16 22:07:11.885 BNRItem[3180:303] Destroyed object: BACKPACK( ) having as cost.Date of listing: 2013-06-16 16:37:11 +0000
2013-06-16 22:07:11.886 BNRItem[3180:303] (null)
2013-06-16 22:13:31.696 BNRItem[3393:303] Destroyed object: CALCULATOR( ) having as cost.Date of listing: 2013-06-16 16:37:11 +0000

Still didn’t get it. Need some more clear explanation. :confused:


#6

[code] BNRItem *backpack = [[BNRItem alloc] init];
[backpack setItemName:@“Backpack”];
//[items addObject];

    BNRItem *calculator = [[BNRItem alloc] init];
    [calculator setItemName:@"Calculator"];
    //[items addObject:calculator];
    
    [backpack setContainedItem:calculator];
    
    // if the line below is commented out then calculator's container is nil
    // at the following NSLog statement, otherwise it still has a value after
    // the backpack reference is set to nil
    NSLog(@"Container: %@", [calculator container]);
    
    NSLog(@"Backpack: %@", backpack );
    backpack = nil;
    NSLog(@"Backpack has been set to nil");
    NSLog(@"Backpack: %@", backpack );
    
    NSLog(@"Container: %@", [calculator container]);
    
    calculator = nil;

[/code]

I’m finding the memory management odd as well. In the above code, if I print out [backpack Description] I get null, however the description of the calculator’s container (referencing the same backpack description) returns a value. And just by removing the first call to NSLog(@“Container: %@”, [calculator container]) both calls to the backpack’s description return null.

Could this be because the result of NSLog(@“Container: %@”, [calculator container]); is reused? Is there a way to ask an instance if it is set to be destroyed? Has anyone found a good explanation of this behavior?


#7

did you use __weak ? or are they strong references ?