Objective-C: Using dtrace to trace messages-to-nil

Update: There are [at least] two different Objective-C messagers. objc_msgSend() and objc_msgSend_stret(). All of what is written here applies to both however objc_msgSend_stret() is the problematic one when it comes to messages to nil; it is the one used to return structures and, thus, the one that does not necessarily guarantee a zero return.


In my last post on the subject, Adrian Milliner posted a short dtrace script that would log the backtrace for all invocations of objc_msgSend where the first paramater — the target — was nil.

The script is as follows:

pid$1::objc_msgSend:entry
/arg0==0/
{
  ustack();
}

Once saved to a file (in this case objc-nil-trace.d, the trace can be applied to any running Cocoa process via:

sudo dtrace -s objc-nil-trace.d <pid>

The <pid> argument should, obviously, be the process ID of the process to be traced.

It works well enough and is certainly faster than a conditional breakpoint in GDB (likely, orders of magnitude faster), but it is far from a complete solution.

The output will be a series of backtraces dumped upon entry into an objc_msgSend() call where the first argument is nil. Something like:

  0  18968               objc_msgSend:entry 
              libobjc.A.dylib`objc_msgSend
              AppKit`-[NSApplication _doOpenUntitled]+0x11f
              AppKit`-[NSApplication(NSAppleEventHandling) _handleCoreEvent:withReplyEvent:]+0x62
              Foundation`-[NSAppleEventManager dispatchRawAppleEvent:withRawReply:handlerRefCon:]+0x28f
              Foundation`_NSAppleEventManagerGenericHandler+0xdf
              AE`aeDispatchAppleEvent(AEDesc const*, AEDesc*, unsigned long, unsigned char*)+0x90
              AE`dispatchEventAndSendReply(AEDesc const*, AEDesc*)+0x2c
              AE`aeProcessAppleEvent+0xb1
              HIToolbox`AEProcessAppleEvent+0x26
....

The first issue is that the backtrace does not dump the selector that was being messaged when the trace was triggered. In some cases, the line number of the original code may not be recoverable or, even if recoverable, you may not have the source available.

Now, the dtrace scripting language is misleadingly simple. It looks kinda like a subset of C with a bit of qualification sugar available upon function invocation.

However, the runtime is considerable more complex. When a dtrace script runs, it is actually running within the kernel. While introspection of the inferior is possible, it requires diddling the inferior from afar, using the various dtrace commands to copy over bits of data, as needed. Actually executing code in the client — often required to introspect higher level constructs — is pretty much out of the question. Given that said execution would happen in a quite thoroughly unexpected thread, doing so is likely to be highly destructive.

So, to grab the actual selector being invoked, we need to copy the selector name from the inferior into the dtrace interpreter within the kernel.

Specifically, taking the script and changing it to the following will dump the actual selector that was sent to objc_msgSend(). It treats the SEL argument as a pointer to a standard C string. It is, but only by coincidence (and a coincidence that is unlikely to change any time soon). However, predictable coincidence is just fine for debugging purposes.

pid$1::objc_msgSend:entry
/arg0==0/
{
    printf("[<nil> %s]", copyinstr(arg1));
    ustack();
}

Well, almost.

Dtrace scripts — running in kernel land — have some serious limitations on the memory in the inferior they can access. In particular, a dtrace script cannot access data on pages of memory that are not currently active within the process at the time the script executes.

Which presents a problem. The actual selector’s name — the C string pointed to by arg1, the selector passed to objc_msgSend — is located on pages of memory in the dyld shared region. And this trips up dtrace in that the memory appears to almost never be resident. I say almost never because I had the rather head scratching moment where it was resident for about ten minutes. That was fun. Not.

However, setting the environment variable DYLD_SHARED_REGION to avoid causes the process to not use the shared cache. This, in turns, causes the pages that contain the selectors to remain in process and, thus, allows this rather seemingly simple dtrace script to dump the messages to nil. (Thank you, Greg!)

While this particular script does rather verbosely dump every single nil targeted invocation, it also dumps the stack trace at the time of invocation. Very useful.

Aside: objc_msgSend()‘s return cannot be traced via dtrace at this time. Not surprising given that the function doesn’t actually return — as far as dtrace is concerned, it is nothing but preamble.

Next post on this subject? Do the same thing in Instruments.



6 Responses to “Objective-C: Using dtrace to trace messages-to-nil”

  1. Bryan Cantrill says:

    Great stuff — and invaluable for Leopard DTrace users, I’m sure. Not sure if you’ve seen this or not, but we’re having a DTrace (un)conference in San Francisco in March, details of which are here. The Apple DTrace team will be there, so this will be an excellent opportunity to both swap tips, and to talk about potential Leopard-specific issues and enhancements…

  2. Michael Tsai - Blog - Logging Messages to Nil says:

    […] Update: Bumgarner shows how to do the logging using Leopard’s DTrace. […]

  3. Adrian Milliner says:

    Cool, and great tip on DYLD_SHARED_REGION. Thanks.

  4. bbum’s weblog-o-mat » Blog Archive » Objective-C: Using Instruments to trace messages-to-nil says:

    […] This work is licensed under a Creative Commons Attribution-NonCommercial-ShareAlike 2.5 License. Amazon.com Widgets « Objective-C: Using dtrace to trace messages-to-nil […]

  5. Daniel Delwood says:

    It’s also quite fun to drop the info in an aggregate to get an idea of how many messages there are from certain points in the app’s code, as well as just checking the overall number of calls to each selector. Remove the printf() line if you don’t care about seeing the events go by in real time. The index at the beginning of the events is because dtrace can report out of order data; with that index, you can always re-assemble the order of the nils to see if there’s a chain you’re interested in.

    $ sudo dtrace -s nil.d -p

    File: “nil.d”
    ——

    #pragma D option quiet
    
    BEGIN
    {
            globalNilMsgIndex = 0;
            globalVtime = vtimestamp;
            globalWtime = walltimestamp;
    }
    
    pid$target::objc_msgSend:entry
    / arg0 == 0 /
    {
            this->mIndex = ++globalNilMsgIndex;
    
            printf("%7d: [nil %s] (thread: %08x)\n", this->mIndex, copyinstr(arg1), tid);
            @nilAgg[ustack()] = count();
            @selCounter[copyinstr(arg1)] = count();
    }
    
    END
    {
            printf("Nil-calling sites:\n");
            printa(@nilAgg);
    
            printf("Selectors frequently sent to nil:\n");
            printa(@selCounter);
    }
    
  6. bbum’s weblog-o-mat » Blog Archive » Objective-C: Printing Class Name from Dtrace says:

    […] and the name of the method that is about to be forwarded (Huge thanks to Daniel Delwood — who commented on this entry with something very very useful — for boatloads of help on […]

Leave a Reply

Line and paragraph breaks automatic.
XHTML allowed: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>