June 3, 2010

NSLog & Performance

Filed under: Uncategorized — Keith Lazuka @ 3:12 pm

Recently I started working on a project that used NSLog extensively. When building for the device/release, stderr was redirected to a file so that everything logged through NSLog was written to a file in the app’s Documents directory.

Preliminary Analysis

I was asked to look into some performance problems, and the first thing that I noticed was that a significant amount of time was spent spinning on malloc’s OSSpinLock. So then I looked at the heap allocation history and noticed that, in this app, there were hundreds of thousands of small, short-lived allocations attributed to NSLog during this time period. Further sampling showed that a significant amount of CPU time was being spent in functions with NSLog somewhere on the callstack.

Quick Check

Given this information, the first order of business was to prove that NSLog was indeed the root cause of the performance problems. So I decided to turn every NSLog call into a nop. This is pretty easy to do if you have a single header file that each source file in your project includes. In my case, there was no such explicit shared header, but in a situation like this where you are just making a quick hack, you can use the project’s precompiled header. So I temporarily inserted the following line into the pch file:

#define NSLog(fmt, ...)  ((void)0)

Next I rebuilt the project and did my performance assessment. I observed that performance had markedly improved–I had found the culprit.

More Analysis

So why was NSLog causing such performance degradation and why was it creating so many memory allocations? Doesn’t it just do string formatting and write the output to stderr? Let’s see what’s happening here:

First, let’s set some Bash variables to make this easier to read and type:

$ OTOOL=/Developer/Platforms/iPhoneOS.platform/Developer/usr/bin/otool
$ FOUNDATION=/Developer/Platforms/iPhoneOS.platform/Developer/SDKs/iPhoneOS3.0.sdk/System/Library/Frameworks/Foundation.framework/Foundation

Now let’s see how NSLog is implemented:

