I lied. Sorry. I thought this dive into DTrace would be a three-parter, but here’s a part 4, on static probes, suggested in a comment by Chris last month.

You can go a long way with the built in DTrace providers, like the syscall, pid, and [objc][/objc]objc providers. But sometimes it would be nice to examine program behavior with a higher-level semantic meaning. That’s just a fancy way of saying “I want to know what this program is doing” without having to tease it out of sequence of function or method calls.

There’s not really any way to get that information from DTrace directly, so your program (or library) needs a way to tell DTrace “Hey, the user clicked on Finland” or “Hey, CoreData just had to fetch 30 bazillion objects.” Luckily there’s a way to do that, otherwise this would be a very short posting. It’s also surprisingly easy.

Heavy Metal

Last year I used a little program that showed off delegation and datasources using a world map:

You can get the code from the WorldMapView github.

Wouldn’t It Be Cool to know what countries the user is clicking on most? As it stands now, you can’t really do that with DTrace. Sure, you can use the objc provider to catch mouse downs or calls to the -selectedCountryCode delegate method, but the program uses NSStrings for the country codes that are passed around, and you can’t call arbitrary Objective-C methods (such as UTF8String) from inside of DTrace to see what the string actually contains.

One way to do it is to make your own static probes. These are functions you explicitly call inside your program or library that tell DTrace “Hey, if you’re interested in country-clicking, someone just clicked on FI.” You can then put a DTrace probe on country-clicks, and all the other data available in DTrace is at your disposal like stack traces and timestamps. You can ask questions such as “What was the average time between clicks on Madagascar before the borders were closed?”

Step 1 : Describe your Probes

Make a .d file that describes the probes you’re adding. The one for WorldMap is pretty simple:

provider BNRWorldMap {
    probe country_clicked (char *);
};

The provider is called BNRWorldMap, and is suffixed with a process number when used in a DTrace script. The probe’s name is country_clicked. Its arg0 will be the address of a C string of the country code that was clicked on. You can provide any arguments you want. Integer-compatible values are passed directly, and you’ll need to use a copyin action for others (such as getting the C string for the clicked-on country code). You can have any number of individual probes here.

In a DTrace script you’d use it like this:

# dtrace -n 'BNRWorldMap$target:::country_clicked' -c ./WorldMap.app/Contents/MacOS/WorldMap
dtrace: description 'BNRWorldMap$target:::country_clicked' matched 1 probe
CPU     ID                    FUNCTION:NAME
  1 166855 -[BNRWorldMapView mouseDown:]:country_clicked
  1 166855 -[BNRWorldMapView mouseDown:]:country_clicked
  2 166855 -[BNRWorldMapView mouseDown:]:country_clicked
  1 166855 -[BNRWorldMapView mouseDown:]:country_clicked

If you wanted to get at the actual country code, you’d use copyinstr, passing it arg0, to get the C string copied to kernel space as described in part 1.

Step 2: Make the Header

You can’t include that .d script directly in Objective-C code. You’ll need to generate a header file that you can #import. Xcode will do that automatically if you drag the .d file into your project – things will Just Work. If you want to make a header yourself you can tell dtrace to do it:

% dtrace -h -s WorldMapProbes.d

You can then look at WorldMapProbes.h and see what it’s doing. It’s kind of cool poking around in there to see what’s going on. dtrace generates two macros for each probe specified in the .d file:

BNRWORLDMAP_COUNTRY_CLICKED_ENABLED returns true if DTrace has been commanded to monitor country_clicked probes in this process. You can use this to gate any expensive work you might want to do when constructing the data you’ll be passing back to DTrace, but otherwise wouldn’t be necessary.

BNRWORLDMAP_COUNTRY_CLICKED is what you call to tell DTrace that something interesting happened. In this case, a country getting clicked. You pass it the parameters you promised in the WorldMapProbes.d file.

Using them is very straightforward:

if (BNRWORLDMAP_COUNTRY_CLICKED_ENABLED()) {
        BNRWORLDMAP_COUNTRY_CLICKED (countryCode.UTF8String);
    }

You don’t have to check if the probe is enabled, but it’s generally a good idea. Notice that the UTF8 string is extracted from the NSString because DTrace doesn’t grok NSStrings.

Step 3: There is no step 3

Now you can build and run your program and see what you’ve created. Get a listing of the probes just to make sure everything got set up correctly:

# dtrace -l -n 'BNRWorldMap$target:::' -c ./WorldMap.app/Contents/MacOS/WorldMap   ID   PROVIDER            MODULE                          FUNCTION NAME
11892 BNRWorldMap51759          WorldMap     -[BNRWorldMapView mouseDown:] country_clicked

You can see that you provide the provider and name portion of the probe description, and DTrace fills in the module (the program name) and the function (where BNRWORLDMAP_COUNTRY_CLICKED is called). You can put the same probe in different functions or methods and have different specific probe points you can look at. I tossed a call into -isFlipped just for demonstration:

# dtrace -l -n 'BNRWorldMap$target:::' -c ./WorldMap.app/Contents/MacOS/WorldMap
   ID   PROVIDER            MODULE                          FUNCTION NAME
11892 BNRWorldMap51787          WorldMap      -[BNRWorldMapView isFlipped] country_clicked
11893 BNRWorldMap51787          WorldMap     -[BNRWorldMapView mouseDown:] country_clicked

Peer at arg0 and see what’s clicked:

