Difference between Linux time and Performance clocks in code

Question

I was running a simple test for timing of some C++ code, and I ran across an artifact that I am not 100% positive about.

Setup

My code uses C++11 high_resolution_clock to measure elapsed time. I also wrap the execution of my program using Linux's time command (/usr/bin/time). For my program, the high_resolution_clock reports ~2s while time reports ~7s (~6.5s user and ~.5s system). Also using the verbose option on time shows that my program used 100% of the CPU with 1 voluntary context switch and 10 involuntary context switches (/usr/bin/time -v).

Question

My question is what causes such a dramatic difference between OS time measurements and performance time measurements?

My initial thoughts

Through my knowledge of operating systems, I am assuming these differences are solely caused by context switches with other programs (as noted by time -v).

Is this the only reason for this difference? And should I trust the time reported by my program or the system when looking at code performance?

Again, my assumption is to trust the computed time from my program over Linux's time, because it times more than just my program's CPU usage.

Caveats

I am not posting code, as it isn't really relevant to the issue at hand. If you wish to know it is a simple test that times 100,000,000 random floating point arithmetic operations.
I know other clocks in my C++ code might be more or less appropriate for difference circumstances (this stack overflow question). High_resolution_clock is just an example.

Edit: Code as requested

#include <chrono>
#include <cstdlib>
#include <iostream>
#include <vector>

using namespace std;
using namespace std::chrono;

int main() {
  size_t n = 100000000;

  double d = 1;

  auto start_hrc = high_resolution_clock::now();

  for(size_t i = 0; i < n; ++i) {
    switch(rand() % 4) {
      case 0: d += 0.0001; break;
      case 1: d -= 0.0001; break;
      case 2: d *= 0.0001; break;
      case 3: d /= 0.0001; break;
    }
  }

  auto end_hrc = high_resolution_clock::now();
  duration<double> diff_hrc = end_hrc - start_hrc;
  cout << d << endl << endl;
  cout << "Time-HRC: " << diff_hrc.count() << " s" << endl;
}

The initial output of `time` will be clock time from program start to program finish, which could take a while if there were context switches, like you mentioned. I would trust the high_resolution_clock as it is quite likely also sleeping while your thread is sleeping. I know you said you don't want to show code, but it would be nice to see exactly how you instrumented your timings, so code is good for that. — AndyG, Sep 12 '16 at 14:02
I uploaded the timing, which is not very different from every tutorial on high_resolution_clock I found. — pippin1289, Sep 12 '16 at 14:11
Correct me if I'm wrong, but the assumption in the code is that the number of ticks represents seconds? What is the output if you use `std::chrono::duration_cast(end_hrc-start_hrc)`? — AndyG, Sep 12 '16 at 14:18
The output would be an integer representation of the seconds passed. — pippin1289, Sep 12 '16 at 14:20
That's fair. I suspect the values are still significantly different, but I wanted to check. Also, `std::duration_cast(diff_hrc)` (with what you have now) — AndyG, Sep 12 '16 at 14:28

score 0 · Accepted Answer · answered Sep 12 '16 at 17:20

My question is what causes such a dramatic difference between OS time measurements and performance time measurements?

It looks like your system takes a while to start your application. Probably a resource issue: not enough free memory (swapping) or oversubscribed CPU.

No dramatic difference is observed on my desktop:

Time-HRC: 1.39005 s
real    0m1.391s
user    0m1.387s
sys     0m0.004s

Difference between Linux time and Performance clocks in code

1 Answers1