bogrov:~ $ $OTOOL -toV -arch armv6 $FOUNDATION | grep -B0 -C24 'NSLog:'
_NSLog:
305666d4	    b40f	push	{r0, r1, r2, r3}
305666d6	    b580	push	{r7, lr}
305666d8	    af00	add	r7, sp, #0
305666da	    b081	sub	sp, #4
305666dc	    ab03	add	r3, sp, #12
305666de	    a904	add	r1, sp, #16
305666e0	    cb04	ldmia	r3!, {r2}
305666e2	    1c10	adds	r0, r2, #0
305666e4	    9203	str	r2, [sp, #12]
305666e6	    9300	str	r3, [sp, #0]
305666e8	f000f805	bl	_NSLogv
305666ec	    b001	add	sp, #4
305666ee	    bc80	pop	{r7}
305666f0	    bc08	pop	{r3}
305666f2	    b004	add	sp, #16
305666f4	    4718	bx	r3
_NSLogv:
305666f6	    b5f0	push	{r4, r5, r6, r7, lr}
305666f8	    af03	add	r7, sp, #12
305666fa	    b082	sub	sp, #8
305666fc	    1c04	adds	r4, r0, #0
305666fe	    2000	movs	r0, #0
30566700	    1c0d	adds	r5, r1, #0
30566702	f7deff2d	bl	_NSPushAutoreleasePool

As you can see at address 0x305666e8, NSLog calls NSLogv. So let’s take a look at that.

bogrov:~ $ $OTOOL -toV -arch armv6 $FOUNDATION | grep -B0 -C48 'NSLogv:'
_NSLogv:
305666f6	    b5f0	push	{r4, r5, r6, r7, lr}
305666f8	    af03	add	r7, sp, #12
305666fa	    b082	sub	sp, #8
305666fc	    1c04	adds	r4, r0, #0
305666fe	    2000	movs	r0, #0
30566700	    1c0d	adds	r5, r1, #0
30566702	f7deff2d	bl	_NSPushAutoreleasePool
30566706	    4b12	ldr	r3, [pc, #72]	(0x30566750)
30566708	    447b	add	r3, pc
3056670a	    681b	ldr	r3, [r3, #0]
3056670c	    1c06	adds	r6, r0, #0
3056670e	    2b00	cmp	r3, #0
30566710	    d00f	beq.n	0x30566732
30566712	    4910	ldr	r1, [pc, #64]	(0x30566754)
30566714	    4810	ldr	r0, [pc, #64]	(0x30566758)
30566716	    4479	add	r1, pc
30566718	    2200	movs	r2, #0
3056671a	    6809	ldr	r1, [r1, #0]
3056671c	    2304	movs	r3, #4
3056671e	    4478	add	r0, pc
30566720	    9400	str	r4, [sp, #0]
30566722	    9501	str	r5, [sp, #4]
30566724	f064eef4	blx	0x305cb510	; symbol stub for: __CFLogvEx
30566728	    1c30	adds	r0, r6, #0
3056672a	f7e1fc0e	bl	_NSPopAutoreleasePool
3056672e	    b002	add	sp, #8
30566730	    bdf0	pop	{r4, r5, r6, r7, pc}
30566732	    490a	ldr	r1, [pc, #40]	(0x3056675c)
30566734	    2200	movs	r2, #0
30566736	    4479	add	r1, pc
30566738	    2304	movs	r3, #4
3056673a	    6809	ldr	r1, [r1, #0]
3056673c	    2000	movs	r0, #0
3056673e	    9400	str	r4, [sp, #0]
30566740	    9501	str	r5, [sp, #4]
30566742	f064eee6	blx	0x305cb510	; symbol stub for: __CFLogvEx
30566746	    1c30	adds	r0, r6, #0
30566748	f7e1fbff	bl	_NSPopAutoreleasePool
3056674c	    b002	add	sp, #8
3056674e	    bdf0	pop	{r4, r5, r6, r7, pc}
30566750	    321c	adds	r2, #28
30566752	    07fc	lsls	r4, r7, #31
30566754	    bb12	cbnz	r2, 0x3056679c
30566756	    07f9	lsls	r1, r7, #31
30566758	    ce9b	ldmia	r6!, {r0, r1, r3, r4, r7}
3056675a	    0002	lsls	r2, r0, #0
3056675c	    baf2	revsh	r2, r6
3056675e	    07f9	lsls	r1, r7, #31

Regardless of whether it takes the branch at 0×30566710, it eventually calls _CFLogvEx. Fortunately we don’t have to disassemble _CFLogvEx because CoreFoundation is open source. So the quickest way to find the implementation of _CFLogvEx is to Google it: “_CFLogvEx site:opensource.apple.com”. This gives a result for CFUtilities.c

Now we can look at _CFLogvEx’s implementation in C rather than disassembled ARM machine code. Notice that _CFLogvEx doesn’t do much except ask CFString to create the formatted string and then calls __CFLogCString, which is defined in the same file.

__CFLogCString is at the heart of NSLog. It is responsible for constructing the timestamp banner at the beginning of each log message, writing the message to stderr (as expected), and sending the message to the console (see the asl_open, asl_set and asl_send function calls). My next question is what is ASL? It’s the Apple System Logging facility. So the next stop is Google to see if ASL is open-source. Google “asl_open site:opensource.apple.com” and you’ll see several matches. Bingo, the page for asl.c contains the definition of asl_open. Now it’s time to go down the rabbit hole and trace the ASL code out…

I’m not going to through each step of the wandering that I took, but if you start to follow the trail from the asl_* code, you’ll learn that each call to NSLog actually triggers 2 IPC messages to the notifyd process and 1 IPC message containing the log message to the syslogd process. After learning this, I ran our iPhone app in Instruments with the “Activity Monitor” instrument and noticed that when our app was experiencing the performance problems, the CPU was almost evenly divided between our app’s process, notifyd and syslogd.

Final Solution

Comforted by knowing that a call to NSLog is more involved than just a fprintf(stderr,…), I proceeded with writing my own simple replacement for NSLog that just handles the extra “%@” format specifier and writes it to stderr. Here is my implementation:

static NSDateFormatter *gFormatter;
void KLog(NSString *format, ...)
{
	va_list ap;
	va_start(ap, format);

	NSAutoreleasePool *pool = [[NSAutoreleasePool alloc] init];
	NSDate *now = [[NSDate alloc] init];
	OSSpinLockLock(&gFormatterLock);
	NSString *timestamp = [gFormatter stringFromDate:now];
	OSSpinLockUnlock(&gFormatterLock);
	NSString *content = [[NSString alloc] initWithFormat:format arguments:ap];
	const char *cc = [content cStringUsingEncoding:NSUTF8StringEncoding];
	const char *fmt = [content characterAtIndex:[content length]-1] == '\n' ? "%s %s" : "%s %s\n";
	fprintf(stderr, fmt, [timestamp cStringUsingEncoding:NSUTF8StringEncoding], cc);
	[now release];
	[content release];

	[pool release];
	va_end(ap);
}

Where gFormatter is defined elsewhere. Note that my implementation does not include the pid or thread id, simply because I didn’t need it.

Wrapping Up

Typically you don’t need to dive down into the implementation details, but I like to know what’s going on when I fix a problem. It takes more time, but you learn more about the system and it helps ensure that you fix the root cause and not a symptom.

There’s actually nothing wrong with NSLog with respect to performance, as long as you are using it in the way that it was intended to be used: to assist during development. If you are going to be making a lot of NSLog calls in a short amount of time, and if you are going to leave the NSLog calls in your production builds, you should consider writing your own logging function.

Keith Lazuka's Blog