Dtrace

From Exterior Memory
Jump to: navigation, search

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".

SystemTap is an alternative to dtrace for Linux kernels.

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() Print
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