Torsten Curdt’s weblog

Instruments and DTrace are extremely valuable tools for inspecting your software and to track down problems. Be it memory leaks or performance bottlenecks. Let me walk you through a real profiling session here.

Sometimes I was surprised about how long it takes for the FeedbackReporter dialog to come up. While I have already suspected from the logs this might be related to the console log gathering I gave the CPU Sampler template in Intruments a go. From inside Xcode you can just pick it from Start with Performance Tool. It fires up Intruments and while you use you application it records the application’s activity. As you can see from the timeline there was a big spike when opening the FeedbackReporter dialog. After I tweaked the Call Tree settings it clearly showed the callstack and with it – the method that uses up more than 70% of the CPU time. Obviously +[ConsoleLog:logSince:] is quite busy here. Unfortunately Instruments does not show exactly busy with what. (I wish you could just drill down further!) So in order to dig a little deeper you can create a custom instrumentation.
I am only interested of what happens inside the ConsoleLog class. The code in +[ConsoleLog:logSince:] basically just calls out to the Apple System Logger. So only those functions I care about.

objc9447:ConsoleLog::entry
{
        self->follow = 1;
}
pid9447::asl_*:entry
/self->follow/
{
        printf("%Y %s %s\n", walltimestamp, probemod, probefunc);
}
objc9447:ConsoleLog::return
/self->follow/
{
        self->follow = 0;
}

The above DTrace script shows how to print a timestamp on all ASL calls within ConsoleLog. (You can run it with “sudo dtrace -s mytrace.d”. But you have to adjust the pid first!) It creates a context to reduce the number of probes and then filters on all method entries that start with “asl_”. To be more precise you would probably also want to record return not just the entry times as well. But that’s good enough for now.

While I am a terminal guy myself you can also model this script inside instruments. Create a new instrumentaion and then add the different parts of the script like this:

When you now run another Instruments session you get the timestamps of all the different ASL calls.

There is a lot of things you can do with DTrace and Instruments. I hope this helped you get started. For FeedbackReporter it means that querying the ASL subsystem can be quite slow. It would be better to run it in the background. Well, maybe in the next release :)

12. August 2008 | cocoa, dtrace, instruments, profiling