Re: timevar: 3/3: use clock_gettime to get wall clock time

[Akim Demaille]

> Le 13 oct. 2018 à 15:41, Bruno Haible <address@hidden> a écrit :
> 
> Hi Akim,
> 
>> But it felt weird to use a double, the number of significant decimal digits
>> of a float (about 7) seems enough.
> 
> This is the line I'm talking about:
> 
>  timer->wall += stop->wall - start->wall;

Sorry, I was unclear.  Yes, I fully understood what you meant.
I was meaning that it felt weird to use double to get improve
the situation: we measure integral types, let’s stick with them.
The less I use floating types, the happier I am.  Now that I have
discovered xtime_t, it felt like the right storage backend.  More
than doubles.

> The 'Includes', as well that the 'Link' field, are part of the contract
> between the author of the module and its user. When it changes, the user
> has to change their source code (for 'Includes' changes) or their Makefile
> (for ‘Link' changes).

Okay, so Bison is lacking these Links…  I’ll update it.

It’s of course more precise when you have tons of utils (coreutils),
or several libraries, etc. and you want to keep it small, but in the
case of Bison, I’d be happy to have a $(LIB_GNULIB) for instance.
I suspect Bison’s case is a common one, but that’s just an intuition,
I have no evidence for this :)


> For 'user' and 'sys', 'double' would have been OK as well.
> 
>> +  sys_s  += rusage.ru_stime.tv_sec + usr_ns / giga;
> Typo: Should be sys_ns / giga

