湖间小筑 | Tunning Rails with DTrace

Tunning Rails with DTrace

发表于2012-05-24 09:25:42

This post will talk about how to do performance test of Rails program with DTrace tool. The testing will be separated into Ruby program part and database operations part. Please make sure all the tested program has provided probes to the DTrace.

NOTICE: The testing data is still under collection, this post has only DTrace script now, I will update this post after gathering enough testing data.

DTrace

DTrace is a dynamic tracing tool, which is safe to use in production systems and it does not require restarting either the system or application. DTrace consists of 4 parts: front-end, libdtrace library, in-kernel DTrace framework and DTrace provider.

DTrace is built on a foundation of objects called probes. Probes are event handlers that will be triggered when their particular event occurs, and DTrace can bind some actions to the probe to get needed information.

Basic syntax

A typically D language script contains three sections, the BEGIN section, END section and probe section. Sections are surrounded by braces. Each probe description is made of four fields, separated by colon character:

provider:module:function:name

privider: Instrumented layer
module: Instrumented module
function: Instrumented function
name: location in the function, typically is enter, return, tick-nsec

The provider field is needed, which others are optional. Pattern matching characters such as *, ?, […] and \ can be used. For example, this script will get all call of write* function:

syscall::write*:entry
{
    printf("(%d): %s write call called", pid, execname);
}

Here is a sample script:

#!/usr/sbin/dtrace -s

#pragma D option quiet

pid$target::fopen*:entry
{
    printf("(%d):%s open\n", pid, execname);
}

pid$target::fwrite*:entry
{
    printf("(%d):%s write\n", pid, execname);
}

pid$target::fread*:entry
{
    printf("(%d):%s read\n", pid, execname);
}

And here is a testing C program:

#include <stdio.h>
#include <stdlib.h>

int main(int argc, char* argv[]) {
    char buffer[64];
    int size = 0;

    FILE *fp = fopen("bar.c", "r");
    fread(buffer, sizeof(buffer), sizeof(char), fp);
    fclose(fp);

    FILE *fp2 = fopen("/tmp/foobar", "w");
    fwrite(buffer, sizeof(buffer), sizeof(char), fp2);
    fclose(fp2);
}

Here is the result of running the program with given script:

$ sudo ./foo.d -c `pwd`/bar
(3001):bar open
(3001):bar read
(3001):bar open
(3001):bar write

It also can support some predication before the action, for example:

/ pid == 12345 /
/ execname == "bash" /

For more information, please refer to reference section:

Rails

Probes for Ruby and Rails application

NOTICE: Make sure the Ruby you are using provides the DTrace probes, or the testing below can NOT be continued.

NOTICE: The Ruby 1.9.3 currently do not support DTrace, please follow this discussion for more information http://bugs.ruby-lang.org/issues/2565

I have applied the patch mentioned above to Ruby 1.9.3 and regenerate the configure file with autoconf command, then compile the binary and install it to replace the Ruby installed by homebrew.

Probes provided by Ruby is list below:

function-entry
function-return
gc-begin
gc-end
line
object-create-start
object-create-end
object-free
raise
rescue
ruby-probe

The list can be get by this command: sudo dtrace -lP 'ruby*'. The -P argument is used to specify the provider.

NOTICE: The probe name may different than above list in different system, please refer to the output of command while writing the script.

The function*, object* and gc* probes can be used to analyse performance while the raise and rescue can be used to analyse error. Since the probes for Ruby my have some errors while running on my system, so I only choose function related probes in the script, and a summary will be printed out after test completed.

Here is the script used for testing, thanks to [this article](http://andyjeffries.co.uk/articles/dtrace-and-ruby-on-rails-with- leopard-snow-leopard) and [this article](http://tenderlovemaking.com/2011/12/05/profiling-rails-startup-with- dtrace/), the script used here is based on their version.

#!/usr/sbin/dtrace -s

#pragma D option quiet

BEGIN
{
    printf("==========================\n");
    printf("Trace started: %Y\n", walltimestamp);
    printf("==========================\n");
    depth = 0;
}

ruby*:::function-entry
{
    k = copyinstr(arg0);
    m = copyinstr(arg1);
    @[k, m] = count();
    self->depth++;
    self->start[k, m, self->depth] = timestamp;
    printf("-> %s::%s (%s:%d)\n", k, m, copyinstr(arg2), arg3);
}

tick-5000hz
/k != 0/
{
      @[k, m] = count();
}

ruby*:::function-return
/(this->class = copyinstr(arg0)) != NULL && \
 (this->func  = copyinstr(arg1)) != NULL && \
 self->start[this->class, this->func, self->depth]/
{
    this->elapsed = timestamp - self->start[this->class, this->func, self->depth];

    this->file = copyinstr(arg2);
    this->line = arg3;
    @num[this->file, this->line] = count();
    @eavg[this->file, this->line] = avg(this->elapsed);
    @esum[this->file, this->line] = sum(this->elapsed);

    self->start[this->class, this->func, self->depth] = 0;
    self->depth--;
}

END
{
    printf("==========================\n");
    printf("Trace ended: %Y\n", walltimestamp);
    printf("==========================\n");
    normalize(@eavg, 1000);
    normalize(@esum, 1000);
    setopt("aggsortpos", "2");
    printf("%-33s %123s\n", "___ OVERLAP TIMES: ___",
            "______ ELAPSED _____");
    printf("%-120s %5s %6s %10s %12s\n", "FILE", "LINE",
            "COUNT", "AVG(us)", "SUM(us)");
    printa("%-120.120s %5d %@6d %@10d %@12d\n", @num, @eavg, @esum);
}

Probes primely used in the script is function-entry and function-return, and the action inside the probe is to calculate the elapsed time. And some summary information will be printed after trace end.

Probes for database operations

The performance test is also needed on Database server, MySQL has provide one method to use DTrace to the database, please refer [this page](http://dev.mysql.com/tech- resources/articles/getting_started_dtrace_saha.html) for reference. Here is the script used for tracing MySQL database.

#!/usr/sbin/dtrace -s

#pragma D option quiet

BEGIN
{
    printf("==========================\n");
    printf("Trace started: %Y\n", walltimestamp);
    printf("==========================\n");
    depth = 0;
}

pid$target::*mysql_parse*:entry
{
    self->query = copyinstr(arg1);
}

mysql*:::query-start
{
    self->query = copyinstr(arg0);
    self->connid = arg1;
    self->db = copyinstr(arg2);
    self->who = strjoin(copyinstr(arg3),strjoin("@",copyinstr(arg4)));
    self->start = timestamp;
}

mysql*:::query-done
/ self->start /
{
    this->elapsed = timestamp - self->start;
    @time[self->query] = quantize(this->elapsed);
    printf("%-20s %-20s %-40s %-9d\n", self->who, self->db, self->query, this->elapsed / 1000000);
    self->query = 0;
    self->start = 0;
}


END
{
    printf("==========================\n");
    printf("Trace ended: %Y\n", walltimestamp);
    printf("==========================\n");

    printf("MySQL query execution latency (ns):\n");
    printa(@time);
}

This script will print out time consumed by query command. There are some more detailed probe, which can be used to monitor the time consumbed by each type of command, please check the document if more information is needed.

Result analysis

The output is different from the two script listed above. In the log message of Ruby, the filename and line number information are saved, which can be used to locate the bottle neck. While the MySQL probe is easy to use, after separating the command type, the performance can be optimized.

The testing data is still under development, and I will update the blog after get the result.