iPhone SDK: The price of logging

February 18, 2009 at 5:48 am (iPhone development) (, , , , , )

While working on a few run-throughs of my currently in-development iPhone game, I came across a performance issue.  When I started playing, the game was pretty zippy…but with each turn it would continue to get slower.  And not just a little slower, a lot slower.  At first a turn might take .2 seconds or so, but by turn 6 or 7 it was up to around 4 seconds to process a turn.  What was going on?  Why am I bothering to share this with the world?

It turns out that the logging was updating a UITextView for each NSLog call, so that a player could tap on a tab and see all the results of the computer resolving all the spells.  Once there is more than one or two spells in play, a single turn could contain maybe 25-30 logging calls.  Each call would copy the whole text out of the UITextView control, append a line to it, then set the text value.  This became incredibly cpu intensive, and was slowing down the app way more than I would have ever imagined.  The instrument panel showed me everything.

system load with unbuffered logging

I was really horrified at how long a single UITextView.text = @”really long multiline multiparagraph log-like string” line can take.  It seems to me that one of the most common use cases is to append text to a control, so being forced to copy the text out, append to it, then copy it back in is really slow and painful.  Is there not a better way?  really?  It’s 2009, do I need to write this kind of control buffering myself?  Apparently, yes.

And it’s worth noting, this only became apparent while running and debugging the app on a device.  The performance issue never really showed up in the simulator, and even once I identified it, the simulator was useless even with the instrument panel.  As much as I love the simulator, and I really do, for performance work don’t waste your time.

So, the solution?  I went with the simple and obvious: create a buffered log.  I only update the LogView when I commit the buffer, while the NSLog calls still go to the console immediately.  Works like a champ!

system load with buffered logging

R.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: