How can I use Dtrace to calculate the time taken between arbitrary C statements

Question

I'm using ImageMagick(via PHP imagick extension) to generate a simple gif animation, like this one.

And I've found WriteGIFImage()(https://github.com/ImageMagick/ImageMagick/blob/c807b69de68a33b42fc8725486d5ac81688afd16/coders/gif.c#L1506) function takes long time to write the gif data by following D script.

pid$target::WriteGIFImage:entry
{
    self->start_WriteGIFImage = timestamp;
    printf("     -> WriteGIFImage\n");
}

pid$target::WriteGIFImage:return
{
    this->delta = (timestamp - self->start_WriteGIFImage) / 1000 / 1000;
    @deltas["WriteGIFImage"] = sum(this->delta);
    printf("     <- WriteGIFImage elapsed %d ms\n", this->delta);
}

// Output
ImagesToBlob
 -> WriteImage
     -> WriteGIFImage
     <- WriteGIFImage elapsed 821 ms
 <- WriteImage elapsed 821 ms
ImagesToBlob elapsed 821 ms

Total (ms):
  RelinquishMagickMemory                                            0
  WriteBlobByte                                                     0
  ImagesToBlob                                                    821
  WriteGIFImage                                                   821
  WriteImage                                                      821

WriteGIFImage() is a big function, I want to know time taken between 2 statements, in order to find the slowest code block. e.g. I suspect this for loop takes long time, so I need Dtrace tell me the time diff between line 1673 and 1678. How can I use D script to finish it?

1673    for (i=0; i < (ssize_t) image->colors; i++)
1674    {
1675      *q++=ScaleQuantumToChar(ClampToQuantum(image->colormap[i].red));
1676      *q++=ScaleQuantumToChar(ClampToQuantum(image->colormap[i].green));
1677      *q++=ScaleQuantumToChar(ClampToQuantum(image->colormap[i].blue));
1678    }

btw, I found ScaleQuantumToChar() and ClampToQuantum() are both inline functions, and pid*::ScaleQuantumToChar:entry/return probe can not work. How to trace inline functions with D?

strongly suggest using calls to `clock()` to obtain the current CPU time at the two points where the time measurement is wanted, then the elapsed time is ValueReturnedFromSecondCallToClock - ValueReturnedFromFirstCallToClock. You could divide the result by `CLOCKS_PER_SECOND` to obtain the (more readable) elapsed seconds — user3629249, Dec 26 '18 at 01:46

score 2 · Answer 1 · answered Dec 25 '18 at 20:40

In addition to the entry and return probes, the pid provider also has probes for each instruction offset. If you do sudo dtrace -l -n 'pid$target::WriteGIFImage:*' -p <pid>, it will list them. Then, you have to disassemble the code to determine what offset corresponds to what line of code. And, when a program is built with optimizations turned on, that correspondence might not be clean. (Instructions can be out of order with respect to code lines.)

You can also define your own User-Defined Static Tracing (USDT) providers and instrument your code with them. The dtrace man page explains how.

All of that said, though, DTrace probably isn't the best tool for this. Use the Time Profiler template of Instruments and it will tell you where your program is spending its time, down to the line (or even instruction).

How can I use Dtrace to calculate the time taken between arbitrary C statements

1 Answers1