Shame on me :(  Actually, I would have preferred not to have
to do it, but xtime_make doesn’t do it.  I should have factored
this there.

I did that.  I hope that’s not a problem.  ?

>> +      const float tiny = 5e-3;
> 
> Shouldn't that be 0.5e-3 for usr and sys, and 0.5e-6 for wall,
> to match the number of decimal places printed below?

Wall is so precise that it almost means « dump everything ».
For Bison, that’s noise (to my eyes).

                          CPU user      CPU system    wall clock      
 reader                   0,017 ( 3%)   0,002 (25%)   0,019317 ( 4%)
 reducing the grammar     0,000 ( 0%)   0,000 ( 0%)   0,000118 ( 0%)
 computing the sets       0,000 ( 0%)   0,000 ( 0%)   0,000048 ( 0%)
 LR(0)                    0,003 ( 0%)   0,000 ( 0%)   0,002693 ( 0%)
 LALR(1)                  0,001 ( 0%)   0,000 ( 0%)   0,001525 ( 0%)
 conflicts                0,001 ( 0%)   0,000 ( 1%)   0,000686 ( 0%)
 outputting report        0,024 ( 5%)   0,001 ( 8%)   0,024495 ( 5%)
 parser action tables     0,017 ( 3%)   0,000 ( 0%)   0,017155 ( 3%)
 outputting parser        0,011 ( 2%)   0,001 (15%)   0,050501 (11%)
 running m4               0,369 (83%)   0,004 (46%)   0,332628 (73%)
 freeing                  0,001 ( 0%)   0,000 ( 0%)   0,000970 ( 0%)
 total time               0,443         0,008         0,450210

I guess you would still like to see it, so I suppose the best
option is to have a variable to control that.  I did that below.

Or we filter on the percentages.



commit 989a5e9e3c3c423038faba7ea86fed70f86202e7
Author: Akim Demaille <address@hidden>
Date:   Fri Oct 12 06:46:09 2018 +0200

    timevar: use gethrxtime to get wall clock time
    
    clock_gettime is not portable.  gethrxtime takes the best available
    option to get the wall clock time, including clock_gettime (monotonic
    clock), and gettime (non monotonic).
    Also, using xtime_t instead of float preserves the precision.
    Suggested by Bruno Haible.
    
    * lib/xtime.h (xtime_make): Handle overflows of nanoseconds.
    * modules/timevar (Depends-on): We need gethrxtime.
    We no longer use times().
    (Link): Update.
    * lib/timevar.h (timevar_time_def): Use xtime_t.
    (timevar_tiny, timevar_wall_tiny): New.
    * lib/timevar.c (timevar_tiny, timevar_wall_tiny): New.
    (timevar_print): Use them.
    (set_to_current_time): Use gethrxtime.
    Adjust all dependencies.

diff --git a/ChangeLog b/ChangeLog
index ecd69df04..9481f12a3 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,3 +1,22 @@
+2018-10-13  Akim Demaille  <address@hidden>
+
+       timevar: use gethrxtime to get wall clock time
+       clock_gettime is not portable.  gethrxtime takes the best available
+       option to get the wall clock time, including clock_gettime (monotonic
+       clock), and gettime (non monotonic).
+       Also, using xtime_t instead of float preserves the precision.
+       Suggested by Bruno Haible.
+       * lib/xtime.h (xtime_make): Handle overflows of nanoseconds.
+       * modules/timevar (Depends-on): We need gethrxtime.
+       We no longer use times().
+       (Link): Update.
+       * lib/timevar.h (timevar_time_def): Use xtime_t.
+       (timevar_tiny, timevar_wall_tiny): New.
+       * lib/timevar.c (timevar_tiny, timevar_wall_tiny): New.
+       (timevar_print): Use them.
+       (set_to_current_time): Use gethrxtime.
+       Adjust all dependencies.
+
 2018-10-13  Akim Demaille  <address@hidden>
 
        bootstrap: fix wget command for po files.
diff --git a/lib/timevar.c b/lib/timevar.c
index 8b574e277..6daa128ab 100644
--- a/lib/timevar.c
+++ b/lib/timevar.c
@@ -30,6 +30,7 @@
 #include <sys/time.h>
 #include <sys/times.h>
 
+#include "gethrxtime.h"
 #include "gettext.h"
 #define _(msgid) gettext (msgid)
 #include "xalloc.h"
@@ -37,6 +38,8 @@
 /* See timevar.h for an explanation of timing variables.  */
 
 int timevar_enabled = 0;
+float timevar_tiny = 5e-3;
+float timevar_wall_tiny = 5e-6;
 
 /* A timing variable.  */
 
@@ -101,13 +104,20 @@ set_to_current_time (struct timevar_time_def *now)
   if (!timevar_enabled)
     return;
 
-  struct rusage rusage;
-  getrusage (RUSAGE_SELF, &rusage);
-  now->user = rusage.ru_utime.tv_sec + rusage.ru_utime.tv_usec * 1e-6;
-  now->sys  = rusage.ru_stime.tv_sec + rusage.ru_stime.tv_usec * 1e-6;
-  getrusage (RUSAGE_CHILDREN, &rusage);
-  now->user += rusage.ru_utime.tv_sec + rusage.ru_utime.tv_usec * 1e-6;
-  now->sys  += rusage.ru_stime.tv_sec + rusage.ru_stime.tv_usec * 1e-6;
+  struct rusage self;
+  getrusage (RUSAGE_SELF, &self);
+  struct rusage chld;
+  getrusage (RUSAGE_CHILDREN, &chld);
+
+  now->user =
+    xtime_make (self.ru_utime.tv_sec + chld.ru_utime.tv_sec,
+                (self.ru_utime.tv_usec + chld.ru_utime.tv_usec) * 1000);
+
+  now->sys =
+    xtime_make (self.ru_stime.tv_sec + chld.ru_stime.tv_sec,
+                (self.ru_stime.tv_usec + chld.ru_stime.tv_usec) * 1000);
+
+  now->wall = gethrxtime();
 }
 
 /* Return the current time.  */
