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

[Akim Demaille]

Hi Bruno!

> Le 13 oct. 2018 à 18:11, Bruno Haible <address@hidden> a écrit :
> 
> Hi Akim,
> 
>> Or we filter on the percentages.
> 
> Yes, filtering on percentages is the way to go. The user doesn't
> care about contributions < 1% or < 0.5%. When people draw pie charts,
> such minimal contributions are usually combined into "Other", but
> here you can just as well omit them entirely.

That’s still very verbose with Bison, two more lines that with
the original criterion:

                          CPU user      CPU system    wall clock      
 reader                   0,014 ( 2%)   0,001 (15%)   0,014834 (15%)
 LR(0)                    0,002 ( 0%)   0,000 ( 1%)   0,002267 ( 1%)
 conflicts                0,000 ( 0%)   0,000 ( 1%)   0,000590 ( 1%)
 outputting report        0,029 ( 6%)   0,001 (17%)   0,030352 (17%)
 parser action tables     0,017 ( 3%)   0,000 ( 1%)   0,017086 ( 1%)
 outputting parser        0,011 ( 2%)   0,001 (14%)   0,052919 (14%)
 running m4               0,405 (84%)   0,004 (46%)   0,366641 (46%)
 total time               0,481         0,008         0,487395

but I can live with that.

> 
>> diff --git a/lib/timevar.h b/lib/timevar.h
>> index ff443fed6..9ea94f71f 100644
>> --- a/lib/timevar.h
>> +++ b/lib/timevar.h
>> ...
>> +float timevar_tiny;
>> +float timevar_wall_tiny;
> 
> These declarations need 'extern', otherwise you'll get "symbol multiply
> defined » errors when linking.

Gee…  But what is wrong with me???

> In order not to fall into this trap, I like to prefix *all* declarations
> in .h file with 'extern'. Yes, it’s more verbose, but it's more systematic.

My way to avoid this is to never expose variables.


commit 29283642c0e39d3e64c555a2ed4fd71feae771a4
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.
    * lib/timevar.c (set_to_current_time): Use gethrxtime.
    (timevar_print): Instead of checking whether the timings themselves
    are large enough for the timevar to be printed, check the percentages.

diff --git a/ChangeLog b/ChangeLog
index ecd69df04..3d7441909 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,3 +1,20 @@
+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.
+       * lib/timevar.c (set_to_current_time): Use gethrxtime.
+       (timevar_print): Instead of checking whether the timings themselves
+       are large enough for the timevar to be printed, check the percentages.
+
 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..6059fd78c 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"
@@ -101,13 +102,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 +318,34 @@ 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;
 
-      /* 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)
+      /* Percentages.  */
+      const int usr = total->user ? tv->elapsed.user * 100 / total->user : 0;
+      const int sys = total->sys ? tv->elapsed.sys * 100 / total->sys : 0;
+      const int wall = total->wall ? tv->elapsed.wall * 100 / total->wall : 0;
+
+      /* Ignore insignificant lines.  */
+      if (!usr && !sys && !wall)
         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);
-
-      /* 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);
-
-      /* Print wall clock time elapsed.  */
-      fprintf (fp, "%11.6f (%2.0f%%)",
-               tv->elapsed.wall,
-               (total->wall == 0 ? 0 : tv->elapsed.wall / total->wall) * 100);
-
-      putc ('\n', fp);
+      fprintf (fp, "%8.3f (%2d%%)", tv->elapsed.user * 1e-9, usr);
+      fprintf (fp, "%8.3f (%2d%%)", tv->elapsed.sys * 1e-9, sys);
+      fprintf (fp, "%11.6f (%2d%%)\n", tv->elapsed.wall * 1e-9, sys);
     }
 
   /* 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..cf9e0830d 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
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+