[PATCH] mid-end: Use integral time intervals in timevar.cc

[Matthew Malcomson <matthew.malcomson@arm.com>]

[-- Attachment #1: Type: text/plain, Size: 6097 bytes --]

Hopefully last update ...

> Specifically, please try compiling with
>    -ftime-report -fdiagnostics-format=sarif-file
> and have a look at the generated .sarif file, e.g. via
>    python -m json.tool foo.c.sarif
> which will pretty-print the JSON to stdout.

Rebasing onto the JSON output was quite simple -- I've inlined the only
change in the patch below (to cast to floating point seconds before
generating the json report).

I have manually checked the SARIF output as you suggested and all looks
good (an in fact better because we no longer save some strange times
like the below due to avoiding the floating point rounding).
	  "wall": -4.49516e-09,


> 
> The patch looks OK to me if it passes bootstrap / regtest and the
> output of -ftime-report doesn't change (too much).
> 
> Thanks,
> Richard.

Though I don't expect you were asking for this, confirmation below that
the output doesn't change.  (Figured I may as well include that info
since the rebase to include the JSON output that David had just added
required re-sending an email anyway).



```
hw-a20-8:checking-theory [10:07:01] $ ${old_build}/gcc/xgcc -B${old_build}/gcc/    -fdiagnostics-plain-output    -Os  -w -S test-sum.c -o /dev/null   -ftime-report

Time variable                                   usr           sys          wall           GGC
 phase setup                        :   0.01 ( 14%)   0.00 (  0%)   0.02 ( 18%)  3389k ( 74%)
 phase parsing                      :   0.03 ( 43%)   0.02 ( 67%)   0.06 ( 55%)   982k ( 21%)
 phase opt and generate             :   0.03 ( 43%)   0.01 ( 33%)   0.03 ( 27%)   215k (  5%)
 callgraph functions expansion      :   0.02 ( 29%)   0.00 (  0%)   0.03 ( 27%)   162k (  4%)
 callgraph ipa passes               :   0.01 ( 14%)   0.01 ( 33%)  -0.00 ( -0%)    38k (  1%)
 CFG verifier                       :   0.00 (  0%)   0.00 (  0%)   0.01 (  9%)     0  (  0%)
 preprocessing                      :   0.02 ( 29%)   0.02 ( 67%)   0.02 ( 18%)   272k (  6%)
 lexical analysis                   :   0.01 ( 14%)   0.00 (  0%)   0.02 ( 18%)     0  (  0%)
 parser (global)                    :   0.00 (  0%)   0.00 (  0%)   0.01 (  9%)   637k ( 14%)
 parser function body               :   0.00 (  0%)   0.00 (  0%)   0.01 (  9%)    18k (  0%)
 tree CFG cleanup                   :   0.00 (  0%)   0.01 ( 33%)   0.00 (  0%)     0  (  0%)
 tree STMT verifier                 :   0.01 ( 14%)   0.00 (  0%)   0.00 (  0%)     0  (  0%)
 expand                             :   0.01 ( 14%)   0.00 (  0%)   0.00 (  0%)    12k (  0%)
 loop init                          :   0.00 (  0%)   0.00 (  0%)   0.01 (  9%)    12k (  0%)
 initialize rtl                     :   0.00 (  0%)   0.00 (  0%)   0.01 (  9%)    15k (  0%)
 rest of compilation                :   0.01 ( 14%)   0.00 (  0%)   0.00 (  0%)  6920  (  0%)
 TOTAL                              :   0.07          0.03          0.11         4587k
Extra diagnostic checks enabled; compiler may run slowly.
Configure with --enable-checking=release to disable checks.
hw-a20-8:checking-theory [10:06:44] $ ${new_build}/gcc/xgcc -B${new_build}/gcc/    -fdiagnostics-plain-output    -Os  -w -S test-sum.c -o /dev/null   -ftime-report

Time variable                                   usr           sys          wall           GGC
 phase setup                        :   0.01 ( 17%)   0.00 (  0%)   0.02 ( 18%)  3389k ( 74%)
 phase parsing                      :   0.02 ( 33%)   0.03 ( 75%)   0.05 ( 45%)   982k ( 21%)
 phase opt and generate             :   0.03 ( 50%)   0.01 ( 25%)   0.04 ( 36%)   215k (  5%)
 callgraph construction             :   0.00 (  0%)   0.01 ( 25%)   0.00 (  0%)  1864  (  0%)
 callgraph functions expansion      :   0.02 ( 33%)   0.00 (  0%)   0.03 ( 27%)   162k (  4%)
 callgraph ipa passes               :   0.01 ( 17%)   0.00 (  0%)   0.01 (  9%)    38k (  1%)
 ipa free lang data                 :   0.00 (  0%)   0.00 (  0%)   0.01 (  9%)     0  (  0%)
 CFG verifier                       :   0.02 ( 33%)   0.00 (  0%)   0.00 (  0%)     0  (  0%)
 preprocessing                      :   0.01 ( 17%)   0.03 ( 75%)   0.01 (  9%)   272k (  6%)
 lexical analysis                   :   0.01 ( 17%)   0.00 (  0%)   0.02 ( 18%)     0  (  0%)
 parser (global)                    :   0.00 (  0%)   0.00 (  0%)   0.01 (  9%)   637k ( 14%)
 parser inl. func. body             :   0.00 (  0%)   0.00 (  0%)   0.01 (  9%)    19k (  0%)
 tree STMT verifier                 :   0.01 ( 17%)   0.00 (  0%)   0.00 (  0%)     0  (  0%)
 expand                             :   0.00 (  0%)   0.00 (  0%)   0.01 (  9%)    12k (  0%)
 integrated RA                      :   0.00 (  0%)   0.00 (  0%)   0.01 (  9%)    50k (  1%)
 initialize rtl                     :   0.00 (  0%)   0.00 (  0%)   0.01 (  9%)    15k (  0%)
 TOTAL                              :   0.06          0.04          0.11         4587k
Extra diagnostic checks enabled; compiler may run slowly.
Configure with --enable-checking=release to disable checks.
```


