Recipe: Obj-C Message Tracing
Written by Allen Ding
Motivation
In a non-trivial application, wrapping your head around interactions between components in your codebase can be difficult. For example, consider delegation via formal protocols, a pattern that is pervasive in iOS frameworks. The interaction protocols for objects connected through delegation often involve numerous and layered sequences of method calls going back and forth between an object and its delegate. Though the iOS API documentation is generally excellent, a visual trace of the messages that are being sent can be very instructive.
In this article, we will take a look at some simple utility code that may assist you in understanding such interactions during your own development. This utility code behaves is as simple to use as NSLog, but with the addition that logged output will be shown with visual indentation that makes it easy to understand the message context in which the logging is taking place.
Result Preview
To start off with, let’s take a look at some sample usage and console output (timestamps have been omitted).
//--- Sample usage begin ---- (UITableViewCell *)tableView:(UITableView *)tableView cellForRowAtIndexPath:(NSIndexPath *)indexPath{TCM_TRACE_BEGIN();static NSString *CellIdentifier = @"Cell";UITableViewCell *cell = [tableView dequeueReusableCellWithIdentifier:CellIdentifier];if (cell == nil) {cell = [[[UITableViewCell alloc] initWithStyle:UITableViewCellStyleDefault reuseIdentifier:CellIdentifier] autorelease];TCM_TRACE(@"Created cell");}cell.textLabel.text = [NSString stringWithFormat:@"Row %d", indexPath.row];// Configure the cell.return cell;TCM_TRACE_END();}//--- Sample usage ends ---//--- Sample output begins ----[TCMTraceAppDelegate application:didFinishLaunchingWithOptions:]-[RootViewController shouldAutorotateToInterfaceOrientation:]-[RootViewController shouldAutorotateToInterfaceOrientation:]-[RootViewController viewDidLoad]-[RootViewController viewWillAppear:]-[RootViewController numberOfSectionsInTableView:]-[RootViewController shouldAutorotateToInterfaceOrientation:]-[RootViewController viewDidAppear:]-[RootViewController numberOfSectionsInTableView:]-[RootViewController tableView:numberOfRowsInSection:]-[RootViewController tableView:cellForRowAtIndexPath:]Created cell//--- Sample output ends --- The output above shows the messages sent by UIKit to a couple delegate objects (TCMTraceAppDelegate and RootViewController) when launching an app with a UITableView. The methods that end up in the log are those that we explicitly want to trace. Hopefully, you’ll agree that the visual trace makes the sequence and layering of calls made to the delegates easier to digest.
Here is more complex sample output obtained when running a modified version of the Core Data application template provided in the iOS 4.3 SDK.
//--- Sample output begins ----[CoreDataTracingAppDelegate awakeFromNib] -[CoreDataTracingAppDelegate managedObjectContext] -[CoreDataTracingAppDelegate persistentStoreCoordinator] -[CoreDataTracingAppDelegate managedObjectModel] Created managed object model Created persistent store coordinator Created managed object context-[CoreDataTracingAppDelegate application:didFinishLaunchingWithOptions:] -[RootViewController shouldAutorotateToInterfaceOrientation:] -[RootViewController shouldAutorotateToInterfaceOrientation:] -[RootViewController viewDidLoad]-[RootViewController viewWillAppear:] -[RootViewController numberOfSectionsInTableView:] -[RootViewController fetchedResultsController]-[RootViewController shouldAutorotateToInterfaceOrientation:]-[RootViewController viewDidAppear:]-[RootViewController numberOfSectionsInTableView:]-[RootViewController tableView:numberOfRowsInSection:]-[RootViewController tableView:cellForRowAtIndexPath:] Created a cell -[RootViewController configureCell:atIndexPath:]... (a cell was added here)-[RootViewController insertNewObject] -[RootViewController controllerWillChangeContent:] -[RootViewController controller:didChangeObject:atIndexPath:forChangeType:newIndexPath:] NSFetchedResultsChangeInsert -[RootViewController controllerDidChangeContent:] -[RootViewController numberOfSectionsInTableView:] -[RootViewController numberOfSectionsInTableView:] -[RootViewController tableView:numberOfRowsInSection:] -[RootViewController tableView:cellForRowAtIndexPath:] Created a cell -[RootViewController configureCell:atIndexPath:]... (a cell was deleted here)-[RootViewController tableView:commitEditingStyle:forRowAtIndexPath:] Deleted object -[RootViewController controllerWillChangeContent:] -[RootViewController controller:didChangeObject:atIndexPath:forChangeType:newIndexPath:] NSFetchedResultsChangeDelete -[RootViewController controllerDidChangeContent:] -[RootViewController numberOfSectionsInTableView:] -[RootViewController numberOfSectionsInTableView:] -[RootViewController tableView:numberOfRowsInSection:]//--- Sample output ends ---
Implementation overview
The mechanics of the implementation are trivial for the most part. We maintain a “trace depth” that is incremented when a method call we would like to trace is encountered and decremented at the end of the method. While logging, the current trace depth is used to properly format the output.
Every method we wish to trace will begin with TCM_TRACE_BEGIN() and must end with TCM_TRACE_END(). These paired macro statements will emit the current method’s name and set up a new log context for code executed within that method. We also have a macro called TCM_TRACE(format, …) for any additional log messages we would like to be output.
Additionally, let’s add the requirement that incorrectly paired TCM_TRACE_BEGIN() and TCM_TRACE_END() statements will not run so as to avoid unnoticed incorrect results. Implementing the TCM_TRACE_END() is slightly tricky because a method may have multiple return paths. We will engineer the solution so that missing this will result in a build error.
Having objects with automatic lifetimes and destructor calls as in (Objective) C++ is one solution, but we will keep our solution pure Objective-C. Luckily, Objective-C’s exception handling mechanism gives us what we need. TCM_TRACE_BEGIN() will expand to a dangling @try block that increments the trace depth and emits the current method. Similarly, TCM_TRACE_END() will close the previous @try block followed by a @finally block that ensures that decrements the trace depth. This approach takes care of the most common usage errors that might occur when using the macros. Yes, this is an abuse of the exception handling mechanism, but it does work rather well and should never be present in production code anyway.
The implementation of the actual logger class and some other housekeeping details are not particularly interesting and won’t be discussed here. Check the end of the article for the source.
Notes
You’ll notice that the implementation presented above expects the logging to be performed on a single thread. Extending it to be usable from multiple threads is possible, but I have never found a need to, and the interleaved output from multiple threads that might result would not be quite as useful for visualizing message traces. Note also that this isn’t actually an actual execution trace. For that, accessing the NSThread stack symbols API or using a tool like Instruments would be a better option.
Remember that behavior that is not explicitly specified in API documentation is behavior that is fair game for change later. You should never rely on observed behavior to infer guaranteed behavior of official APIs. The goal here was to develop a quick and dirty way of getting logging functionality to assist with comprehension and debugging. I personally find the most utility in this functionality when learning new APIs and quickly verifying expected interactions between my own classes.
Files
The files containing the implementation are TCMTrace(.h|.m).
The sample was developed in Xcode 4.0.1.
Simple sample project
Apress Book Excerpt – Building apps with Monotouch
Written by John W
Our friends at Apress gave us a copy of "Developing C# Apps for iPhone and iPad Using MonoTouch" to include an excerpt in this month's release. Take a look, and if you like it go buy the book. This excerpt is the CoreGraphics and Core Animation chapters. Take a... Continue reading this article…Rendevous with Open Source Cocoa
Written by Achal Aggarwal
Over the past 3 years, we have seen a lot of developers making the switch to iOS and quite recently to Mac development. Even though Objective-C has been around since the early 1980s, not many developers bothered to give it a try. Like it happens in every community, many developers have... Continue reading this article…Welcome to OUR Magazine
Written by John W
Hi, Welcome to The Cocoa Magazine. I started this magazine (I hesitate to call it that, since there will NEVER be a print component) because there was a clear lack of any such source for developers to get the best information available. Sure there's google, and it does ok, but my... Continue reading this article…Conversations With Greg: Occipital
Written by Greg Cerveny
For those that don't know Occipital, they're the team behind Red Laser (iTunes link), which was recently bought by Ebay not too long ago. Since then, they've gone on to launch 360 Panorama (iTunes link), a widely popular panoramic photo app for the iPhone. Greg Cerveny is currently working... Continue reading this article…UIGestureRecognizer Saves The Day
Written by Jonathan Hays (3Jacks Software, @cheesemaker)
So you’ve just finished implementing the latest, greatest application and for once, you feel that your design was kept intact through the entire project schedule. You’ve kept your objects oriented and your models viewed and controlled. You’ve put together a design that Donald Knuth himself would approve of. In short,... Continue reading this article…iPhone Programming 101: How To Make a Tip Calculator
Written by Ray Wenderlich
If you're completely new to iPhone programming and want to dive right in, this is the tutorial for you! In this tutorial, you'll get started with iPhone programming by making a tip calculator! Why make a tip calculator? First, it's one of the easiest exercises you can do, so it is a... Continue reading this article…Source : thecocoamag[dot]com
0 comments:
Post a Comment