#include "ParTicky.h" /* ToDo: move into Rts.h */
#include "Profiling.h"
#include "GetTime.h"
+#include "GC.h"
+#include "GCUtils.h"
+#include "Evac.h"
+
+#if USE_PAPI
+#include "Papi.h"
+#endif
/* huh? */
#define BIG_STRING_LEN 512
static ullong GC_tot_alloc = 0;
static ullong GC_tot_copied = 0;
-static ullong GC_tot_scavd_copied = 0;
static Ticks GC_start_time = 0, GC_tot_time = 0; /* User GC Time */
static Ticks GCe_start_time = 0, GCe_tot_time = 0; /* Elapsed GC time */
static lnat GC_start_faults = 0, GC_end_faults = 0;
-static Ticks *GC_coll_times;
-
-static void statsPrintf( char *s, ... )
- GNUC3_ATTRIBUTE(format (printf, 1, 2));
+static Ticks *GC_coll_times = NULL;
+static Ticks *GC_coll_etimes = NULL;
static void statsFlush( void );
static void statsClose( void );
(Ticks *)stgMallocBytes(
sizeof(Ticks)*RtsFlags.GcFlags.generations,
"initStats");
+ GC_coll_etimes =
+ (Ticks *)stgMallocBytes(
+ sizeof(Ticks)*RtsFlags.GcFlags.generations,
+ "initStats");
for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
GC_coll_times[i] = 0;
+ GC_coll_etimes[i] = 0;
}
}
} else {
InitElapsedTime = elapsed - ElapsedTimeStart;
}
+#if USE_PAPI
+ /* We start counting events for the mutator
+ * when garbage collection starts
+ * we switch to the GC event set. */
+ papi_start_mutator_count();
+
+ /* This flag is needed to avoid counting the last GC */
+ papi_is_reporting = 1;
+
+#endif
}
/* -----------------------------------------------------------------------------
MutUserTime = user - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
if (MutUserTime < 0) { MutUserTime = 0; }
+
+#if USE_PAPI
+ /* We stop counting mutator events
+ * GC events are not being counted at this point */
+ papi_stop_mutator_count();
+
+ /* This flag is needed, because GC is run once more after this function */
+ papi_is_reporting = 0;
+
+#endif
}
void
GC_start_faults = getPageFaults();
}
}
+
+#if USE_PAPI
+ if(papi_is_reporting) {
+ /* Switch to counting GC events */
+ papi_stop_mutator_count();
+ papi_start_gc_count();
+ }
+#endif
+
}
/* -----------------------------------------------------------------------------
-------------------------------------------------------------------------- */
void
-stat_endGC (lnat alloc, lnat live, lnat copied,
- lnat scavd_copied, lnat gen)
+stat_endGC (lnat alloc, lnat live, lnat copied, lnat gen)
{
if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
Ticks time, etime, gc_time, gc_etime;
nat faults = getPageFaults();
statsPrintf("%9ld %9ld %9ld",
- alloc*sizeof(W_), (copied+scavd_copied)*sizeof(W_),
+ alloc*sizeof(W_), copied*sizeof(W_),
live*sizeof(W_));
statsPrintf(" %5.2f %5.2f %7.2f %7.2f %4ld %4ld (Gen: %2ld)\n",
TICK_TO_DBL(gc_time),
}
GC_coll_times[gen] += gc_time;
+ GC_coll_etimes[gen] += gc_etime;
GC_tot_copied += (ullong) copied;
- GC_tot_scavd_copied += (ullong) scavd_copied;
GC_tot_alloc += (ullong) alloc;
GC_tot_time += gc_time;
GCe_tot_time += gc_etime;
debugBelch("\b\b\b \b\b\b");
rub_bell = 0;
}
+
+#if USE_PAPI
+ if(papi_is_reporting) {
+ /* Switch to counting mutator events */
+ if (gen == 0) {
+ papi_stop_gc0_count();
+ } else {
+ papi_stop_gc1_count();
+ }
+ papi_start_mutator_count();
+ }
+#endif
}
/* -----------------------------------------------------------------------------
were left unused when the heap-check failed.
-------------------------------------------------------------------------- */
+#ifdef DEBUG
+#define TICK_VAR(arity) \
+ extern StgInt SLOW_CALLS_##arity; \
+ extern StgInt RIGHT_ARITY_##arity; \
+ extern StgInt TAGGED_PTR_##arity;
+
+#define TICK_VAR_INI(arity) \
+ StgInt SLOW_CALLS_##arity = 1; \
+ StgInt RIGHT_ARITY_##arity = 1; \
+ StgInt TAGGED_PTR_##arity = 0;
+
+extern StgInt TOTAL_CALLS;
+
+TICK_VAR(1)
+TICK_VAR(2)
+
+TICK_VAR_INI(1)
+TICK_VAR_INI(2)
+
+StgInt TOTAL_CALLS=1;
+#endif
+
+/* Report the value of a counter */
+#define REPORT(counter) \
+ { \
+ ullong_format_string(counter,temp,rtsTrue/*commas*/); \
+ statsPrintf(" (" #counter ") : %s\n",temp); \
+ }
+
+/* Report the value of a counter as a percentage of another counter */
+#define REPORT_PCT(counter,countertot) \
+ statsPrintf(" (" #counter ") %% of (" #countertot ") : %.1f%%\n", \
+ counter*100.0/countertot)
+
+#define TICK_PRINT(arity) \
+ REPORT(SLOW_CALLS_##arity); \
+ REPORT_PCT(RIGHT_ARITY_##arity,SLOW_CALLS_##arity); \
+ REPORT_PCT(TAGGED_PTR_##arity,RIGHT_ARITY_##arity); \
+ REPORT(RIGHT_ARITY_##arity); \
+ REPORT(TAGGED_PTR_##arity)
+
+#define TICK_PRINT_TOT(arity) \
+ statsPrintf(" (SLOW_CALLS_" #arity ") %% of (TOTAL_CALLS) : %.1f%%\n", \
+ SLOW_CALLS_##arity * 100.0/TOTAL_CALLS)
+
+
void
stat_exit(int alloc)
{
ullong_format_string(GC_tot_copied*sizeof(W_),
temp, rtsTrue/*commas*/);
- statsPrintf("%11s bytes copied during GC (scavenged)\n", temp);
+ statsPrintf("%11s bytes copied during GC\n", temp);
- ullong_format_string(GC_tot_scavd_copied*sizeof(W_),
- temp, rtsTrue/*commas*/);
- statsPrintf("%11s bytes copied during GC (not scavenged)\n", temp);
-
if ( ResidencySamples > 0 ) {
ullong_format_string(MaxResidency*sizeof(W_),
temp, rtsTrue/*commas*/);
/* Print garbage collections in each gen */
for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
- statsPrintf("%11d collections in generation %d (%6.2fs)\n",
+ statsPrintf("%11d collections in generation %d, %6.2fs, %6.2fs elapsed\n",
generations[g].collections, g,
- TICK_TO_DBL(GC_coll_times[g]));
+ TICK_TO_DBL(GC_coll_times[g]),
+ TICK_TO_DBL(GC_coll_etimes[g]));
}
- statsPrintf("\n%11ld Mb total memory in use\n\n",
+ statsPrintf("\n%11ld MB total memory in use\n\n",
mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
#if defined(THREADED_RTS)
TICK_TO_DBL(time - GC_tot_time -
PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100
/ TICK_TO_DBL(etime));
+
+ /*
+ TICK_PRINT(1);
+ TICK_PRINT(2);
+ REPORT(TOTAL_CALLS);
+ TICK_PRINT_TOT(1);
+ TICK_PRINT_TOT(2);
+ */
+
+#if USE_PAPI
+ papi_stats_report();
+#endif
}
if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
}
+#if defined(THREADED_RTS) && defined(PROF_SPIN)
+ {
+ nat g, s;
+
+ statsPrintf("recordMutableGen_sync: %"FMT_Word64"\n", recordMutableGen_sync.spin);
+ statsPrintf("gc_alloc_block_sync: %"FMT_Word64"\n", gc_alloc_block_sync.spin);
+ statsPrintf("whitehole_spin: %"FMT_Word64"\n", whitehole_spin);
+ for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
+ for (s = 0; s < generations[g].n_steps; s++) {
+ statsPrintf("gen[%d].steps[%d].sync_todo: %"FMT_Word64"\n", g, s, generations[g].steps[s].sync_todo.spin);
+ statsPrintf("gen[%d].steps[%d].sync_large_objects: %"FMT_Word64"\n", g, s, generations[g].steps[s].sync_large_objects.spin);
+ }
+ }
+ }
+#endif
+
statsFlush();
statsClose();
}
+
if (GC_coll_times)
stgFree(GC_coll_times);
GC_coll_times = NULL;
+ if (GC_coll_etimes)
+ stgFree(GC_coll_etimes);
+ GC_coll_etimes = NULL;
}
/* -----------------------------------------------------------------------------
Produce some detailed info on the state of the generational GC.
-------------------------------------------------------------------------- */
-#ifdef DEBUG
void
statDescribeGens(void)
{
for (bd = step->large_objects, lge = 0; bd; bd = bd->link) {
lge++;
}
- live = step->n_large_blocks * BLOCK_SIZE;
- bd = step->blocks;
// This live figure will be slightly less that the "live" figure
// given by +RTS -Sstderr, because we take don't count the
// slop at the end of each block.
- for (; bd; bd = bd->link) {
- live += (bd->free - bd->start) * sizeof(W_);
- }
+ live += countOccupied(step->blocks) + countOccupied(step->large_objects);
if (s != 0) {
debugBelch("%36s","");
}
}
debugBelch("\n");
}
-#endif
/* -----------------------------------------------------------------------------
Stats available via a programmatic interface, so eg. GHCi can time
Dumping stuff in the stats file, or via the debug message interface
-------------------------------------------------------------------------- */
-static void
+void
statsPrintf( char *s, ... )
{
FILE *sf = RtsFlags.GcFlags.statsFile;
projects / ghc-hetmet.git / blobdiff