N.b. in the change below it's worth mentioning that the
`nanosec_to_floating_sec` and `percent_of` macros were already defined.
I just moved them to below the `make_json_for_timevar_time_def`
function.
###############          Changes to the previous patch.          ###############


@@ -832,12 +841,16 @@ json::object *
 make_json_for_timevar_time_def (const timevar_time_def &ttd)
 {
   json::object *obj = new json::object ();
-  obj->set ("user", new json::float_number (ttd.user));
-  obj->set ("sys", new json::float_number (ttd.sys));
-  obj->set ("wall", new json::float_number (ttd.wall));
+  obj->set ("user",
+	    new json::float_number (nanosec_to_floating_sec (ttd.user)));
+  obj->set ("sys", new json::float_number (nanosec_to_floating_sec (ttd.sys)));
+  obj->set ("wall",
+	    new json::float_number (nanosec_to_floating_sec (ttd.wall)));
   obj->set ("ggc_mem", new json::integer_number (ttd.ggc_mem));
   return obj;
 }
+#undef nanosec_to_floating_sec
+#undef percent_of
 
 /* Create a json value representing this object, suitable for use
    in SARIF output.  */




[-- Attachment #2: timevar-including-json.patch --]
[-- Type: text/plain, Size: 8525 bytes --]

diff --git a/gcc/timevar.h b/gcc/timevar.h
index e359e9fa1fa5b4c230aa2711e58a8883824d9682..541216ee1dcaa6b3a4702fe6a2b171c51ffd6f27 100644
--- a/gcc/timevar.h
+++ b/gcc/timevar.h
@@ -46,7 +46,7 @@ namespace json { class value; }
 */
 
 /* This structure stores the various varieties of time that can be
-   measured.  Times are stored in seconds.  The time may be an
+   measured.  Times are stored in nanoseconds.  The time may be an
    absolute time or a time difference; in the former case, the time
    base is undefined, except that the difference between two times
    produces a valid time difference.  */
@@ -54,14 +54,13 @@ namespace json { class value; }
 struct timevar_time_def
 {
   /* User time in this process.  */
-  double user;
+  uint64_t user;
 
-  /* System time (if applicable for this host platform) in this
-     process.  */
-  double sys;
+  /* System time (if applicable for this host platform) in this process.  */
+  uint64_t sys;
 
   /* Wall clock time.  */
-  double wall;
+  uint64_t wall;
 
   /* Garbage collector memory.  */
   size_t ggc_mem;
diff --git a/gcc/timevar.cc b/gcc/timevar.cc
index 5368ff06ac966a1a69b7008fd23f33ff45464138..a63e5c6334e652c76fd91f673a6fdf6ff4b61867 100644
--- a/gcc/timevar.cc
+++ b/gcc/timevar.cc
@@ -43,7 +43,7 @@ struct tms
 # define RUSAGE_SELF 0
 #endif
 
-/* Calculation of scale factor to convert ticks to microseconds.
+/* Calculation of scale factor to convert ticks to seconds.
    We mustn't use CLOCKS_PER_SEC except with clock().  */
 #if HAVE_SYSCONF && defined _SC_CLK_TCK
 # define TICKS_PER_SECOND sysconf (_SC_CLK_TCK) /* POSIX 1003.1-1996 */
@@ -92,14 +92,15 @@ struct tms
    the underlying constants, and that can be very slow, so we have to
    precompute them.  Whose wonderful idea was it to make all those
    _constants_ variable at run time, anyway?  */
+#define NANOSEC_PER_SEC 1000000000
 #ifdef USE_TIMES
-static double ticks_to_msec;
-#define TICKS_TO_MSEC (1 / (double)TICKS_PER_SECOND)
+static uint64_t ticks_to_nanosec;
+#define TICKS_TO_NANOSEC (NANOSEC_PER_SEC / TICKS_PER_SECOND)
 #endif
 
 #ifdef USE_CLOCK
-static double clocks_to_msec;
-#define CLOCKS_TO_MSEC (1 / (double)CLOCKS_PER_SEC)
+static uint64_t clocks_to_nanosec;
+#define CLOCKS_TO_NANOSEC (NANOSEC_PER_SEC / CLOCKS_PER_SEC)
 #endif
 
 /* Non-NULL if timevars should be used.  In GCC, this happens with
@@ -243,18 +244,20 @@ get_time (struct timevar_time_def *now)
   {
 #ifdef USE_TIMES
     struct tms tms;
-    now->wall = times (&tms)  * ticks_to_msec;
-    now->user = tms.tms_utime * ticks_to_msec;
-    now->sys  = tms.tms_stime * ticks_to_msec;
+    now->wall = times (&tms)  * ticks_to_nanosec;
+    now->user = tms.tms_utime * ticks_to_nanosec;
+    now->sys  = tms.tms_stime * ticks_to_nanosec;
 #endif
 #ifdef USE_GETRUSAGE
     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;
+    now->user = rusage.ru_utime.tv_sec * NANOSEC_PER_SEC
+		+ rusage.ru_utime.tv_usec * 1000;
+    now->sys  = rusage.ru_stime.tv_sec * NANOSEC_PER_SEC
+		+ rusage.ru_stime.tv_usec * 1000;
 #endif
 #ifdef USE_CLOCK
-    now->user = clock () * clocks_to_msec;
+    now->user = clock () * clocks_to_nanosec;
 #endif
   }
 }
@@ -305,10 +308,10 @@ timer::timer () :
   /* Initialize configuration-specific state.
      Ideally this would be one-time initialization.  */
 #ifdef USE_TIMES
-  ticks_to_msec = TICKS_TO_MSEC;
+  ticks_to_nanosec = TICKS_TO_NANOSEC;
 #endif
 #ifdef USE_CLOCK
-  clocks_to_msec = CLOCKS_TO_MSEC;
+  clocks_to_nanosec = CLOCKS_TO_NANOSEC;
 #endif
 }
 
@@ -617,12 +620,11 @@ timer::validate_phases (FILE *fp) const
 {
   unsigned int /* timevar_id_t */ id;
   const timevar_time_def *total = &m_timevars[TV_TOTAL].elapsed;
-  double phase_user = 0.0;
-  double phase_sys = 0.0;
-  double phase_wall = 0.0;
+  uint64_t phase_user = 0;
+  uint64_t phase_sys = 0;
+  uint64_t phase_wall = 0;
   size_t phase_ggc_mem = 0;
   static char phase_prefix[] = "phase ";
-  const double tolerance = 1.000001;  /* One part in a million.  */
 
   for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
     {
@@ -641,26 +643,32 @@ timer::validate_phases (FILE *fp) const
 	}
     }
 
-  if (phase_user > total->user * tolerance
-      || phase_sys > total->sys * tolerance
-      || phase_wall > total->wall * tolerance
-      || phase_ggc_mem > total->ggc_mem * tolerance)
+  if (phase_user > total->user
+      || phase_sys > total->sys
+      || phase_wall > total->wall
+      || phase_ggc_mem > total->ggc_mem)
     {
 
       fprintf (fp, "Timing error: total of phase timers exceeds total time.\n");
       if (phase_user > total->user)
-	fprintf (fp, "user    %24.18e > %24.18e\n", phase_user, total->user);
+	fprintf (fp, "user    %13" PRIu64 " > %13" PRIu64 "\n",
+		 phase_user, total->user);
       if (phase_sys > total->sys)
-	fprintf (fp, "sys     %24.18e > %24.18e\n", phase_sys, total->sys);
+	fprintf (fp, "sys     %13" PRIu64 " > %13" PRIu64 "\n",
+		 phase_sys, total->sys);
       if (phase_wall > total->wall)
-	fprintf (fp, "wall    %24.18e > %24.18e\n", phase_wall, total->wall);
+	fprintf (fp, "wall    %13" PRIu64 " > %13" PRIu64 "\n",
+		 phase_wall, total->wall);
       if (phase_ggc_mem > total->ggc_mem)
-	fprintf (fp, "ggc_mem %24lu > %24lu\n", (unsigned long)phase_ggc_mem,
+	fprintf (fp, "ggc_mem %13lu > %13lu\n", (unsigned long)phase_ggc_mem,
 		 (unsigned long)total->ggc_mem);
       gcc_unreachable ();
     }
 }
 
+#define nanosec_to_floating_sec(NANO) ((double)(NANO) * 1e-9)
+#define percent_of(TOTAL, SUBTOTAL) \
+  ((TOTAL) == 0 ? 0 : ((double)SUBTOTAL / TOTAL) * 100)
 /* Helper function for timer::print.  */
 
 void
@@ -674,22 +682,22 @@ timer::print_row (FILE *fp,
 #ifdef HAVE_USER_TIME
   /* Print user-mode time for this process.  */
   fprintf (fp, "%7.2f (%3.0f%%)",
-	   elapsed.user,
-	   (total->user == 0 ? 0 : elapsed.user / total->user) * 100);
+	   nanosec_to_floating_sec (elapsed.user),
+	   percent_of (total->user, elapsed.user));
 #endif /* HAVE_USER_TIME */
 
 #ifdef HAVE_SYS_TIME
   /* Print system-mode time for this process.  */
   fprintf (fp, "%7.2f (%3.0f%%)",
-	   elapsed.sys,
-	   (total->sys == 0 ? 0 : elapsed.sys / total->sys) * 100);
+	   nanosec_to_floating_sec (elapsed.sys),
+	   percent_of (total->sys, elapsed.sys));
 #endif /* HAVE_SYS_TIME */
 
 #ifdef HAVE_WALL_TIME
   /* Print wall clock time elapsed.  */
   fprintf (fp, "%7.2f (%3.0f%%)",
-	   elapsed.wall,
-	   (total->wall == 0 ? 0 : elapsed.wall / total->wall) * 100);
+	   nanosec_to_floating_sec (elapsed.wall),
+	   percent_of (total->wall, elapsed.wall));
 #endif /* HAVE_WALL_TIME */
 
   /* Print the amount of ggc memory allocated.  */
