Merge branch 'wip/tsan/stats' into wip/tsan/all

4 files changed, 62 insertions, 27 deletions

diff --git a/rts/RtsStartup.c b/rts/RtsStartup.c
index 6dd8c555f1..5e2495844c 100644
--- a/rts/RtsStartup.c
+++ b/rts/RtsStartup.c
@@ -581,6 +581,10 @@ hs_exit_(bool wait_foreign)
    if (is_io_mng_native_p())
       hs_restoreConsoleCP();
 #endif
+
+    /* tear down statistics subsystem */
+    stat_exit();
+
     /* free hash table storage */
     exitHashTable();
 
diff --git a/rts/Stats.c b/rts/Stats.c
index fcf48c3720..71dcf8a9d0 100644
--- a/rts/Stats.c
+++ b/rts/Stats.c
@@ -26,6 +26,11 @@
 
 #include <string.h> // for memset
 
+#if defined(THREADED_RTS)
+// Protects all statistics below
+Mutex stats_mutex;
+#endif
+
 static Time
     start_init_cpu, start_init_elapsed,
     end_init_cpu,   end_init_elapsed,
@@ -81,25 +86,6 @@ Time stat_getElapsedTime(void)
    Measure the current MUT time, for profiling
    ------------------------------------------------------------------------ */
 
-double
-mut_user_time_until( Time t )
-{
-    return TimeToSecondsDbl(t - stats.gc_cpu_ns - stats.nonmoving_gc_cpu_ns);
-    // heapCensus() time is included in GC_tot_cpu, so we don't need
-    // to subtract it here.
-
-    // TODO: This seems wrong to me. Surely we should be subtracting
-    // (at least) start_init_cpu?
-}
-
-double
-mut_user_time( void )
-{
-    Time cpu;
-    cpu = getProcessCPUTime();
-    return mut_user_time_until(cpu);
-}
-
 #if defined(PROFILING)
 /*
   mut_user_time_during_RP() returns the MUT time during retainer profiling.
@@ -120,6 +106,10 @@ mut_user_time_during_RP( void )
 void
 initStats0(void)
 {
+#if defined(THREADED_RTS)
+    initMutex(&stats_mutex);
+#endif
+
     start_init_cpu    = 0;
     start_init_elapsed = 0;
     end_init_cpu     = 0;
@@ -281,9 +271,11 @@ stat_endInit(void)
 void
 stat_startExit(void)
 {
+    ACQUIRE_LOCK(&stats_mutex);
     getProcessTimes(&start_exit_cpu, &start_exit_elapsed);
     start_exit_gc_elapsed = stats.gc_elapsed_ns;
     start_exit_gc_cpu = stats.gc_cpu_ns;
+    RELEASE_LOCK(&stats_mutex);
 }
 
 /* -----------------------------------------------------------------------------
@@ -294,7 +286,9 @@ stat_startExit(void)
 void
 stat_endExit(void)
 {
+    ACQUIRE_LOCK(&stats_mutex);
     getProcessTimes(&end_exit_cpu, &end_exit_elapsed);
+    RELEASE_LOCK(&stats_mutex);
 }
 
 void
@@ -306,8 +300,10 @@ stat_startGCSync (gc_thread *gct)
 void
 stat_startNonmovingGc ()
 {
+    ACQUIRE_LOCK(&stats_mutex);
     start_nonmoving_gc_cpu = getCurrentThreadCPUTime();
     start_nonmoving_gc_elapsed = getProcessCPUTime();
+    RELEASE_LOCK(&stats_mutex);
 }
 
 void
@@ -315,6 +311,8 @@ stat_endNonmovingGc ()
 {
     Time cpu = getCurrentThreadCPUTime();
     Time elapsed = getProcessCPUTime();
+
+    ACQUIRE_LOCK(&stats_mutex);
     stats.gc.nonmoving_gc_elapsed_ns = elapsed - start_nonmoving_gc_elapsed;
     stats.nonmoving_gc_elapsed_ns += stats.gc.nonmoving_gc_elapsed_ns;
 
@@ -324,12 +322,15 @@ stat_endNonmovingGc ()
     stats.nonmoving_gc_max_elapsed_ns =
       stg_max(stats.gc.nonmoving_gc_elapsed_ns,
               stats.nonmoving_gc_max_elapsed_ns);
+    RELEASE_LOCK(&stats_mutex);
 }
 
 void
 stat_startNonmovingGcSync ()
 {
+    ACQUIRE_LOCK(&stats_mutex);
     start_nonmoving_gc_sync_elapsed = getProcessElapsedTime();
+    RELEASE_LOCK(&stats_mutex);
     traceConcSyncBegin();
 }
 
@@ -337,13 +338,17 @@ void
 stat_endNonmovingGcSync ()
 {
     Time end_elapsed = getProcessElapsedTime();
+    ACQUIRE_LOCK(&stats_mutex);
     stats.gc.nonmoving_gc_sync_elapsed_ns = end_elapsed - start_nonmoving_gc_sync_elapsed;
     stats.nonmoving_gc_sync_elapsed_ns +=  stats.gc.nonmoving_gc_sync_elapsed_ns;
     stats.nonmoving_gc_sync_max_elapsed_ns =
       stg_max(stats.gc.nonmoving_gc_sync_elapsed_ns,
               stats.nonmoving_gc_sync_max_elapsed_ns);
+    Time sync_elapsed = stats.gc.nonmoving_gc_sync_elapsed_ns;
+    RELEASE_LOCK(&stats_mutex);
+
     if (RtsFlags.GcFlags.giveStats == VERBOSE_GC_STATS) {
-      statsPrintf("# sync %6.3f\n", TimeToSecondsDbl(stats.gc.nonmoving_gc_sync_elapsed_ns));
+      statsPrintf("# sync %6.3f\n", TimeToSecondsDbl(sync_elapsed));
     }
     traceConcSyncEnd();
 }
@@ -459,6 +464,8 @@ stat_endGC (Capability *cap, gc_thread *initiating_gct, W_ live, W_ copied, W_ s
             W_ mut_spin_spin, W_ mut_spin_yield, W_ any_work, W_ no_work,
             W_ scav_find_work)
 {
+    ACQUIRE_LOCK(&stats_mutex);
+
     // -------------------------------------------------
     // Collect all the stats about this GC in stats.gc. We always do this since
     // it's relatively cheap and we need allocated_bytes to catch heap
@@ -628,6 +635,7 @@ stat_endGC (Capability *cap, gc_thread *initiating_gct, W_ live, W_ copied, W_ s
                            CAPSET_HEAP_DEFAULT,
                            mblocks_allocated * MBLOCK_SIZE);
     }
+    RELEASE_LOCK(&stats_mutex);
 }
 
 /* -----------------------------------------------------------------------------
@@ -640,8 +648,10 @@ stat_startRP(void)
     Time user, elapsed;
     getProcessTimes( &user, &elapsed );
 
+    ACQUIRE_LOCK(&stats_mutex);
     RP_start_time = user;
     RPe_start_time = elapsed;
+    RELEASE_LOCK(&stats_mutex);
 }
 #endif /* PROFILING */
 
