Increase precision of timings reported by RTS

Summary:
Today's hardware is much faster, so it makes sense to report timings
with more precision, and possibly help reduce rounding-induced
fluctuations in the nofib statistics.

This commit increases the precision of all timings previously reported
with a granularity of 10ms to 1ms. For instance, the `+RTS -S` output is
now rendered as:

    Alloc    Copied     Live     GC     GC      TOT      TOT  Page Flts
    bytes     bytes     bytes   user   elap     user     elap
   641936     59944    158120  0.000  0.000    0.013    0.001    0    0  (Gen:  0)
   517672     60840    158464  0.000  0.000    0.013    0.002    0    0  (Gen:  0)
   517256     58800    156424  0.005  0.005    0.019    0.007    0    0  (Gen:  1)
   670208      9520    158728  0.000  0.000    0.019    0.008    0    0  (Gen:  0)

  ...

                                     Tot time (elapsed)  Avg pause  Max pause
  Gen  0        24 colls,     0 par    0.002s   0.002s     0.0001s    0.0002s
  Gen  1         3 colls,     0 par    0.011s   0.011s     0.0038s    0.0055s

  TASKS: 4 (1 bound, 3 peak workers (3 total), using -N1)

  SPARKS: 0 (0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled)

  INIT    time    0.001s  (  0.001s elapsed)
  MUT     time    0.005s  (  0.006s elapsed)
  GC      time    0.014s  (  0.014s elapsed)
  EXIT    time    0.001s  (  0.001s elapsed)
  Total   time    0.032s  (  0.020s elapsed)

Note that this change also requires associated changes in the nofib
submodule.

Test Plan: tested with modified nofib

Reviewers: simonmar, nomeata, austin

Subscribers: simonmar, relrod, carter

Differential Revision: https://phabricator.haskell.org/D97

2 files changed, 20 insertions, 20 deletions

diff --git a/nofib b/nofib
-Subproject d98f7038d1111e515db9cc27d5d3bbe237e6e14
+Subproject 5bc1c75db2c74413959772c85d43f8171fdd7b8
diff --git a/rts/Stats.c b/rts/Stats.c
index c3d963c845..894e9d2c79 100644
--- a/rts/Stats.c
+++ b/rts/Stats.c
@@ -173,8 +173,8 @@ initStats1 (void)
     nat i;
   
     if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
