1

I was doing a microbenchmark. My code appears something like this

while(some condition){
    struct timespec tps, tpe;
    clock_gettime(CLOCK_REALTIME, &tps);

    encrypt_data(some_data)

    clock_gettime(CLOCK_REALTIME, &tpe);
    long time_diff = tpe.tv_nsec - tps.tv_nsec;
    usleep(1000);
}

However, the sleep time that I put in usleep() actually affects the observed time_diff that I get. If I measure the execution of this code using the skeleton above the time I get varies from ~1.8us to ~7us for sleep time of 100us and 1000us respectively. Why would the measured time change with the change in sleep time, when sleep time is outside the instrumentation block?

The time results are average of multiple runs. I am using Ubuntu 14.04 to run this code. For encryption I am using aesgcm from openssl.

I know that this is not the best way to microbenchmark but that is not the problem here.

mbbce
  • 2,245
  • 1
  • 19
  • 31
  • Your test loop will get optimized to `int x = 1000;`, you are not measuring what you think you are. – Baum mit Augen Mar 12 '17 at 17:10
  • What is the "issue" exactly? – Lightness Races in Orbit Mar 12 '17 at 17:10
  • That the measured time changes with the change of sleep time. Which it shouldn't, because sleep time is outside the instrumentation code block. – mbbce Mar 12 '17 at 17:48
  • @BaummitAugen this is just an example Regardless of what it measure. Why would the measured time change when I change the sleep duration? – mbbce Mar 12 '17 at 17:48
  • Regarding the first issue using usleep: You may get varying measurements because usleep only guarantees to sleep *at least* n us. Nothing else. And the second issue was answered by @BaummitAugen (in addition I would mention that you don't provide enough information such as optimization leven etc). – overseas Mar 12 '17 at 20:01
  • @MB_CE When you only measure noise, it is not surprising if the result is pure noise. Read up on how to do a proper micro benchmark. – Baum mit Augen Mar 12 '17 at 22:20
  • @BaummitAugen as I said. This was just an example. The code that I am measuring is actually doing encryption so I hadn't put it in. Also pure noise shouldn't behave consistently for each of the value of usleep. – mbbce Mar 13 '17 at 04:52
  • @overseas I understand that usleep isn't supposed to provide exact sleep time. That shouldn't be a problem. usleep is outside the instrumentation block. – mbbce Mar 13 '17 at 04:57
  • Let me just edit the example so this discussion moves away from this line of arguments – mbbce Mar 13 '17 at 04:57
  • You are running on a normal OS, when you do any measurements, use times in seconds, not in microseconds. Maybe your data get moved to a higher cash level or ram when you wait longer and you have more cash-misses and higher latency when you run it again. – 12431234123412341234123 Mar 13 '17 at 06:50
  • Did you disable hyperthreading? Did you use scaling governor "performance"? You can also use `sched_setaffinity` to fix the core, `sched_setscheduler` to set the maximum priority, and `mlockall` to lock the mapped pages (`MCL_CURRENT | MCL_FUTURE`) – overseas Mar 13 '17 at 10:32
  • A other thing what can happen: the second change during this call, and you get a negative number. you should convert the complete struct to a uin64_t first in nanoseconds (same as internal in the linux kernel) (something like us would also work) and use this value to calculate the time difference. – 12431234123412341234123 Mar 13 '17 at 10:59

1 Answers1

0

Did you disable the CPU scaling?

sudo cpupower frequency-set --governor performance

See here and here.

mattdibi
  • 641
  • 10
  • 23