Dtrace
dtrace is a tool on Mac OS X (and BSD) to log which system call are made by an application. It allows you to get an overview what an application is doing "behind the scenes".
- DTrace User Guide by Oracle
- DTrace Quick Start Guide by Oracle
- Exploring OS X with dtrace by Mac OS X hints
- Exploring Leopard with DTrace - How to use DTrace for debugging and exploration by MacTech Magazine
SystemTap is an alternative to dtrace for Linux kernels.
Contents
Examples
Here are a few example DTrace scripts, taken from the MacTech article
Print Open Files
#!dtrace -qs
syscall::open*:entry
{
printf("%s %s\n", execname, copyinstr(arg0));
}
or
sudo dtrace -n 'syscall::open*:entry { trace(execname); trace(copyinstr(arg0)); }'
(Here, we use trace() instead of printf(), and don't use the -s flag that silence dtrace a bit, so we now see CPU, probe ID and function name too.)
To print only files for a given process ID (PID), call this script as openfiles.d 1234 (with 1234 the PID of some process):
#!dtrace -qs
pid$1::open*:entry
{
printf("%s %s\n", execname, copyinstr(arg0));
}
To print only files for a process with the given name, call this script as openfiles.d "Safari":
#!/usr/sbin/dtrace -qs
syscall::open*:entry
/ execname == $$1 /
{
printf("%s\n", copyinstr(arg0));
}
To print all system calls (including file I/O), use dtruss:
dtruss myapplication
To print all opened files, use `iosnoop` or `opensnoop`:
opensnoop -n myapplication
Time Spend in Each Function
#!/usr/sbin/dtrace -s
pid$1:::entry
{
self->ts[probefunc] = timestamp;
}
pid$1:::return
/self->ts[probefunc]/
{
@func_time[probefunc] = sum(timestamp - self->ts[probefunc]);
self->ts[probefunc] = 0;
}
This script stores the timestamp in an array called ts for each function, and sums the total time spend. The self-> construct makes sure that each thread uses a different ts variable.
In order to print a histogram of the times, use the quantize() aggregation function:
#!/usr/sbin/dtrace -s
pid$1:::entry
{
self->start = timestamp;
}
pid$1:::return
{
@ = quantize(timestamp - self->start);
}
Count the Number of Function Calls
sudo dtrace -q -n 'syscall:::entry / execname == "thunderbird" / { @count_table[probefunc] = count(); }'
Count the Number of Context Switches
On Solaris:
sudo dtrace -n 'sysinfo:::pswitch { @[execname] = count(); }'
On Mac OS X, I had to experiment a bit to find the correct function call:
sudo dtrace -n 'fbt::*switch:entry { @[probefunc,execname] = count(); }'
Print a Stack Trace
#!/usr/sbin/dtrace -s
syscall::open:entry
/pid == $1/
{
self->path = copyinstr(arg0);
}
syscall::open:return
/self->path != NULL && arg1 == -1/
{
printf("open for ’%s’ failed", self->path);
ustack();
}
Probes and Predicates
General Syntax
DTrace rules are written in the D language. The general syntax of a rule is:
probe descriptions
/ predicate /
{
action statements
}
The probe description is either a keyword like BEGIN or a 4-tuple written as provider:module:function:name. In here:
- provider
- Specifies the layer that is instrumented. E.g. "syscall"
- module
- Describes the module that is instrumented. E.g. "libsystem_c.dylib"
- function
- Describes the function that is instrumented. e.g. "open" or "open*"
- name
- Typically represents the location in the function, e.g. "entry" or "return"
Providers
Here are some interesting providers:
| Provider | Explanation |
|---|---|
| syscall | System calls in the kernel |
| fbt | (Function Boundary Tracing) - Functions in the kernel |
| proc | Functions related to the process life cycle |
| mach_trap | Mach traps in the kernel |
| sched | CPU scheduler |
| vminfo | virtual memory |
| io | disk I/O |
| ip | Network IP stack |
| tcp | Network TCP connections |
| pid1234 | C functions (or individual instructions) in user space for process with PID 1234 |
| magmalloc1234 | memory allocations for process with PID 1234 |
| garbage_collection1234 | memory garbage collection for process with PID 1234 |
| security_debug1234 | security events for process with PID 1234 |
| CoreDate1234 | Functions in the Core Data libary for process with PID 1234 |
| NSApplication1234 | Functions in the Cococa Application libary for process with PID 1234 |
| JavaScriptCore1234 | Functions in the JavaScript libary for process with PID 1234 |
| QuartzComposer1234 | Functions in the Quartz Composer libary for process with PID 1234 |
To display all possible providers, run:
dtrace -l | less
The less is there for a reason: my Mac OS X system has just over 270000 publishers.
Script Parameters
For scripts, it is recommended to use argument substitution for the PID:
#!/usr/sbin/dtrace -s
pid$1:::entry
{}
Predicates
Typical predicates are:
| Action | Explanation |
|---|---|
| / cpu == 0 / | True if the probe executes on cpu0 |
| / pid == 1029 / | True if the pid of the process that caused the probe to fire is 1029 |
| / uid == 123 / | True if the probe is fired by a process owned by userid 123 |
| / execname == "mysql" / | True if the probe is fired by the mysql process |
| / execname != "sched" / | True if the process is not the scheduler (sched) |
| / ppid !=0 && arg0 == 0 / | True if the parent process id is not 0 and the first argument is 0 |
Actions
Typical actions are:
| Action | Explanation |
|---|---|
| trace() | |
| printf() | Print something using C-style printf() command |
| ustack() | Print the user level stack |
| stack() | Print the kernel level stack |
Typical aggregate functions are:
| Action | Explanation |
|---|---|
| count() | Count the number of times the probe was called |
| sum(var) | Adds the values of variable for each call |
| avg(var) | Displays the average value |
| min(var) | Displays the minimum value |
| max(var) | Displays the maximum value |
| quantize(var) | Print a histogram of |
Variables
Predefined variables you can access are:
| execname | The name of the current process |
| probeprov | The name of the provider |
| probemod | The name of the module |
| probefunc | The name of the function |
| probename | The name of the probe |
| arg0, ..., arg9 | The memory location of the first ten arguments of the function call. Use copyinstr(arg0) to display the argument as text. |
| cpu | CPU identifier |
| tid | Thread identifier |
| cwd | Name of the current working directory |
| uid | User ID |
| gid | Group ID |
| pid | Process ID |
| ppid | Parent process ID |
| walltimestamp | time in nanoseconds since January 1, 1970 |
| vtimestamp | time given to the current proccess since it was started (this excludes time spend in other processes) |
| errno | The error value returned by the last system call executed by this thread |
| stackdepth | The depth of the current stack trace |
