Re: [PATCH v4.16-rc5 (3)] x86/vdso: on Intel, VDSO should handle CLOCK_MONOTONIC_RAW

[Jason Vas Dias]

Hi Thomas -
RE:
On 15/03/2018, Thomas Gleixner <tglx@xxxxxxxxxxxxx> wrote:
> Jason,
>
> On Thu, 15 Mar 2018, jason.vas.dias@xxxxxxxxx wrote:
>
>>   Resent to address reviewer comments.
>
> I was being patient so far and tried to guide you through the patch
> submission process, but unfortunately this turns out to be just waste of my
> time.
>
> You have not addressed any of the comments I made here:
>
> [1]
> https://lkml.kernel.org/r/alpine.DEB.2.21.1803141511340.2481@xxxxxxxxxxxxxxxxxxxxxxx
> [2]
> https://lkml.kernel.org/r/alpine.DEB.2.21.1803141527300.2481@xxxxxxxxxxxxxxxxxxxxxxx
>

I'm really sorry about that - I did not see those mails ,
and have searched for them in my inbox -
are you sure they were sent to 'linux-kernel@xxxxxxxxxxxxxxx' ?
That is the only list I am subscribed to .
I clicked on the links , but the 'To:' field is just
'linux-kernel' .

If I had seen those messages before I re-submitted,
those issues would have been fixed.

checkpatch.pl did not report them -
I ran it with all patches and it reported
no errors .

And I did send the test results in a previous mail -

$ gcc -m64 -o timer timer.c

( must be compiled in 64-bit mode).

This is using the new rdtscp() function :
$ ./timer -r 100
...
Total time: 0.000002806S - Average Latency: 0.000000028S N zero
deltas: 0 N inconsistent deltas: 0
Average of 100 average latencies of 100 samples : 0.000000027S

This is using the rdtsc_ordered() function:

$ ./timer -m -r 100
Total time: 0.000005269S - Average Latency: 0.000000052S N zero
deltas: 0 N inconsistent deltas: 0
Average of 100 average latencies of 100 samples : 0.000000047S

timer.c is a very short program that just reads N_SAMPLES (a
compile-time option)
timespecs using either CLOCK_MONOTONIC_RAW (no -m) or CLOCK_MONOTONIC
first parameter to clock_gettime(),  then
computes the deltas as long long, then averages them , counting any
zero deltas, or deltas where the previous timespec is somehow
greater than the current timespec, which are reported as
inconsitencies (note 'inconistent deltas:0' and 'zero deltas: 0' in output).

So my initial claim that rdtscp() can be twice as fast as rdtsc_ordered()
was not far-fetched - this is what I am seeing .

I think this is because of the explicit barrier() call in rdtsc_ordered() .
This must be slower than than the internal processor pipeline
"cancellation point" (barrier) used by the rdtscp instruction itself.
This is the only reason for the rdtscp call  -  plus all modern Intel
& AMD CPUs support it, and it DOES solve the ordering problem,
whereby instructions in one pipeline of a task can get different
rdtsc() results than instructions in another pipeline.

I will document the results better in the ChangeLog , fix all issues
you identified, and resend .

I did not mean to ignore your comments -
those mails are nowhere in my Inbox -
please ,  confirm the actual email address
they are getting sent to.

Thanks & Regards,
Jason
/* 
 * Program to measure high-res timer latency.
 *
 */
#include <stdint.h>
#include <stdbool.h>
#include <sys/types.h>
#include <unistd.h>
#include <time.h>
#include <errno.h>
#include <alloca.h>
#include <string.h>
#include <stdio.h>
#include <stdlib.h>

#ifndef N_SAMPLES
#define N_SAMPLES 100
#endif
#define _STR(_S_) #_S_
#define STR(_S_) _STR(_S_)

#define TS2NS(_TS_) ((((unsigned long long)(_TS_).tv_sec)*1000000000ULL) + (((unsigned long long)((_TS_).tv_nsec)))) 

