Profile Ruby 2.0 apps using DTrace - part 2

This is Part - 2 in series of articles we are writing on Dtrace. If you haven't already - do read Part 1.

Running Dtrace scripts

Before we delve deeper into guts of Dtrace, one of the questions which I often get asked is, How can I profile one off programs (i.e not a application running in background) with Dtrace.

There are basically couple of ways you can fire Dtrace.

One of them is obviously straight up sudo dtrace -[fmp] [name] which we kind of covered in last tutorial. Needless to say, you can't run dtrace scripts this way and hence is not very useful.
Second one is, you can supply Dtrace script as argument. This is useful for profiling long running applications (such as unicorn, thin)

~> sudo dtrace -qs <dtrace_script>.d

Third one is, which I am very fond is:

~> sudo dtrace -s count.d -c '/Users/gnufied/.rbenv/versions/20/bin/ruby leaky_app.rb'

What is a predicate?

In last part of tutorial we described what a probe description looks like. For a refresh:

probe description
/predicate/
{
    action;
}

Predicate is a way to filter the number of probes fired based on certain critirea. For example, in last tutorial we wrote a Dtrace script to keep track of all system calls being made by all currently running applications.

Lets say, now we want to restrict those probes only to system calls that are being made by Ruby applications. We can do this by introducing a predicate in our Dtrace script.

syscall:::entry
/execname=="ruby"/
{
	printf("%s(%d) called %s\n", execname, pid, probefunc);
}

Or you can use pid predicate:

/*
 * Print system calls made by pid 61465
 *
 */
syscall:::entry
/pid == 61465/
{
	printf("%s(%d) called %s\n", execname, pid, probefunc);
}

Now when I was learning Dtrace, I was mightly confused from where these things called execname, pid, probefunc are coming from? Turns out, Dtrace automatically provides built-in variable definitions for inspecting processes. They make Dtrace scripts quite powerful.

Built-in Variables

Here is a list of important built-in variables available in your DTrace scripts:

execname - Name of current process.
probeprov - Name of the probe provider (Read previous post about probes)
probemod - Name of the module in which probe is defined.
probefunc - Name of the function
probename - Name of the probe
arg0..arg9 - The function you are trying to probe likely takes arguments. For example, if you are profiling a Ruby program, you may be interesting in knowing about what kind of objects we are creating. When probes fire arguments accepted by the function (for which probe fired) are automatiaclly available as variables arg0 to arg9 in your DTrace script.
cpu - CPU identifier
tid - Thread identifier
cwd - Name of current working directory
uid - User ID
gid - Groupd ID
pid - Process ID
timestamp - Current Timestamp
errno - Set by system call errors

Now, I believe previous scripts would have started making sense. Above list does not include all built-in variables though.

Lets do an exercise and try to print number of bytes being read (from network or file system) by process with pid 61465. The script will look like:

syscall::read:entry
/pid == 61465/
{
    printf("%s read %d\n", execname, arg2);
}

If you crack open man 2 read you will find out that read system call's third argument contains number of bytes being read.

Having just ability to print numbers as probes fire is useful but you can easily imagine it would be nice, if we can somehow aggregate the data. For example, how much of your program's memory is taken by string allocation or how much time is being spent in total in the function foo. Ability to aggregate such data would be really useful.

Aggregates and Collections

Agrregates, Collections and variables are most important tools DTrace has to offer for data gathering, analyzing and printing. We will start with different types of variables available to us.

Variable types

D scripting language has 3 types of variables which you can use to keep track of things.

Block local

You can define a block local variable with :

syscall::read:entry
{
  this->currentTime = timestamp;
}

Scope of a block local variable is limited to the block in which it is defined.

Global scalar variables

You can define a global variable like:

BEGIN {
  startTime = timestamp;
}

Variables defined like this are global and they are available in all the probe descriptions. Also, if you haven't guessed it - BEGIN and END[2] are two special probes that fire at the beginning of a DTrace script and at the end of it. They can be very useful for initializing things or printing summary results at the end of execution.