@@ -659,11 +669,14 @@ stat_endRP(
     Time user, elapsed;
     getProcessTimes( &user, &elapsed );
 
+    ACQUIRE_LOCK(&stats_mutex);
     RP_tot_time += user - RP_start_time;
     RPe_tot_time += elapsed - RPe_start_time;
+    double mut_time_during_RP = mut_user_time_during_RP();
+    RELEASE_LOCK(&stats_mutex);
 
     fprintf(prof_file, "Retainer Profiling: %d, at %f seconds\n",
-      retainerGeneration, mut_user_time_during_RP());
+            retainerGeneration, mut_time_during_RP);
     fprintf(prof_file, "\tMax auxiliary stack size = %u\n", maxStackSize);
     fprintf(prof_file, "\tAverage number of visits per object = %f\n",
             averageNumVisit);
@@ -680,8 +693,10 @@ stat_startHeapCensus(void)
     Time user, elapsed;
     getProcessTimes( &user, &elapsed );
 
+    ACQUIRE_LOCK(&stats_mutex);
     HC_start_time = user;
     HCe_start_time = elapsed;
+    RELEASE_LOCK(&stats_mutex);
 }
 #endif /* PROFILING */
 
@@ -695,8 +710,10 @@ stat_endHeapCensus(void)
     Time user, elapsed;
     getProcessTimes( &user, &elapsed );
 