int main(int argc, char *const* argv, char *const* envp)
{ struct timespec sample[N_SAMPLES+1];
  unsigned int cnt=N_SAMPLES, s=0 , avg_n=0;
  unsigned long long
    deltas [ N_SAMPLES ]
    , t1, t2, sum=0, zd=0, ic=0, d
    , t_start, avg_ns, *avgs=0;
  clockid_t clk = CLOCK_MONOTONIC_RAW;
  bool do_dump = false;
  int argn=1, repeat=1;
  for(; argn < argc; argn+=1)
    if( argv[argn] != NULL )
      if( *(argv[argn]) == '-')
	switch( *(argv[argn]+1) )
	{ case 'm':
	  case 'M':
	    clk = CLOCK_MONOTONIC;
	    break;
	  case 'd':
	  case 'D':
	    do_dump = true;
	    break;
     	  case 'r':
      	  case 'R':
	    if( (argn < argc) && (argv[argn+1] != NULL))
	      repeat = atoi(argv[argn+=1]);
	    break;
	  case '?':
	  case 'h':
	  case 'u':
	  case 'U':
	  case 'H':
	    fprintf(stderr,"Usage: timer_latency [\n\t-m : use CLOCK_MONOTONIC clock (not CLOCK_MONOTONIC_RAW)\n\t-d : dump timespec contents. N_SAMPLES: " STR(N_SAMPLES) "\n\t"
	            "-r <repeat count>\n]\t" 
	            "Calculates average timer latency (minimum time that can be measured) over N_SAMPLES.\n"
	           );
	    return 0;
	}
  if( repeat > 1 )
  { avgs=alloca(sizeof(unsigned long long) * (N_SAMPLES + 1));
    if( ((unsigned long) avgs) & 7 )
      avgs = ((unsigned long long*)(((unsigned char*)avgs)+(8-((unsigned long) avgs) & 7)));
  }
  do {
    cnt=N_SAMPLES;
    s=0;
  do
  { if( 0 != clock_gettime(clk, &sample[s++]) )
    { fprintf(stderr,"oops, clock_gettime() failed: %d: '%s'.\n", errno, strerror(errno));
      return 1;
    }
  }while( --cnt );
  clock_gettime(clk, &sample[s]);
  for(s=1; s < (N_SAMPLES+1); s+=1)
  { t1 = TS2NS(sample[s-1]);
    t2 = TS2NS(sample[s]);
    if ( (t1 > t2)
       ||(sample[s-1].tv_sec > sample[s].tv_sec)
       ||((sample[s-1].tv_sec == sample[s].tv_sec)
        &&(sample[s-1].tv_nsec > sample[s].tv_nsec)
         )
       )
    { fprintf(stderr,"Inconsistency: %llu %llu %lu.%lu %lu.%lu\n", t1 , t2
            , sample[s-1].tv_sec, sample[s-1].tv_nsec
            , sample[s].tv_sec,   sample[s].tv_nsec
      );
      ic+=1;
      continue;
    }
    d = t2 - t1;
    if ( d == 0 )
    {  zd += 1;
    }
    deltas[s-1] = d;
    if(do_dump)
      fprintf(stderr, "%lu %lu %llu\n",
              sample[s].tv_sec, sample[s].tv_nsec, d
             );
  }
  for(s = 0, sum=0; s < N_SAMPLES; s+=1)
    sum += deltas[s];
  fprintf(stderr,"sum: %llu\n",sum);
  avg_ns = sum / N_SAMPLES;
  t_start = TS2NS(sample[0]);
  t1=(t2 - t_start);
  printf("Total time: %1.1llu.%9.9lluS - Average Latency: %1.1llu.%9.9lluS N zero deltas: %u N inconsistent deltas: %u\n",
          t1 / 1000000000,       t1 % 1000000000,
          avg_ns / 1000000000,   avg_ns % 1000000000 ,
          zd, ic
        );
  if (avgs != ((void*)0UL))
    avgs[avg_n++] = avg_ns;
  } while (--repeat);
  if (avgs != ((void*)0UL))
  { for( s=0, sum=0; s < avg_n; s+=1)
      sum += avgs[s];
    printf("Average of %u average latencies of " STR(N_SAMPLES) " samples : %1.1llu.%9.9lluS\n"
          , avg_n, (sum / N_SAMPLES) / 1000000000, (sum / N_SAMPLES) % 1000000000
          );
  }
  return 0;
}