-        statsPrintf("    Alloc    Copied     Live    GC    GC     TOT     TOT  Page Flts\n");
-        statsPrintf("    bytes     bytes     bytes  user  elap    user    elap\n");
+        statsPrintf("    Alloc    Copied     Live     GC     GC      TOT      TOT  Page Flts\n");
+        statsPrintf("    bytes     bytes     bytes   user   elap     user     elap\n");
     }
     GC_coll_cpu = 
 	(Time *)stgMallocBytes(
@@ -380,7 +380,7 @@ stat_endGC (Capability *cap, gc_thread *gct,
 	    statsPrintf("%9" FMT_SizeT " %9" FMT_SizeT " %9" FMT_SizeT,
 		    alloc*sizeof(W_), copied*sizeof(W_), 
 			live*sizeof(W_));
-            statsPrintf(" %5.2f %5.2f %7.2f %7.2f %4" FMT_Word " %4" FMT_Word "  (Gen: %2d)\n",
+            statsPrintf(" %6.3f %6.3f %8.3f %8.3f %4" FMT_Word " %4" FMT_Word "  (Gen: %2d)\n",
                     TimeToSecondsDbl(gc_cpu),
 		    TimeToSecondsDbl(gc_elapsed),
 		    TimeToSecondsDbl(cpu),
@@ -604,7 +604,7 @@ stat_exit (void)
 	
 	if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
 	    statsPrintf("%9" FMT_SizeT " %9.9s %9.9s", (W_)alloc*sizeof(W_), "", "");
-	    statsPrintf(" %5.2f %5.2f\n\n", 0.0, 0.0);
+	    statsPrintf(" %6.3f %6.3f\n\n", 0.0, 0.0);
 	}
 
         for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
@@ -654,10 +654,10 @@ stat_exit (void)
                         (size_t)(peak_mblocks_allocated * BLOCKS_PER_MBLOCK * BLOCK_SIZE_W - hw_alloc_blocks * BLOCK_SIZE_W) / (1024 * 1024 / sizeof(W_)));
 
 	    /* Print garbage collections in each gen */
-            statsPrintf("                                    Tot time (elapsed)  Avg pause  Max pause\n");
+            statsPrintf("                                     Tot time (elapsed)  Avg pause  Max pause\n");
             for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
                 gen = &generations[g];
-                statsPrintf("  Gen %2d     %5d colls, %5d par   %5.2fs   %5.2fs     %3.4fs    %3.4fs\n",
+                statsPrintf("  Gen %2d     %5d colls, %5d par   %6.3fs  %6.3fs     %3.4fs    %3.4fs\n",
                             gen->no,
                             gen->collections,
                             gen->par_collections,
@@ -704,23 +704,23 @@ stat_exit (void)
             }
 #endif
 
-	    statsPrintf("  INIT    time  %6.2fs  (%6.2fs elapsed)\n",
+	    statsPrintf("  INIT    time  %7.3fs  (%7.3fs elapsed)\n",
                         TimeToSecondsDbl(init_cpu), TimeToSecondsDbl(init_elapsed));
 
-            statsPrintf("  MUT     time  %6.2fs  (%6.2fs elapsed)\n",
+            statsPrintf("  MUT     time  %7.3fs  (%7.3fs elapsed)\n",
                         TimeToSecondsDbl(mut_cpu), TimeToSecondsDbl(mut_elapsed));
-            statsPrintf("  GC      time  %6.2fs  (%6.2fs elapsed)\n",
+            statsPrintf("  GC      time  %7.3fs  (%7.3fs elapsed)\n",
                         TimeToSecondsDbl(gc_cpu), TimeToSecondsDbl(gc_elapsed));
 
 #ifdef PROFILING
-	    statsPrintf("  RP      time  %6.2fs  (%6.2fs elapsed)\n",
+	    statsPrintf("  RP      time  %7.3fs  (%7.3fs elapsed)\n",
 		    TimeToSecondsDbl(RP_tot_time), TimeToSecondsDbl(RPe_tot_time));
-	    statsPrintf("  PROF    time  %6.2fs  (%6.2fs elapsed)\n",
+	    statsPrintf("  PROF    time  %7.3fs  (%7.3fs elapsed)\n",
 		    TimeToSecondsDbl(HC_tot_time), TimeToSecondsDbl(HCe_tot_time));
 #endif 
-	    statsPrintf("  EXIT    time  %6.2fs  (%6.2fs elapsed)\n",
+	    statsPrintf("  EXIT    time  %7.3fs  (%7.3fs elapsed)\n",
 		    TimeToSecondsDbl(exit_cpu), TimeToSecondsDbl(exit_elapsed));
-	    statsPrintf("  Total   time  %6.2fs  (%6.2fs elapsed)\n\n",
+	    statsPrintf("  Total   time  %7.3fs  (%7.3fs elapsed)\n\n",
 		    TimeToSecondsDbl(tot_cpu), TimeToSecondsDbl(tot_elapsed));
 #ifndef THREADED_RTS
 	    statsPrintf("  %%GC     time     %5.1f%%  (%.1f%% elapsed)\n\n",
@@ -779,17 +779,17 @@ stat_exit (void)
                  " ,(\"max_bytes_used\", \"%ld\")\n"
                  " ,(\"num_byte_usage_samples\", \"%ld\")\n"
                  " ,(\"peak_megabytes_allocated\", \"%lu\")\n"
-                 " ,(\"init_cpu_seconds\", \"%.2f\")\n"
-                 " ,(\"init_wall_seconds\", \"%.2f\")\n"
-                 " ,(\"mutator_cpu_seconds\", \"%.2f\")\n"
-                 " ,(\"mutator_wall_seconds\", \"%.2f\")\n"
-                 " ,(\"GC_cpu_seconds\", \"%.2f\")\n"
-                 " ,(\"GC_wall_seconds\", \"%.2f\")\n"
+                 " ,(\"init_cpu_seconds\", \"%.3f\")\n"
+                 " ,(\"init_wall_seconds\", \"%.3f\")\n"
+                 " ,(\"mutator_cpu_seconds\", \"%.3f\")\n"
+                 " ,(\"mutator_wall_seconds\", \"%.3f\")\n"
+                 " ,(\"GC_cpu_seconds\", \"%.3f\")\n"
+                 " ,(\"GC_wall_seconds\", \"%.3f\")\n"
                  " ]\n";
       }
       else {
           fmt1 = "<<ghc: %llu bytes, ";
-          fmt2 = "%d GCs, %ld/%ld avg/max bytes residency (%ld samples), %luM in use, %.2f INIT (%.2f elapsed), %.2f MUT (%.2f elapsed), %.2f GC (%.2f elapsed) :ghc>>\n";
+          fmt2 = "%d GCs, %ld/%ld avg/max bytes residency (%ld samples), %luM in use, %.3f INIT (%.3f elapsed), %.3f MUT (%.3f elapsed), %.3f GC (%.3f elapsed) :ghc>>\n";
       }
 	  /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
 	  statsPrintf(fmt1, GC_tot_alloc*(StgWord64)sizeof(W_));