@@ -310,49 +320,50 @@ timevar_print (FILE *fp)
            "", _("CPU user"), _("CPU system"), _("wall clock"));
   for (unsigned /* timevar_id_t */ id = 0; id < (unsigned) TIMEVAR_LAST; ++id)
     {
-      struct timevar_def *tv = &timevars[(timevar_id_t) id];
-      const float tiny = 5e-3;
-
       /* Don't print the total execution time here; that goes at the
          end.  */
       if ((timevar_id_t) id == tv_total)
         continue;
 
       /* Don't print timing variables that were never used.  */
+      struct timevar_def *tv = &timevars[(timevar_id_t) id];
       if (!tv->used)
         continue;
 
+      const float usr = tv->elapsed.user * 1e-9;
+      const float sys = tv->elapsed.sys * 1e-9;
+      const float wall = tv->elapsed.wall * 1e-9;
+
       /* Don't print timing variables if we're going to get a row of
          zeroes.  */
-      if (tv->elapsed.user < tiny
-          && tv->elapsed.sys < tiny
-          && tv->elapsed.wall < tiny)
+      if (usr < timevar_tiny && sys < timevar_tiny
+          && wall < timevar_wall_tiny)
         continue;
 
       /* The timing variable name.  */
       fprintf (fp, " %-22s", tv->name);
 
       /* Print user-mode time for this process.  */
-      fprintf (fp, "%8.3f (%2.0f%%)",
-               tv->elapsed.user,
-               (total->user == 0 ? 0 : tv->elapsed.user / total->user) * 100);
+      fprintf (fp, "%8.3f (%2lld%%)",
+               usr,
+               total->user ? tv->elapsed.user * 100 / total->user : 0);
 
       /* Print system-mode time for this process.  */
-      fprintf (fp, "%8.3f (%2.0f%%)",
-               tv->elapsed.sys,
-               (total->sys == 0 ? 0 : tv->elapsed.sys / total->sys) * 100);
+      fprintf (fp, "%8.3f (%2lld%%)",
+               sys,
+               total->sys ? tv->elapsed.sys * 100 / total->sys : 0);
 
       /* Print wall clock time elapsed.  */
-      fprintf (fp, "%11.6f (%2.0f%%)",
-               tv->elapsed.wall,
-               (total->wall == 0 ? 0 : tv->elapsed.wall / total->wall) * 100);
+      fprintf (fp, "%11.6f (%2lld%%)",
+               wall,
+               total->wall ? tv->elapsed.wall * 100 / total->wall : 0);
 
       putc ('\n', fp);
     }
 
   /* Print total time.  */
   fprintf (fp, " %-22s", timevars[tv_total].name);
-  fprintf (fp, "%8.3f      ", total->user);
-  fprintf (fp, "%8.3f      ", total->sys);
-  fprintf (fp, "%11.6f\n", total->wall);
+  fprintf (fp, "%8.3f      ", total->user * 1e-9);
+  fprintf (fp, "%8.3f      ", total->sys * 1e-9);
+  fprintf (fp, "%11.6f\n", total->wall * 1e-9);
 }
diff --git a/lib/timevar.h b/lib/timevar.h
index ff443fed6..9ea94f71f 100644
--- a/lib/timevar.h
+++ b/lib/timevar.h
@@ -23,6 +23,8 @@
 
 # include <stdio.h>
 
+# include "xtime.h"
+
 # ifdef  __cplusplus
 extern "C" {
 # endif
@@ -58,14 +60,14 @@ extern "C" {
 struct timevar_time_def
 {
   /* User time in this process.  */
-  float user;
+  xtime_t user;
 
   /* System time (if applicable for this host platform) in this
      process.  */
-  float sys;
+  xtime_t sys;
 
   /* Wall clock time.  */
-  float wall;
+  xtime_t wall;
 };
 
 /* An enumeration of timing variable identifiers.  Constructed from
@@ -129,6 +131,14 @@ void timevar_print (FILE *fp);
 
 extern int timevar_enabled;
 
+/* Control which timevars are displayed by timevar_print.  If a
+   timevar has usr and sys times less than TIMEVAR_TINY (5e-3 by
+   default) and wall time less than TIMEVAR_WALL_TINY (5e-6 by
+   default), don't display it.  */
+
+float timevar_tiny;
+float timevar_wall_tiny;
+  
 # ifdef  __cplusplus
 }
 # endif
diff --git a/lib/xtime.h b/lib/xtime.h
index 7ed4b1cd4..aabcee9e6 100644
--- a/lib/xtime.h
+++ b/lib/xtime.h
@@ -50,10 +50,13 @@ extern "C" {
 #endif
 
 /* Return an extended time value that contains S seconds and NS
-   nanoseconds, without any overflow checking.  */
+   nanoseconds.  */
 XTIME_INLINE xtime_t
 xtime_make (xtime_t s, long int ns)
 {
+  const long int giga = 1000 * 1000 * 1000;
+  s += ns / giga;
+  ns %= giga;
   if (XTIME_PRECISION == 1)
     return s;
   else
diff --git a/modules/timevar b/modules/timevar
index 354d1d211..b2a12bb99 100644
--- a/modules/timevar
+++ b/modules/timevar
@@ -6,12 +6,12 @@ lib/timevar.h
 lib/timevar.c
 
 Depends-on:
+gethrxtime
 getrusage
 gettext-h
 stdlib
 sys_time
 sys_times
-times
 xalloc
 
 Makefile.am:
@@ -20,6 +20,10 @@ lib_SOURCES += timevar.c timevar.def
 Include:
 "timevar.h"
 
+Link:
+$(LIB_GETHRXTIME)
+$(LTLIBINTL) when linking with libtool, $(LIBINTL) otherwise
+
 License:
 GPLv3+