DPROBES (DTRACE_PROBE) for measuring high latency stuff under 1µsec

Question

Currently, I'm analyzing the performance of a high latency application but I'm not confident in my measurements at all. So far, I have used DPROBES for instrumentation and BCC/funclatency for measuring. Would someone be able to verify those numbers? Also, if someone knows of a better method, please let me know.

measuring usleep(1) : avg = 53962 nsecs

#include <unistd.h>
#include <sys/sdt.h>

int main() {
   int i;
   for(i=0; i<1000000; i++){ 
   DTRACE_PROBE("hello-usdt", probe-main-start);
   usleep(1);
   DTRACE_PROBE("hello-usdt", probe-main-end);
   }
}

measuring the overhead : avg = 788 nsecs

#include <sys/sdt.h>

int main() {
   int i;
   for(i=0; i<1000000; i++){ 
   DTRACE_PROBE("hello-usdt", probe-main-start);
   DTRACE_PROBE("hello-usdt", probe-main-end);
   }
}

As an overhead, can I subtract 788 nsecs from all my measurements?

another example with nanosleep(200) :avg = 52563 nsecs

#include <sys/sdt.h>
#include <unistd.h>
#include <time.h>
#include <stdio.h>
int main() {
  
    struct timespec tim, tim2;
    tim.tv_sec = 0;
    tim.tv_nsec = 200L;
    int i;
    for (i=0; i<100000; i++){
    DTRACE_PROBE("hello-usdt", probe-main-start);
    if(nanosleep(&tim , &tim2) < 0 ){
            printf("Nano sleep system call failed \n");
            return -1;
    }   
    DTRACE_PROBE("hello-usdt", probe-main-end);
    }
    printf("Nano sleep successfull \n");

    return 0;
}

A little modification was made to the funclatency code:

# attach probes

usdt = USDT(path = "path to application")
usdt.enable_probe(probe = "probe-main-start", fn_name = "trace_func_entry")
usdt.enable_probe(probe = "probe-main-end", fn_name = "trace_func_return")
b = BPF(text = bpf_text, usdt_contexts = [usdt])

Am I unable to measure anything below 0.8usec with this method? Furthermore I cannot believe that nanosleep(200) "oversleep" by 50 usec.

Answer 1

measuring usleep(1) : avg = 53962 nsecs

Please understand that, in the sequence your code is following :

   DTRACE_PROBE("hello-usdt", probe-main-start);
   usleep(1);
   DTRACE_PROBE("hello-usdt", probe-main-end);

The associated process is very much likely to get scheduled out following the request for usleeping.
And consequently the following DTRACE_PROBE will get executed only when the associated process is scheduled back in. Therefore your measurement does not reliably measure the clock-time spent by usleep(1) but instead the time spent sleeping for 1 µs + a variable amount of time depending on system activity, the latter being in any case superior to 1 µs by far.
let's venture… 50 times more… that is in average ~50µs ;-)
In a non-real-time context, I would suspect the stdev being quite high on this measure.

---

measuring the overhead : avg = 788 nsecs.
As an overhead, can I subtract 788 nsecs from all my measurements?

Let's admit that your method will indeed measure the overhead induced by DTRACE_PROBE.
In any case, as in any measurement operation, do consider the stdev first. Because the higher the stdev, the less the meaningfulness of the average.
If happy with the stdev, then yes, do subtract the average from your measurements.
But… well… are we speaking of some time < 1 µs ?

---

another example with nanosleep(200) :avg = 52563 nsecs

What ? Once more… a ~50 µs drift ? how strange ?
Please do refer to the very first part of my answer which applies to nanosleep as well. And, if not enough, refer to nanosleep manual :

Furthermore, after the sleep completes, there may still be a delay before the CPU becomes free to once again execute the calling thread.

---

Am I unable to measure anything below 0.8usec with this method? Futhermore I cannot believe that nanosleep(200) "oversleep" by 50 usec.

Having read all here-above written, I expect you have the answer to your last question which incidentally gives an answer to the former :

No ! you are not unable to measure anything below 800 ns with this method.
But, because of your system activity & hardware performances you are only (I mean I would also be) unable to measure the clock-time taken by whatever blocking call (whatever call that would immediately trigger the scheduler to schedule the process out) with a better precision than ~50 µs.