Thread local variables

If you are trying to profile a multi-threaded application you will want to keep DTrace variables separate for different threads. You can do that with thread local variables:

syscall::read:entry
{
  self->currentTime = timestamp;
}

Variables declared like this won't be shared between threads and hence can be used reliably.

Associative Arrays

If you are coming from Ruby, think of associative array as a Hash where that keys can be a single value or a tuple of values. In either case once declared type of key shouldn't change. For example, following script will calcuate time spent by each process in a system call.

syscall:::entry
{
  callTime[execname, probefunc] = timestamp;
}

syscall:::return {
    this->timeElapsed = timestamp - callTime[execname,probefun];
}

You can learn more about these different kind of variables at[1].

Aggregates

Armed with knowledge of variables and collections, we can finally dip our toes in aggregates. Aggregates is a way of gathering data from individual probes without you the programmer doing actual work of summing things up,calculating the median, frequency of occurence etc.

For example, lets write a DTrace script that prints number of top 20 objects Rails creates when it boots up. You are obviously going to need Ruby 2.0 for following script to work.

/* rails_boot.d
 * object-create is the name of the probe that fires
 * when any new ruby object is created.
 * Corresponding function called is - rb_obj_alloc
 */
ruby*:::object-create
{
   /* If you look up code of rb_obj_alloc, first argument to
    * function contains class which is being instantiated
    */
   @objects[copyinstr(arg0)] = count();
}

END {
  /* Truncate the aggregate to top 20 results */
  trunc(@objects,20);
  /* Print the aggregate */
  printa(@objects);
}

The output should look something like:

  Mime::Type                                                       22
  Psych::Nodes::Scalar                                             27
  Bundler::LazySpecification                                       39
  Set                                                              54
  Sass::Script::Functions::Signature                               55
  Rails::Paths::Path                                               71
  Class                                                            73
  Pathname                                                         74
  Bundler::DepProxy                                                77
  Rails::Initializable::Collection                                 93
  Regexp                                                           95
  Rails::Initializable::Initializer                               143
  Range                                                           332
  Gem::Specification                                              410
  Hash                                                            579
  Gem::Dependency                                                1660
  Gem::Version                                                   2416
  Gem::Requirement                                               3061
  String                                                         4723
  Array                                                          4948

Keep in mind, running above script isn't as simple as running sudo dtrace -qs rails_boot.d -c 'rails s' . Depending on whether you are using RVM or rbenv all those shell scripts shims create a problem when running dtrace scripts. What I ended up doing is, created a file called load_env.rb that had just one line require_relative config/environment and then ran the Dtrace script with:

sudo dtrace -qs rails_boot.d -c "/Users/gnufied/.rbenv/versions/20/bin/ruby load_env.rb"

Now there are some new keywords in above script and we will to get them in a bit, but first let us talk about aggregates. DTrace allows you to store result of aggregate functions in objects called aggregates, they are defined like:

@name[ keys ] = aggfunc ( args );

Aggregate object name starts with @ and behave very similar to associative arrays and hence can use tuples as keys. Using aggregate functions frees you up from keeping counter yourself. In above script we are using count function which keeps track of number of times that particular probe fired. There are other aggergate functions available as well:

count - The number of times called.
sum - The total value of the specified expressions.
avg - The arithmetic average of the specified expressions.
min - The smallest value among the specified expressions.
max - The largest value among the specified expressions.
lquantize - A linear frequency distribution, sized by the specified range, of the values of the specified expressions. Increments the value in the highest bucket that is less than the specified expression.
quantize - A power-of-two frequency distribution of the values of the specified expressions. Increments the value in the highest power-of-two bucket that is less than the specified expression.

You can find out more about aggregates from [3].

That about sums up content for part 2 of DTrace tutorial. In the next part we are going to cover in built functions, printing and profiling of real world Ruby applications. You should also follow us on twitter @codemancershq if you don't want to miss out Part 3.