Tuesday, November 8, 2011

Logging & Grand Central Dispatch

Grand Central Dispatch is a marvelous technology. It provides our application with a thread-pool, and various methods to execute code on the threads in that thread pool. And best of all, it automatically manages the thread-pool size based on some very detailed knowledge of what the rest of the system is doing.


However, issuing log statements from a dispatch queue can be confusing. To see what I mean, take a look at what a normal NSLog statement spits out:

2011-11-08 17:09:47.642 MyAppName[50662:707] My log statement

Most of this is pretty self-explanatory. But the stuff in [brackets] may need a bit of explanation. It is actually [<process_id>:<mach_thread_id_in_hex>].

In the past, the thread id would help make it easier to read log statements coming from multi-threaded code. For example:

2011-11-08 17:09:47:643 MyAppName[50662:707] Log from main thread
2011-11-08 17:09:47:643 MyAppName[50662:2303] Log from thread 2
2011-11-08 17:09:47:644 MyAppName[50662:550b] Log from thread 3

However, with GCD, every block of code we hand it will get executed on some random thread from the thread-pool.  Even if we tell GCD to execute the code on a serial queue, it very well may execute each block on a different thread (albeit in a serial fashion). For example, this code:

for (i = 0; i < count; i++)
{
    dispatch_async(mySerialQueue, ^{ NSLog(@"help me"); });
}

might give you this result:

2011-11-08 17:25:18:062 MyAppName[50706:4f07] help me
2011-11-08 17:25:18:062 MyAppName[50706:5603] help me
2011-11-08 17:25:18:064 MyAppName[50706:5107] help me
2011-11-08 17:25:18.062 MyAppName[50706:520b] help me
2011-11-08 17:25:18:066 MyAppName[50706:1a03] help me

Now add to this the fact that your application my have multiple dispatch queues, all running in parallel.  So it sometimes becomes difficult to follow the log statements coming from our code.

What would be more helpful is if we could replace the mach_thread_id with the gcd_queue_name (when available).

Using CocoaLumberjack and a DispatchQueueLogFormatter, this becomes a simple operation.

If you've never heard of CocoaLumberjack before, you should really go check it out. There's a TON of information and documentation available on the GitHub project page.

Then you simply apply a DispatchQueueLogFormatter and you can get output like this:

2011-11-08 17:25:18:062 MyAppName[myQueue] help me
2011-11-08 17:25:18:062 MyAppName[myQueue] help me
2011-11-08 17:25:18:064 MyAppName[myQueue] help me
2011-11-08 17:25:18.062 MyAppName[myQueue] help me
2011-11-08 17:25:18:066 MyAppName[myQueue] help me


The log formatter comes with several different configuration options. But my favorite is the ability to set replacements for dispatch queue labels. For example, the main-thread has a queue label of "com.apple.main-thread". I find this to be a bit long, so I generally do something like this:

[formatter setReplacementString:@"main" forQueueLabel:@"com.apple.main-thread"];

Then I get:

2011-11-08 17:09:47:643 MyAppName[main] Log from main thread

Easy as cake!

1 comment:

Anonymous said...

It would be really great if you would post small example on how to use it (socket) with java server... I manage to connect and send message, but I can't receive from server on device (server sends response). Please help