Correlating dtrace probes

Question

I'm seeing unexpected results using dtrace, in that my -entry and -return results don't always seem to correlate, I seem to see either too many or too few, and have simplified my script to explore what is going wrong.

I'm attempting to profile the amount of time spent in require "./foo"s in my Ruby code using the following D script:

ruby*:::require-entry
{
  self->start = timestamp;
  @counts["require-entry"] = count();
}

ruby*:::require-return
/self->start/
{
  @counts["correlated require returns"] = count();
  self->start = 0;
}

ruby*:::require-return
/!self->start/
{
  /* @reqTimes[copyinstr(arg0)] = quantize(self->start - timestamp); */
  @counts["uncorrelated require returns"] = count();
}

Running this prints:

$ time sudo dtrace -q -s script.d -c './script.rb'

  correlated require returns                                     5691
  uncorrelated require returns                                   7872
  require-entry                                                  7877
sudo dtrace -q -s script.d -c './script.rb'  0.22s user 0.22s system 3% cpu 13.488 total

am I using the self-> variables correctly (vs. this-> or similar?)
are my predicates correct?
when running dtrace this way, do I "race" against the probes activating before the script starts?

Ruby badly abuses `setjmp()`/`longjmp()`- see https://stackoverflow.com/questions/28569337/setjmp-longjmp-in-ruby-s-continuation. Is there any possibility that Ruby is jumping into/out of the calls you're trying to trace? — Andrew Henle, Apr 03 '19 at 12:12

score 0 · Answer 1 · answered Jun 11 '19 at 20:27

am I using the self-> variables correctly

Probably not. Because the third clause will always run (self->start=0). That’s the problem.

If you have recent enough (dtrace -V ≥ dtrace: Sun D 1.14) dtrace version, you can do

ruby*:::require-return
{
  if (self->start)
    @counts["correlated require returns"] = count();
  else
    @counts["uncorrelated require returns"] = count();

  self->start = 0;
}

otherwise

ruby*:::require-return
{
  @counts[self->start ? "correlated require returns" : "uncorrelated require returns"] = count();
  self->start = 0;
}

will do the trick too.

thanks, I'll go do some more digging and see what I can turn up - I haven't touched this project in a while and will need to refresh my memory. — Lee Hambley, Jun 13 '19 at 17:16

Correlating dtrace probes

1 Answers1