# dtrace -q -n 'BNRWorldMap$target:::country_clicked { printf("clicked in %sn", copyinstr(arg0)); }' -c ./WorldMap.app/Contents/MacOS/WorldMap
clicked in US
clicked in FR
clicked in CN
clicked in AU
clicked in AU
clicked in US

OONGAWA!

OK, so that’s not much better than caveman debugging that you can turn on or off at runtime. You could get the same info with an NSLog inside of -mouseDown. How about doing something you can’t duplicate with NSLog? An interesting question might be “What are the most commonly clicked countries over the run of the program?”, a good use of DTrace aggregation. Here’s a script:

BNRWorldMap$target:::country_clicked
{
    @clicks[copyinstr(arg0)] = count();
}

Every time a country is clicked, the action body grabs the country code from arg0 and indexes an aggregate with it that is maintaining a count of clicks. (Refer back to part 3 if this sounds like gibberish.)

You can run it as a one-liner, click around the map, then interrupt dtrace with a control-C to get the output:

# dtrace -q -n 'BNRWorldMap$target:::country_clicked { @clicks[copyinstr(arg0)] = count(); }' -c ./WorldMap.app/Contents/MacOS/WorldMap
^C
  BR                                                                1
  FR                                                                1
  IT                                                                1
  SE                                                                2
  AU                                                                3
  US                                                                3
  CN                                                                6
  FI                                                               13

Bonus: Other static probes

One of the true joys of DTrace is serendipitous discovery of nerdy tools. You can list all of the probes, including the static probes, with a command like:

# dtrace -l ':::' -c ./WorldMap.app/Contents/MacOS/WorldMap > probes.txt

This produces about 185,000 lines of output for me, showing static probes for many applications in the system. I boiled down the providers inside of WorldMap:

BNRWorldMap
    Cocoa_Autorelease
    Cocoa_Layout
    CoreData
    CoreImage
    HALC_IO
    NSApplication
    NSTrackingArea
    RemoteViewServices
    cache
    codesign
    garbage_collection
    magmalloc
    objc_runtime
    opencl_api
    plockstat
    security_debug
    security_exception
    syspolicy

Some really cool stuff. Like with Cocoa autolayout (51038 is the process ID of the WorldMap program I took this listing from):

17016 Cocoa_Layout51038      AppKit  ConstraintDidPerformInitialSetup constraint_lifecycle
17017 Cocoa_Layout51038      AppKit -[NSLayoutConstraint setPriority:] constraint_lifecycle
17018 Cocoa_Layout51038      AppKit -[NSLayoutConstraint _setIdentifier:] constraint_lifecycle
17019 Cocoa_Layout51038      AppKit -[NSLayoutConstraint _setSymbolicConstant:constant:] constraint_lifecycle
17020 Cocoa_Layout51038      AppKit -[NSLayoutConstraint _addToEngine:roundingAdjustment:mutuallyExclusiveConstraints:] constraint_lifecycle
17021 Cocoa_Layout51038      AppKit -[NSLayoutConstraint _removeFromEngine:] constraint_lifecycle

So you could put a probe on constraint_lifecycle and see when its priority changes, or when it gets added to the layout engine.

There’s also probes on NSTracking area, to see when tracking areas are added, created, enabled and disabled, and removed.

objc_runtime can let you attach probes on exception throwing:

16007 objc_runtime51038   libobjc.A.dylib            objc_exception_rethrow objc_exception_rethrow
16008 objc_runtime51038   libobjc.A.dylib              objc_exception_throw objc_exception_throw

You could use ustack() to record the stack traces when something bad happens. Throwing a quick

[@"" stringByAppendingString: nil];

into WorldMapView’s -mouseDown forces an exception. Running with this command

# dtrace -n 'objc_runtime$target::: { ustack(); } ' -c ./WorldMap.app/Contents/MacOS/WorldMap

gives this stack from DTrace:

CPU     ID                    FUNCTION:NAME
  0  10864 objc_exception_throw:objc_exception_throw
              libobjc.A.dylib`objc_exception_throw+0x12f
              CoreFoundation`+[NSException raise:format:arguments:]+0x6a
              CoreFoundation`+[NSException raise:format:]+0x74
              Foundation`-[NSString stringByAppendingString:]+0x5b
              WorldMap`-[BNRWorldMapView mouseDown:]+0x85
              AppKit`-[NSWindow sendEvent:]+0x18a2
              AppKit`-[NSApplication sendEvent:]+0x15d9
              AppKit`-[NSApplication run]+0x22b
              AppKit`NSApplicationMain+0x363
              WorldMap`main+0x22
              WorldMap`start+0x34
              WorldMap`0x1

You don’t get file and line goodness, but sometimes this might be all the information you need for tracking down weird in-the-field problems.

Finally, CoreData provides a number of probes related to faulting:

BeginFault
    EndFault
    BeginFaultCacheMiss
    EndFaultCacheMiss
    BeginFetch
    EndFetch
    BeginRelationshipCacheMiss
    EndRelationshipCacheMiss
    BeginRelationshipFault
    EndRelationshipFault
    BeginSave
    EndSave

Which you can experiment with to watch your CoreData behavior. This is what the CoreData instrument is based on, by the way.

That’s All Folks, for real

I was actually shocked and amazed at how easy it was to make custom DTrace probes. I had put off learning about them for years assuming it’d time consuming figuring them out. Can’t get much easier than building a small D script, dropping it into Xcode, and invoking one of the generated macros.