Recipe: Obj-C Message Tracing

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

Core Datasample project

Source : thecocoamag[dot]com