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

Already on GitHub? Sign in to your account

Multiple memory leaks in DDLogMessage #21

Closed
cacofonix opened this Issue Feb 13, 2012 · 13 comments

Comments

Projects
None yet
3 participants

When running the profile over my application for iOS

  • XCode 4.2.1
  • No ARC
  • Using a custom log formatter (from the example in the docs)

I found a set of memory leaks in the DDLogMessage class

[DDLogMessage methodName]
[DDLogMessage threadID]
[DDLogMessage fileName]

Each of these methods alloc's a new string, assigns it to a member but then doesn't decrement the retain count at the end of the method

e.g.

  • (NSString *)methodName
    {
    if (methodName == nil && function != NULL)
    {
    methodName = [[NSString alloc] initWithUTF8String:function];
    }

    return methodName;
    }

the line with the alloc should have an autorelease at the end of it right?

@cacofonix cacofonix closed this Feb 13, 2012

Contributor

robbiehanson commented Feb 13, 2012

Arc is required. There should be a warning getting spit out when you compile that explains the situation. If your project is non-arc, then you need to flag the lumberjack files as arc in your Xcode project. See the warning pragma at the top of the file.

-Robbie Hanson
Sent from my iPhone

On Feb 12, 2012, at 9:00 PM, suhailduttareply@reply.github.com wrote:

When running the profile over my application for iOS

  • XCode 4.2.1
  • No ARC
  • Using a custom log formatter (from the example in the docs)

I found a set of memory leaks in the DDLogMessage class

[DDLogMessage methodName]
[DDLogMessage threadID]
[DDLogMessage fileName]

Each of these methods alloc's a new string, assigns it to a member but then doesn't decrement the retain count at the end of the method

e.g.

  • (NSString *)methodName
    {
    if (methodName == nil && function != NULL)
    {
    methodName = [[NSString alloc] initWithUTF8String:function];
    }

    return methodName;
    }

the line with the alloc should have an autorelease at the end of it right?


Reply to this email directly or view it on GitHub:
robbiehanson#21

Hey - Thanks for the response

I intentionally used the 1.2 branch - your docs suggest that it is a viable option for non ARC projects.
Do I still need to mark them as ARC?

Contributor

robbiehanson commented Feb 15, 2012

the line with the alloc should have an autorelease at the end of it right?

No. "methodName" is an ivar that is lazily initialized. It is properly released in the dealloc method.

I found a set of memory leaks in the DDLogMessage class

How did you find them? Instruments? Static analyzer?

I found them using Instruments

Address Category Event Type RefCt Timestamp Size Responsible Library Responsible Caller
0xb20a940 CFString (immutable) Malloc 1 00:03.213.078 16 Foundation -[NSPlaceholderString initWithFormat:locale:arguments:]
0xb20a940 CFString (immutable) CFRetain 2 00:03.213.097 0 Foundation -[NSPlaceholderString initWithFormat:locale:arguments:]
0xb20a940 CFString (immutable) CFRelease 1 00:03.213.098 0 Foundation -[NSPlaceholderString initWithFormat:locale:arguments:]

Stacktrace

8 MyApp -[DDLogMessage threadID] //Classes/Lumberjack/DDLog.m:1237
9 MyApp -[PSLogFormatter formatLogMessage:] //Classes/Lumberjack/PSLogFormatter.m:44
10 MyApp -[DDASLLogger logMessage:] //Classes/Lumberjack/DDASLLogger.m:58
11 MyApp __+[DDLog lt_log:]_block_invoke_1 //Classes/Lumberjack/DDLog.m:919

oscahie commented Mar 27, 2012

I'm getting this as well using my custom formatter, which is pretty much identical to the one described in the documentation. I'm also using the old non-ARC branch on a non-ARC project. Basically every logged string is leaking, or so says the instruments leaks tool. However these leaks only show up on the iPad 2, not on other devices such as the iPhone 4 or iPad 1 running the same iOS version (5.0). Perhaps it has something to do with the device having a dual core CPU.

Anyway, suhaildutta you marked the issue as closed, could you please share your solution?

@cacofonix cacofonix reopened this Mar 27, 2012

Actually - I closed the issue by mistake - I definitely see the leak when using Instruments

Sorry to give you the false hope of a solution - I basically just turn off logging in production - but would love to be able to fix and use this

Contributor

robbiehanson commented Mar 27, 2012