@@ -707,7 +715,8 @@ timer::print_row (FILE *fp,
 bool
 timer::all_zero (const timevar_time_def &elapsed)
 {
-  const double tiny = 5e-3;
+  /* 5000000 nanosec == 5e-3 seconds.  */
+  uint64_t tiny = 5000000;
   return (elapsed.user < tiny
 	  && elapsed.sys < tiny
 	  && elapsed.wall < tiny
@@ -800,13 +809,13 @@ timer::print (FILE *fp)
   /* Print total time.  */
   fprintf (fp, " %-35s:", "TOTAL");
 #ifdef HAVE_USER_TIME
-  fprintf (fp, "%7.2f      ", total->user);
+  fprintf (fp, "%7.2f      ", nanosec_to_floating_sec (total->user));
 #endif
 #ifdef HAVE_SYS_TIME
-  fprintf (fp, "%8.2f      ", total->sys);
+  fprintf (fp, "%8.2f      ", nanosec_to_floating_sec (total->sys));
 #endif
 #ifdef HAVE_WALL_TIME
-  fprintf (fp, "%8.2f      ", total->wall);
+  fprintf (fp, "%8.2f      ", nanosec_to_floating_sec (total->wall));
 #endif
   fprintf (fp, PRsa (7) "\n", SIZE_AMOUNT (total->ggc_mem));
 
@@ -832,12 +841,16 @@ json::object *
 make_json_for_timevar_time_def (const timevar_time_def &ttd)
 {
   json::object *obj = new json::object ();
-  obj->set ("user", new json::float_number (ttd.user));
-  obj->set ("sys", new json::float_number (ttd.sys));
-  obj->set ("wall", new json::float_number (ttd.wall));
+  obj->set ("user",
+	    new json::float_number (nanosec_to_floating_sec (ttd.user)));
+  obj->set ("sys", new json::float_number (nanosec_to_floating_sec (ttd.sys)));
+  obj->set ("wall",
+	    new json::float_number (nanosec_to_floating_sec (ttd.wall)));
   obj->set ("ggc_mem", new json::integer_number (ttd.ggc_mem));
   return obj;
 }
+#undef nanosec_to_floating_sec
+#undef percent_of
 
 /* Create a json value representing this object, suitable for use
    in SARIF output.  */