[commit: ghc] master: Increase precision of timings reported by RTS (57ed410)
git at git.haskell.org
git at git.haskell.org
Mon Jul 28 08:48:44 UTC 2014
Repository : ssh://git@git.haskell.org/ghc
On branch : master
Link : http://ghc.haskell.org/trac/ghc/changeset/57ed4101687651ba3de59fb75355f4b83ffdca75/ghc
>---------------------------------------------------------------
commit 57ed4101687651ba3de59fb75355f4b83ffdca75
Author: Herbert Valerio Riedel <hvr at gnu.org>
Date: Sat Jul 26 11:05:22 2014 +0200
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
>---------------------------------------------------------------
57ed4101687651ba3de59fb75355f4b83ffdca75
nofib | 2 +-
rts/Stats.c | 40 ++++++++++++++++++++--------------------
2 files changed, 21 insertions(+), 21 deletions(-)
diff --git a/nofib b/nofib
index d98f703..5bc1c75 160000
--- a/nofib
+++ b/nofib
@@ -1 +1 @@
-Subproject commit d98f7038d1111e515db9cc27d5d3bbe237e6e14f
+Subproject commit 5bc1c75db2c74413959772c85d43f8171fdd7b8c
diff --git a/rts/Stats.c b/rts/Stats.c
index c3d963c..894e9d2 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_));
More information about the ghc-commits
mailing list