0
#include <stdio.h>
#include <stdarg.h>
#include <sys/time.h>

char kBuff[1024];
const char* kMsg = "0123456789 abcdefghizklmnopqrstuvwxyz ABCDEFGHIJKLMNOPQRSTUVWXYZ";
const long kThreshold = 100; //us

void func(const char* fmt, ...) {  
  struct timeval start, end;
  gettimeofday(&start, NULL);

  va_list ap;
  va_start (ap, fmt);
  vsnprintf(kBuff, sizeof(kBuff) - 1, fmt, ap);
  va_end (ap);

  gettimeofday(&end, NULL);

  long during = (end.tv_sec - start.tv_sec) * 1000 * 1000 + (end.tv_usec - start.tv_usec);
  if (during > kThreshold)
    printf("%ld, ", during);
}

int main() {
  long index = 0;
  for(int i = 0; i < 1000000; i++) {
    func("Index:%8ld Msg:%s", index++, kMsg);
  }
}

I run a quite simple code for 10,000,000 times, and sometimes the running time of the specific piece of code is varies greatly, sometimes reaching 1000+us. The result is below:

105, 106, 135, 115, 121, 664, 135, 1024, 165, 130,

The program is running in a virtual machine of Ubuntu-18.04 on Windows-10

g++ -ggdb -O2 test.cpp

gettimeofday(&start, NULL);

va_list ap;
va_start (ap, fmt);
vsnprintf(kBuff, sizeof(kBuff) - 1, fmt, ap);
va_end (ap);

gettimeofday(&end, NULL);

The code above does not fall into kernel, and does not wait I/O, does not wait locks, so why the runing time can reaching 1000 us?

One reason I guessed was due to the scheduling of the operating system. but how do I prove this?

If this is the reason, then how can I accurately measure the running time of a program?

Jason
  • 3,777
  • 14
  • 27
davidwang414
  • 1
  • Any thread can be suspended by the OS for an arbitrary amount of time. Ought to be "worse" on a VM. Focusing on the outliers is not useful, you need to take the median of the measurements as the representative value. – Hans Passant Oct 06 '19 at 16:54

1 Answers1

2

Measuring performance simply using wall clock time is often inadequate for several reasons such as

  1. OS may schedule other processes on the CPU (like you mentioned)
  2. You may not measure what you're actually trying to measure because of possible compiler reordering (Enforcing statement order in C++ discusses this in detail)
  3. Routines that measure time (gettimeofday in your case) themselves have an overhead which may be included in your measurement thus introducing noise

There are tools like perf tool which use performance counters and tracepoints to analyze the performance without these issues.

I find https://www.youtube.com/watch?v=nXaxk27zwlk a good starting point to learn how to benchmark. It discusses the usage of google benchmark and perf both useful for measuring performance.

Having said that, using these tools does not mean that there will be no variance in your measurement. Real-time performance is affected by several factors like cache, changing clock frequencies, page-faults and so on. Unless you are working on a real-time system, tail-latency is seldom an issue.

Empty Space
  • 743
  • 6
  • 17