Re: [tlug] timing for geeks

[Jim <jep200404@example.com>]

Michal Hajek <hajek1@example.com> wrote:

> I need a time mark in my experiments, so I have used ftime() function.
> But what was my surprise, when I discovered, that time mark for the
> _later_ measurements are actually more recent than _sooner_
> measurements. 

This is a rich experiment with many twists and turns. 

On my Linux box man ftime shows: 

BUGS
       This function is obsolete. Don't use it. 
...
       gettimeofday(2) gives microseconds; 
       clock_gettime(3) gives nanoseconds but
       is not yet widely available.

       Under  libc4  and  libc5  the millitm field is meaningful.
       But early glibc2 is buggy and returns 0 there; glibc 2.1.1
       is correct again.

What does man ftime show on your system? 

That said, you might also be exposing accuracy limits of floating 
point math used in awk and/or gnuplot. 

Beside the point is: 

> This beast writes to my disk with cca 21MB/s, so be carefull!
> 
> 4. since many of the lines are same, lets uniq it :)
> uniq cas.txt > uniq.txt

Since you are concerned about the big file, 
it would have been better to pipe the output from cas to uniq to awk, 
without saving the intermediate data. 
I.e., 

   $ ./cas | uniq | awk '{print $1, $1 - 1133531643.784}' >data.awk

To avoid awk's accuracy limits, use a cruder tool to 'normalize' the data: 

   $ ./cas | uniq | sed -e 's/^113353//g' >data.sed

then grep to make sure sed didn't prune all the lines. 
I.e., the following should have no matching lines. 

   $ grep 113353 data.sed

Then run gnuplot: 

   $ gnuplot
   gnuplot> plot 'data.sed'

Of course, you'll have to update the 113353 string to prune. 

With my style of sed pruning, gnuplot is not stressed and 
still shows the suspect sawtooth-ish waveform. 

Also, look at the data a little closer: 

   $ ./cas | uniq >data.uniq

yielded: 

   1133553014.999
   1133553015.0
   1133553015.1
   1133553015.2
   1133553015.3
   1133553015.4
   1133553015.5
   1133553015.6
   1133553015.7
   1133553015.8
   1133553015.9
   1133553015.10
   1133553015.11
   1133553015.12
   1133553015.13

Oops. 

1133553015.1 should be 1133553015.001
1133553015.10 should be 1133553015.010

Good old fashioned browsing the data for reasonableness 
revealed the problem. 

Go back to your program and change the format string to: 

   "%d.%03d \t \n"

I.e.: 

   $ cat cas2.c
   #include <stdio.h>
   #include <stdlib.h>
   #include <sys/timeb.h>

   int main(int argc,char *argv[])
   {
      struct timeb start;

      for (;;) {
         ftime(&start);
         printf("%d.%03d \t \n",start.time,start.millitm);
      }

      return 0;
   }

   $ make cas2
   cc     cas2.c   -o cas2
   $ ./cas2 | uniq | sed -e 's/^113355//g' >data.sed

   $ gnuplot

   gnuplot> plot 'data.sed'

yields a better line, although I can not see if the discontinuity 
is monotonic or not. I'll leave that as an exercise for you to zoom 
in on. 

Of course, even if it is monotonic, you should avoid using ftime. 

For fun review your old plots, especially 

   http://material.karlov.mff.cuni.cz/people/hajek/timetest/detail.png

and correlate the crazy points with the data. I.e., from: 

   1133553015.1
   1133553015.2
   1133553015.3
   1133553015.4
   1133553015.5
   1133553015.6
   1133553015.7
   1133553015.8
   1133553015.9

you should have about nine crazy points and from: 

   1133553015.10
   1133553015.11
   1133553015.12
   1133553015.13
...
   1133553015.99

you should have about ninety crazy points. I counted the nine bad points, 
but I'll let you count the ~90 bad points. 

Notice how the trash clusters repeat about every 1000 points in 

   http://material.karlov.mff.cuni.cz/people/hajek/timetest/uniq.png

(actually a little less because not all milliseconds were caught). 

Crazy data often has important clues. The nine crazy points and 
the ~ninety crazy points and the repetition about every 1000 points 
were all important clues. Mulling stuff over helps. Some folks 
use beverages to improve their vision. 

I did not actually offer a proper solution, just a patch and an 
analysis of the bugs, so of course I must leave it to you to 
decide if that warrants a free one when I get to Prague.