+    ACQUIRE_LOCK(&stats_mutex);
     HC_tot_time += user - HC_start_time;
     HCe_tot_time += elapsed - HCe_start_time;
+    RELEASE_LOCK(&stats_mutex);
 }
 #endif /* PROFILING */
 
@@ -793,6 +810,7 @@ static void free_RTSSummaryStats(RTSSummaryStats * sum)
     sum->gc_summary_stats = NULL;
 }
 
+// Must hold stats_mutex.
 static void report_summary(const RTSSummaryStats* sum)
 {
     // We should do no calculation, other than unit changes and formatting, and
@@ -1195,6 +1213,7 @@ static void report_machine_readable (const RTSSummaryStats * sum)
     statsPrintf(" ]\n");
 }
 
+// Must hold stats_mutex.
 static void report_one_line(const RTSSummaryStats * sum)
 {
     // We should do no calculation, other than unit changes and formatting, and
@@ -1226,7 +1245,7 @@ static void report_one_line(const RTSSummaryStats * sum)
 }
 
 void
-stat_exit (void)
+stat_exitReport (void)
 {
     RTSSummaryStats sum;
     init_RTSSummaryStats(&sum);
@@ -1241,6 +1260,7 @@ stat_exit (void)
             Time now_cpu_ns, now_elapsed_ns;
             getProcessTimes(&now_cpu_ns, &now_elapsed_ns);
 
+            ACQUIRE_LOCK(&stats_mutex);
             stats.cpu_ns = now_cpu_ns - start_init_cpu;
             stats.elapsed_ns = now_elapsed_ns - start_init_elapsed;
             /* avoid divide by zero if stats.total_cpu_ns is measured as 0.00
@@ -1429,6 +1449,7 @@ stat_exit (void)
                 report_one_line(&sum);
             }
         }
+        RELEASE_LOCK(&stats_mutex);
 
         statsFlush();
         statsClose();
@@ -1452,6 +1473,13 @@ stat_exit (void)
     RELEASE_LOCK(&all_tasks_mutex);
 }
 
+void stat_exit()
+{
+#if defined(THREADED_RTS)
+        closeMutex(&stats_mutex);
+#endif
+}
+
 /* Note [Work Balance]
 ----------------------
 Work balance is a measure of how evenly the work done during parallel garbage
@@ -1669,7 +1697,10 @@ statDescribeGens(void)
 
 uint64_t getAllocations( void )
 {
-    return stats.allocated_bytes;
+    ACQUIRE_LOCK(&stats_mutex);
+    StgWord64 n = stats.allocated_bytes;
+    RELEASE_LOCK(&stats_mutex);
+    return n;
 }
 
 int getRTSStatsEnabled( void )
@@ -1682,7 +1713,9 @@ void getRTSStats( RTSStats *s )
     Time current_elapsed = 0;
     Time current_cpu = 0;
 
+    ACQUIRE_LOCK(&stats_mutex);
     *s = stats;
+    RELEASE_LOCK(&stats_mutex);
 
     getProcessTimes(&current_cpu, &current_elapsed);
     s->cpu_ns = current_cpu - end_init_cpu;
diff --git a/rts/Stats.h b/rts/Stats.h
index f5b8ce9991..9d62acef37 100644
--- a/rts/Stats.h
+++ b/rts/Stats.h
@@ -58,6 +58,7 @@ void      stat_endHeapCensus(void);
 void      stat_startExit(void);
 void      stat_endExit(void);
 
+void      stat_exitReport(void);
 void      stat_exit(void);
 void      stat_workerStop(void);
 
@@ -65,9 +66,6 @@ void      initStats0(void);
 void      initStats1(void);
 void      resetChildProcessStats(void);
 
-double    mut_user_time_until(Time t);
-double    mut_user_time(void);
-
 void      statDescribeGens( void );
 
 Time      stat_getElapsedGCTime(void);
diff --git a/rts/sm/Storage.c b/rts/sm/Storage.c
index 251353de6d..98aefa9a4b 100644
--- a/rts/sm/Storage.c
+++ b/rts/sm/Storage.c
@@ -302,7 +302,7 @@ exitStorage (void)
 {
     nonmovingExit();
     updateNurseriesStats();
-    stat_exit();
+    stat_exitReport();
 }
 
 void