DTrace

DTrace

Overview

I'm using DTrace to dig into the erlang VM more and do performance profiling tracking.

Check out the definitions for what all is currently possible.

It's currently in a fairly unstable (though quite useful) state. Some things may be a bit misleading due to the differences between how a C function call works and how an erlang function call works.

In C, we push the user stack and have a fairly straightforward way to pull it from dtrace space (that is to say, ustack is awesome until you can't use it). In erlang, TCO means that some function calls aren't actually entering a function and some results can't tell you what function they're results from. A bit more instrumentation will help resolve these issues, but in the meantime, you can see things you couldn't see before, and that's pretty awesome.

Examples

Some examples I'm collecting of seeing what's going on here.

Looking for slow functions

I'm using a separate slowness for regular erlang code and BIF and NIF times, otherwise, it's mostly the same.

#pragma D option quiet

erlang*:::function-entry,
erlang*:::bif-entry,
erlang*:::nif-entry
{
    self->start[copyinstr(arg0), copyinstr(arg1)] = timestamp
}

erlang*:::function-return
/ self->start[copyinstr(arg0), copyinstr(arg1)] != 0 &&
  timestamp - self->start[copyinstr(arg0), copyinstr(arg1)] > 1000000 /
{
    duration = timestamp - (self->start[copyinstr(arg0), copyinstr(arg1)]);
    printf("CALL: %s - %s - %d\n", copyinstr(arg0), copyinstr(arg1), duration)
}

erlang*:::bif-return,
erlang*:::nif-return
/ self->start[copyinstr(arg0), copyinstr(arg1)] != 0 &&
  timestamp - self->start[copyinstr(arg0), copyinstr(arg1)] > 10000 /
{
    duration = timestamp - (self->start[copyinstr(arg0), copyinstr(arg1)]);
    printf("[BN]IF: %s - %s - %d\n", copyinstr(arg0), copyinstr(arg1),
           duration)
}

Looking for large messages being sent.

#pragma D option quiet

:beam.smp::function-entry
{
    self->mfa[copyinstr(arg0)] = copyinstr(arg1);
}

:beam.smp::send
/arg2 > 4096/
{
    printf("Sending %d bytes of data from %s to %s from %s\n", arg2,
           copyinstr(arg0), copyinstr(arg1), self->mfa[copyinstr(arg0)]);
}

Find Functions that Copy a Lot

This works by keeping track of the most recent function seen and associating any copy_struct calls with that function. While it does leave room for inaccuracies theoretically, the stuff floating up to the top has been pretty clearly correct for my purposes.

In this case, I'm also looking at BIFs and NIFs, but if you decide those aren't interesting, you can just drop them.

self string current;

erlang*:::function-entry,
erlang*:::function-return,
erlang*:::bif-entry,
erlang*:::bif-return,
erlang*:::nif-entry,
erlang*:::nif-return,
erlang*:::process_scheduled
{
    self->current = copyinstr(arg1);
}

erlang*:::copy_struct
/ self->current != "" /
{
    @copies[self->current] = sum(arg0);
}

tick-10sec
{
    trunc(@copies, 25);
    printa(@copies);
}