Monday, August 17, 2009

It's NSLog, NSLog...

What rolls downstairs, alone or in pairs, and over your neighbor's dog?
What's great for a snack, and fits on your back? It's NSLog, NSLog, NSLog!

I do crazy amounts of logging in my programs. This has proven to be an invaluable tool for me as I learn how Cocoa/Cocoa Touch works. Being relatively new to Object-Oriented Programming, it has taken me a while to wrap my head around when methods get called, in what order, and so on. So I borrowed a technique I was using in the I-DEAS macro language in order to help me figure out what was happening:

NSLog(@"Now entering viewDidLoad in RootViewController");
// Do stuff
NSLog(@"Now leaving viewDidLoad in RootViewController");

The console will then present a nice history of what the program did. This is useful, especially for things like UITableView delegate methods, where simply putting the view on the screen can cause several methods to be triggered. Read back through the console, see which methods were called, note the order, learn how the system works.

I do both the 'entering' and 'leaving' part because simply putting the 'entering' one does not provide enough information, especially when trying to track down where a crash happened. A given method could branch out into any number of other methods, so without knowing when a method has finished, you don't really know which one crashed. You can make some partial assumptions by figuring out if expected methods were NOT called, but still, you don't get the complete picture. By adding the 'leaving' message, it's a matter of figuring out which method(s) started, but didn't finish.

The information provided by this technique is incredibly valuable, but it has (at least) two key drawbacks:

1. The log messages themselves must be customized for each method, in each class. You can get away with some copy-n-pasting, but you are going to have to retype something every single time. That's annoying, time consuming, and a good source for mistakes (if you forget to change the information).

2. The performance hit from displaying this many log messages is considerable, particularly on the iPhone. It's useful for debugging, but is not something you want to do for shipping code.

It's NSLog, it's NSLog... It's big, it's heavy, it's wood.
It's NSLog, it's NSLog, it's better than bad, it's good!

I was doing this - what I'll call "the hard way" - for while before I decided there had to be an easier way. I did some Googling, and landed on this page. There are several good tips there, but this is the important part:

NSLog(@"%s", __PRETTY_FUNCTION__);

Will print a log line similar to:

*2008-12-12 09:22:49.552 Healthcheck[79016:20b] -[HealthcheckAppDelegate applicationDidFinishLaunching:]*

Perfect. That is copy-paste-able, no additional typing required. However, I still want my entering/leaving deal, so adapting this to my preferred style:

NSLog(@">>> Entering %s <<<", __PRETTY_FUNCTION__);
// Do stuff
NSLog(@"<<< Leaving %s >>>", __PRETTY_FUNCTION__);

And I do this everywhere. Every single method. I'm not kidding.

Experienced programmers reading this are thinking I'm pretty ridiculous right now. But I need the extra help. And I highly, highly recommend this for people just getting started. I've been answering a lot of questions on iPhone Dev SDK, and am amazed at the number of people who know nothing about logging. And I don't mean noobs, I mean people with apps on the store! I'd probably still be floundering around with my very first bug without liberal use of logging. So, my hat's off to people who can get by without, but I have to assume that life could be easier for them.

Everyone wants a NSLog
You're gonna love it, NSLog

So that addressed the first problem, but what about the second? Fortunately, I got an answer to that without really even asking the question. After finding the pretty function thing, and posting on Twitter about how awesome that is, Danilo Campos was kind enough to make an off-hand remark that I should disable my log messages before submitting my app to the store. I had no idea how to do that, so with a couple of generous emails, he got me squared away. So full credit goes to him for this technique.

First, your program should have a *.pch file in it somewhere, named something like <YourAppName>_Prefix.pch. In my case, this file is SlickShopper_Prefix.pch. Add the following to that file:

#define NSLog(format, ...)
#define NSLog(format, ...) NSLog(format, ## __VA_ARGS__)

The 'DC' part is for Danilo Campos, so if you want to change that, you can. I've decided to leave it alone, along with a commented note giving him credit. Now I won't claim to totally understand what this says, but it looks like if DCBLOCKNSLOGSTATEMENTS is defined, do something to NSLog statements, if not, do something else. In this case, the 'do something' part is to make the NSLog statements not do anything, and the 'do something else' case is leave them alone. So that's the easy part. The harder part is getting this to work.

What you need to do now is mess with the settings in your build configurations panel. To do this, select your project, and hit the Info button, like so:

Next, go to the 'Build' tab, select the "Release" configuration, and do a search for "preprocessor". Ex:

You are looking for the ones listed under "GCC 4.2 - Preprocessing" - the "Preprocessor Macros" one and the "Preprocessor Macros Not Used In Precompiler" one. I occasionally cannot find these items. The solution seems to be to go to the 'General' tab. There is a pull-down menu next to "Base SDK for All Configurations". Set that to "iPhone Simulator 3.0", and then try searching again.

It is very important that you select the Release configuration. Do not do this in Debug. We're about to kill NSLog statements; we want those in Debug.

Now, double-click in the 'Value' column field next to Preprocessor Macros. A sheet will slide in.

Click the plus button to add a new value.

Paste in "DCBLOCKNSLOGSTATEMENTS" (or whatever you called it).

Hit OK...

...and then do the same thing for the second item.

And that's it. Just as a quick check, flip over to the Debug configuration:

You do NOT want to see the items we just added here.

If you have additional configurations already, say one for beta-testing and another for App Store submission, you will probably want to repeat these steps for those configurations as well.

Now test it out. Build-and-go with Debug, and observe your log messages. Do it again with Release, and observe the lack of log messages, and the snappier performance.

Next, head over to Danilo's web site and buy some of his apps as a thank you for making this technique known. And uh, if you want to buy mine for typing this up, well that'd be nice, too.

Have a better way? Let me know in the comments.

Everyone wants a NSLog. You're gonna love it, NSLog
Come on and get your NSLog. Everyone needs a NSLog
NSLog NSLog NSLog!


Danilo Campos said...

Cool writeup!

The one obvious catch with this method is that if you *want* log entries to be recorded in your shipping product, this all-or-nothing approach is much less helpful. Logging choice bits of your application state to the console could potentially be very useful down the road if you want to troubleshoot a bug with a user. It's a tough balance, though, because if you log too much, you'll see a noticeable performance hit.

You might combine this technique with another macro that prints logs no matter what, to selectively log certain events in production code. There are a million ways to skin this particular cowboy debugging cat. Here's proof:

David said...

Thanks for putting this all in one place.

Nice iphone application development said...

Hey thanks. I got where my error is :) Nice information.

WASD said...

Thanks, this is great!

Please, add "Share" button to your blog ;)