There are a couple things I can think of:

  1. Log statements that leak:
    DDLogVerbose(@"recv: %@", [[NSString alloc] init...);
  2. Formatters that leak:
    return [[NSString alloc] init...];

If you don't think it's either of these, could you please send me a sample project that reproduces the leak?

oscahie commented Mar 28, 2012

Ok, so I hadn't really given much thought to this since we also have logging disabled in production. But today I decided to get to the bottom of it and the problem is actually not hard to spot. The DDLogMessage accessors with lazily initialized variables are just not thread safe. For instance, the getter for the 'threadID' property is implemented as:

- (NSString *)threadID
{
        if (threadID == nil)
        {
            threadID = [[NSString alloc] initWithFormat:@"%x", machThreadID];
        }

    return threadID;
}

This method when accessed by multiple threads simultaneously is bound to leak memory sooner or later. And in my project I happen to have 3 separate loggers defined, so each log message sent down the pipeline has this method invoked 3 times. On single core devices the leaks might not ever happen but on dual core CPUs like that of the iPad 2 it does happen, and it happens a lot.

So the solution is to make these accessors thread safe, either by using a @synchronized block, or an NSLock or with dispatch_once() for instance. I've chosen the later method because allegedly there is a significant performance difference over synchronized blocks of code.

Therefore having declared a once-token in the DDLogMessage interface:

dispatch_once_t threadIdOnceToken;

the fixed threadID getter would look like this:

- (NSString *)threadID
{
    dispatch_once(&threadIdOnceToken, ^{
        if (threadID == nil)
        {
            threadID = [[NSString alloc] initWithFormat:@"%x", machThreadID];
        }
    });

    return threadID;
}

And just repeat the same procedure for the 'fileName' and 'methodName' accessors.

Happy logging!

Contributor

robbiehanson commented Mar 28, 2012

Wow! Great find!!!

There are 2 possible solutions to making the methods thread safe:

  1. Thread safe lazy initialization of instance variables (as you mentioned)
  2. Change the methods to alloc/init/return on demand without instance variables.

I.E.:

- (NSString *)threadID
{
    return = [[NSString alloc] initWithFormat:@"%x", machThreadID];
}

Using dispatch_once, unfortunately, isn't possible. From Apple's documentation on dispatch_once:

The predicate must point to a variable stored in global or static scope.
The result of using a predicate with automatic or dynamic storage is undefined.

In other words, the "onceToken" passed to dispatch_once can't be an instance variable.

We could use other techniques, such as @synchronized or NSLock's. But I believe, in this case, the costs of such devices outweigh the costs to simply compute the value on demand.

I did some benchmarking on this topic, testing simple creation-on-demand, vs other techniques. The best I found was using OSSpinLock. It fits the situation, as contention is generally low. Plus the spin lock itself doesn't require initialization (vs things like NSLock). However, it's still more costly when only using a single logger. And doesn't save a significant amount of time when using multiple simultaneous loggers.

Add to this that, for the majority of developers, only a single logger is being used most of the time.

So I've fixed the bug using code similar to the threadID method I posted above.

Side Note: The fastest possible solution is to not use logMessage.threadID or logMessage.methodName in your custom formatter. Instead just use the same printf style within your own code. For example:

return [NSString stringWithFormat:@"...%x...", ..., logMessage->machThreadID, ...];

And for logMessage.fileName, you may be able to speed up your custom formatter by caching the results of these calculations.

oscahie commented Mar 28, 2012

You are right! This is not a good use case for dispatch_once(), bad idea.

BTW you need to add an autorelease message to those allocated strings in your fix!

Contributor

robbiehanson commented Mar 28, 2012

I've pushed the changes to master (ARC).

I'm trying to discourage people from using the deprecated non-arc 1.2.X branch. I don't have any desire to maintain both an arc and non-arc branch. With Xcode, it's so easy to mix and match, so there's no reason for library developers to go through such troubles. And it seems clear ARC is the future. So I'm extremely reluctant to push any changes to the 1.2.X branch. (Lest people think it's actively maintained.) Is there any reason you're not using the latest branch?

Its easy enough to port your fix to my local branch

The main reason I haven't changed over to using ARC is the required testing
time with the combination of phonegap and other libraries we use - there
are quite a few.
(mix and match might be a viable option)

On Wed, Mar 28, 2012 at 2:09 PM, Robbie Hanson <
reply@reply.github.com

wrote:

I've pushed the changes to master (ARC).

I'm trying to discourage people from using the deprecated non-arc 1.2.X
branch. I don't have any desire to maintain both an arc and non-arc branch.
With Xcode, it's so easy to mix and match, so there's no reason for library
developers to go through such troubles. And it seems clear ARC is the
future. So I'm extremely reluctant to push any changes to the 1.2.X branch.
(Lest people think it's actively maintained.) Is there any reason you're
not using the latest branch?


Reply to this email directly or view it on GitHub:

robbiehanson#21 (comment)

oscahie commented Mar 28, 2012

I actually attempted to update to the latest version in trunk some months ago but experienced some rare crashes and ended up rolling back to 1.2 in order to not compromise our testing. I guess I might give it another try.

Also all our code is non-ARC yet so it is still kinda confusing for me to deal with ARC code :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment