Fix GC stress log and analysis

src/coreclr/gc/env/gcenv.h

@@ -97,7 +97,6 @@ enum LogFacility
     LF_GC       = 0x00000001,
     LF_GCALLOC  = 0x00000100,
     LF_GCROOTS  = 0x00080000,
-    LF_ALWAYS   = 0x80000000,
 };
 
 enum LogLevel
@@ -192,19 +191,25 @@ struct StressLogMsg
     }
 };
 
-template<>
-void* StressLogMsg::ConvertArgument(float arg) = delete;
-
 #if TARGET_64BIT
 template<>
 inline void* StressLogMsg::ConvertArgument(double arg)
 {
     return (void*)(size_t)(*((uint64_t*)&arg));
 }
+// COMPAT: Convert 32-bit floats to 64-bit doubles.
+template<>
+inline void* StressLogMsg::ConvertArgument(float arg)
+{
+    return StressLogMsg::ConvertArgument((double)arg);
+}
 #else
 template<>
 void* StressLogMsg::ConvertArgument(double arg) = delete;
 
+template<>
+void* StressLogMsg::ConvertArgument(float arg) = delete;
+
 // COMPAT: Truncate 64-bit integer arguments to 32-bit
 template<>
 inline void* StressLogMsg::ConvertArgument(uint64_t arg)
@@ -234,7 +239,7 @@ class StressLog
 
     static void LogMsg(unsigned dprintfLevel, const StressLogMsg& msg)
     {
-        GCToEEInterface::LogStressMsg(LL_ALWAYS, LF_ALWAYS|(dprintfLevel<<16)|LF_GC, msg);
+        GCToEEInterface::LogStressMsg(LL_ALWAYS, (dprintfLevel<<16)|LF_GC, msg);
     }
 
     static void LogMsg(unsigned level, unsigned facility, const StressLogMsg& msg)

src/coreclr/gc/gc.cpp

@@ -7442,7 +7442,7 @@ bool gc_heap::virtual_commit (void* address, size_t size, int bucket, int h_numb
 
             if ((base + size) > limit)
             {
-                dprintf (1, ("%zd + %zd = %zd > limit %zd ", base, size, (base + size), limit));
+                dprintf (2, ("%zd + %zd = %zd > limit %zd ", base, size, (base + size), limit));
                 exceeded_p = true;
             }
         }
@@ -8259,9 +8259,9 @@ uint8_t* get_plug_start_in_saved (uint8_t* old_loc, mark* pinned_plug_entry)
 {
     uint8_t* saved_pre_plug_info = (uint8_t*)(pinned_plug_entry->get_pre_plug_reloc_info());
     uint8_t* plug_start_in_saved = saved_pre_plug_info + (old_loc - (pinned_plug (pinned_plug_entry) - sizeof (plug_and_gap)));
-    //dprintf (1, ("detected a very short plug: %zx before PP %zx, pad %zx",
+    //dprintf (2, ("detected a very short plug: %zx before PP %zx, pad %zx",
     //    old_loc, pinned_plug (pinned_plug_entry), plug_start_in_saved));
-    dprintf (1, ("EP: %p(%p), %p", old_loc, pinned_plug (pinned_plug_entry), plug_start_in_saved));
+    dprintf (2, ("EP: %p(%p), %p", old_loc, pinned_plug (pinned_plug_entry), plug_start_in_saved));
     return plug_start_in_saved;
 }
 
@@ -13511,7 +13511,7 @@ void gc_heap::distribute_free_regions()
         }
     }
 
-    dprintf (1, ("moved %2zd regions (%8zd) to decommit based on time", num_decommit_regions_by_time, size_decommit_regions_by_time));
+    dprintf (REGIONS_LOG, ("moved %2zd regions (%8zd) to decommit based on time", num_decommit_regions_by_time, size_decommit_regions_by_time));
 
     global_free_huge_regions.transfer_regions (&global_regions_to_decommit[huge_free_region]);
 
@@ -30793,7 +30793,7 @@ void gc_heap::realloc_plan_generation_start (generation* gen, generation* consin
         generation_allocation_pointer (consing_gen) += allocation_left;
     }
 
-    dprintf (1, ("plan re-alloc gen%d start at %p (ptr: %p, limit: %p)", gen->gen_num,
+    dprintf (2, ("plan re-alloc gen%d start at %p (ptr: %p, limit: %p)", gen->gen_num,
         generation_plan_allocation_start (consing_gen),
         generation_allocation_pointer (consing_gen),
         generation_allocation_limit (consing_gen)));
@@ -32337,7 +32337,7 @@ void gc_heap::process_remaining_regions (int current_plan_gen_num, generation* c
         }
     }
 
-    dprintf (1, ("we still need %d regions, %d will be empty", plan_regions_needed, to_be_empty_regions));
+    dprintf (REGIONS_LOG, ("we still need %d regions, %d will be empty", plan_regions_needed, to_be_empty_regions));
     if (plan_regions_needed > to_be_empty_regions)
     {
         dprintf (REGIONS_LOG, ("h%d %d regions will be empty but we still need %d regions!!", heap_number, to_be_empty_regions, plan_regions_needed));
@@ -33693,7 +33693,7 @@ void gc_heap::plan_phase (int condemned_gen_number)
 #else
                 0;
 #endif //SHORT_PLUGS
-            dprintf (1, ("gen%d: NON PIN alloc: %zd, pin com: %zd, sweep: %zd, surv: %zd, pinsurv: %zd(%d%% added, %d%% art), np surv: %zd, pad: %zd",
+            dprintf (2, ("gen%d: NON PIN alloc: %zd, pin com: %zd, sweep: %zd, surv: %zd, pinsurv: %zd(%d%% added, %d%% art), np surv: %zd, pad: %zd",
                 gen_idx,
                 generation_allocation_size (temp_gen),
                 generation_pinned_allocation_compact_size (temp_gen),
@@ -43414,7 +43414,7 @@ generation* gc_heap::expand_heap (int condemned_generation,
     BOOL should_promote_ephemeral = FALSE;
     ptrdiff_t eph_size = total_ephemeral_size;
 #ifdef BACKGROUND_GC
-    dprintf(2,("%s: ---- Heap Expansion ----", (gc_heap::background_running_p() ? "FGC" : "NGC")));
+    dprintf(2,("%s: ---- Heap Expansion ----", get_str_gc_type()));
 #endif //BACKGROUND_GC
     settings.heap_expansion = TRUE;
 
@@ -43916,7 +43916,7 @@ size_t gc_heap::desired_new_allocation (dynamic_data* dd,
                 {
                     size_t allocated = 0;
                     size_t committed = uoh_committed_size (gen_number, &allocated);
-                    dprintf (1, ("GC#%zd h%d, GMI: UOH budget, UOH commit %zd (obj %zd, frag %zd), total commit: %zd (recorded: %zd)",
+                    dprintf (2, ("GC#%zd h%d, GMI: UOH budget, UOH commit %zd (obj %zd, frag %zd), total commit: %zd (recorded: %zd)",
                         (size_t)settings.gc_index, heap_number,
                         committed, allocated,
                         dd_fragmentation (dynamic_data_of (gen_number)),
@@ -43993,7 +43993,7 @@ size_t gc_heap::desired_new_allocation (dynamic_data* dd,
 
         dd_surv (dd) = cst;
 
-        dprintf (1, (ThreadStressLog::gcDesiredNewAllocationMsg(),
+        dprintf (2, (ThreadStressLog::gcDesiredNewAllocationMsg(),
                     heap_number, gen_number, out, current_size, (dd_desired_allocation (dd) - dd_gc_new_allocation (dd)),
                     (int)(cst*100), (int)(f*100), current_size + new_allocation, new_allocation));
 
@@ -47292,18 +47292,18 @@ void gc_heap::descr_generations (const char* msg)
 #endif //!TRACE_GC
 
 #ifdef STRESS_LOG
-    if (StressLog::StressLogOn(LF_GC, LL_INFO10))
+    if (StressLog::StressLogOn(LF_GC, LL_INFO1000))
     {
         gc_heap* hp = 0;
 #ifdef MULTIPLE_HEAPS
         hp= this;
 #endif //MULTIPLE_HEAPS
 
-        STRESS_LOG1(LF_GC, LL_INFO10, "GC Heap %p\n", hp);
+        STRESS_LOG1(LF_GC, LL_INFO1000, "GC Heap %p\n", hp);
         for (int n = max_generation; n >= 0; --n)
         {
 #ifndef USE_REGIONS
-            STRESS_LOG4(LF_GC, LL_INFO10, "    Generation %d [%p, %p] cur = %p\n",
+            STRESS_LOG4(LF_GC, LL_INFO1000, "    Generation %d [%p, %p] cur = %p\n",
                     n,
                     generation_allocation_start(generation_of(n)),
                     generation_allocation_limit(generation_of(n)),
@@ -47313,7 +47313,7 @@ void gc_heap::descr_generations (const char* msg)
             heap_segment* seg = generation_start_segment(generation_of(n));
             while (seg)
             {
-                STRESS_LOG4(LF_GC, LL_INFO10, "        Segment mem %p alloc = %p used %p committed %p\n",
+                STRESS_LOG4(LF_GC, LL_INFO1000, "        Segment mem %p alloc = %p used %p committed %p\n",
                         heap_segment_mem(seg),
                         heap_segment_allocated(seg),
                         heap_segment_used(seg),
@@ -48141,7 +48141,7 @@ void gc_heap::verify_heap (BOOL begin_gc_p)
     dprintf (2,("[%s]GC#%zu(%s): Verifying heap - begin",
         (begin_gc_p ? "BEG" : "END"),
         VolatileLoad(&settings.gc_index),
-        (settings.concurrent ? "BGC" : (gc_heap::background_running_p() ? "FGC" : "NGC"))));
+        get_str_gc_type()));
 #else
     dprintf (2,("[%s]GC#%zu: Verifying heap - begin",
                 (begin_gc_p ? "BEG" : "END"), VolatileLoad(&settings.gc_index)));
@@ -48548,7 +48548,7 @@ void gc_heap::verify_heap (BOOL begin_gc_p)
 
 #ifdef BACKGROUND_GC
     dprintf (2, ("(%s)(%s)(%s) total_objects_verified is %zd, total_objects_verified_deep is %zd",
-                 (settings.concurrent ? "BGC" : (gc_heap::background_running_p () ? "FGC" : "NGC")),
+                 get_str_gc_type(),
                  (begin_gc_p ? "BEG" : "END"),
                  ((current_c_gc_state == c_gc_state_planning) ? "in plan" : "not in plan"),
                  total_objects_verified, total_objects_verified_deep));
@@ -48601,7 +48601,7 @@ void gc_heap::verify_heap (BOOL begin_gc_p)
     }
     dprintf (2,("GC%zu(%s): Verifying heap - end",
         VolatileLoad(&settings.gc_index),
-        (settings.concurrent ? "BGC" : (gc_heap::background_running_p() ? "FGC" : "NGC"))));
+        get_str_gc_type()));
 #else
     dprintf (2,("GC#d: Verifying heap - end", VolatileLoad(&settings.gc_index)));
 #endif //BACKGROUND_GC
@@ -50362,6 +50362,15 @@ last_recorded_gc_info* gc_heap::get_completed_bgc_info()
 }
 #endif //BACKGROUND_GC
 
+const char* gc_heap::get_str_gc_type()
+{
+#ifdef BACKGROUND_GC
+    return (settings.concurrent ? "BGC" : (gc_heap::background_running_p () ? "FGC" : "NGC"));
+#else // BACKGROUND_GC
+    return "NGC";
+#endif // BACKGROUND_GC
+}
+
 void gc_heap::do_pre_gc()
 {
     STRESS_LOG_GC_STACK;
@@ -50390,14 +50399,21 @@ void gc_heap::do_pre_gc()
 #ifdef TRACE_GC
     size_t total_allocated_since_last_gc[total_oh_count];
     get_total_allocated_since_last_gc (total_allocated_since_last_gc);
-
+    bool compatibleWithStressLog = true;
+#ifdef SIMPLE_DPRINTF
+    compatibleWithStressLog = false;
+#endif //SIMPLE_DPRINTF
+    bgc_state b_state = bgc_not_in_process;
 #ifdef BACKGROUND_GC
+    b_state = settings.b_state;
+#endif //BACKGROUND_GC
+
     size_t heap_size_before = get_total_heap_size();
     uint64_t start_gc_time = GetHighPrecisionTimeStamp();
     uint64_t elapsed_since_last_gc_us = start_gc_time - last_alloc_reset_suspended_end_time;
     max_peak_heap_size = max (max_peak_heap_size, heap_size_before);
 
-    dprintf (6666, (ThreadStressLog::gcDetailedStartMsg(),
+    dprintf (6666, (ThreadStressLog::gcDetailedStartMsg(compatibleWithStressLog),
         VolatileLoad(&settings.gc_index),
         dd_collection_count (hp->dynamic_data_of (0)),
         settings.condemned_generation,
@@ -50410,18 +50426,11 @@ void gc_heap::do_pre_gc()
         (elapsed_since_last_gc_us ? (total_allocated_since_last_gc[gc_oh_num::loh] / 1000.0 / elapsed_since_last_gc_us) : 0),
         total_allocated_since_last_gc[gc_oh_num::poh],
         (elapsed_since_last_gc_us ? (total_allocated_since_last_gc[gc_oh_num::poh] / 1000.0 / elapsed_since_last_gc_us) : 0),
-        (settings.concurrent ? "BGC" : (gc_heap::background_running_p() ? "FGC" : "NGC")),
-        settings.b_state,
-        n_heaps,
-        (heap_size_before / 1000.0 / 1000.0),
-        (max_peak_heap_size / 1000.0 / 1000.0)));
-#else
-    dprintf (1, ("*GC* %d(gen0:%d)(%d)(alloc: %zd)",
-        VolatileLoad(&settings.gc_index),
-        dd_collection_count(hp->dynamic_data_of(0)),
-        settings.condemned_generation,
-        (total_allocated_since_last_gc[0] + total_allocated_since_last_gc[1] + total_allocated_since_last_gc[2])));
-#endif //BACKGROUND_GC
+        get_str_gc_type(),
+        b_state,
+        n_heaps
+        SIMPLE_DPRINTF_ARG(heap_size_before / 1000.0 / 1000.0)
+        SIMPLE_DPRINTF_ARG(max_peak_heap_size / 1000.0 / 1000.0)));
 
     if (heap_hard_limit)
     {
@@ -50840,18 +50849,12 @@ void gc_heap::do_post_gc()
     }
 #endif //BGC_SERVO_TUNING
 
-#ifdef BACKGROUND_GC
-    const char* str_gc_type = (settings.concurrent ? "BGC" : (gc_heap::background_running_p () ? "FGC" : "NGC"));
-#else
-    const char* str_gc_type = "NGC";
-#endif //BACKGROUND_GC
-
     dprintf (6666, (ThreadStressLog::gcDetailedEndMsg(),
         VolatileLoad (&settings.gc_index),
         dd_collection_count (hp->dynamic_data_of (0)),
         (get_total_heap_size() / 1000.0 / 1000.0),
         settings.condemned_generation,
-        str_gc_type,
+        get_str_gc_type(),
         (settings.compaction ? "C" : "S"),
         (settings.promotion ? "P" : "S"),
         settings.entry_memory_load,

src/coreclr/gc/gc.h

@@ -344,9 +344,23 @@ inline bool IsServerHeap()
 #define MAX_LONGPATH 1024
 #endif // MAX_LONGPATH
 
-// #define TRACE_GC
+// TRACE_GC has two sub-modes: the standard VM stress log mechanism and
+// SIMPLE_DPRINTF, which is text output.  By default, we enable TRACE_GC (not
+// SIMPLE_DPRINTF) for debug/checked builds so that we can catch build breaks.
+// HOST_64BIT is required because logging dprintf to the stress log us only
+// supported on 64 bit platforms.  We could consider enabling it in release
+// builds and for more logging sites (see below for details) but are being
+// conservative about performance impact.
+//
+// Normal development time changes are to enable SIMPLE_DPRINTF here (which
+// will automatically set TRACE_GC) or to only enable TRACE_GC.
+
 // #define SIMPLE_DPRINTF
 
+#if defined(SIMPLE_DPRINTF) || (defined(_DEBUG) && defined(HOST_64BIT))
+#define TRACE_GC
+#endif // _DEBUG
+
 #ifdef TRACE_GC
 #define MIN_CUSTOM_LOG_LEVEL 7
 #define SEG_REUSE_LOG_0 (MIN_CUSTOM_LOG_LEVEL)
@@ -375,10 +389,79 @@ HRESULT initialize_log_file();
 void flush_gc_log (bool);
 void GCLog (const char *fmt, ... );
 #define dprintf(l,x) {if ((l == 1) || (l == GTC_LOG)) {GCLog x;}}
+#define SIMPLE_DPRINTF_ARG(x) , x
+
 #else //SIMPLE_DPRINTF
+
 #ifdef HOST_64BIT
-#define dprintf(l,x) STRESS_LOG_VA(l,x);
+
+// -------------------------------
+// Stress log / dprintf background
+// -------------------------------
+//
+// This code connects dprintf to the stress log mechanism.  These machanisms
+// and their usage has evolved a bit separately over time, so there are some
+// rough edges here.
+//
+// The stress log mechanism has a LogFacility and a LogLevel.  Facilities can be
+// chosen through DOTNET_LogFacility, and the facility is recorded in the
+// stress log.  LogFacility is a bitmask.  The GC only has a few bits reserved
+// in the bitmask, and most GC logging uses a single value (LF_GC, which is 0x1).
+//
+// The stress log logging level can be chosen through DOTNET_LogLevel.  This
+// causes filtering at runtime, and the level is not recorded in the stress log.
+// The first argument to dprintf is similar, though it can record either a level
+// (values below 7) or a GC area (values starting with SEG_REUSE_LOG_0 above).
+// Developers often use StressLogAnalyzer to filter by this value at _analysis_
+// time, which doesn't match usual stress log usage.
+//
+// In practice, dprintf(1) and LL_INFO10 (which has the value 4) have been used
+// similarly on log messages.  A dprintf(1) is generally called about once per
+// GC, and LL_INFO10 is "10 logs per small but not trivial run".  Other values
+// have been audited.  We could consider moving the GC values to be in line with
+// the rest of the runtime (change 1 to 4 to make room for errors/warnings, etc.)
+// or (to avoid churn) convert them by adding 3.
+//
+// To allow StressLogAnalyzer to use the GC level values, we abuse the stress
+// log LogLevel by storing the GC value in the upper 16 bits of LogLevel and
+// also settings LF_GC (0x1).  This works because we don't enable other logging
+// when doing GC investigations.  However, we don't want to do this by default
+// because setting the upper bits will cause GC logging to masquerade as non-GC
+// logging.  For example, dprintf(3) would use (3 << 16) | LF_GC == 0x30001,
+// which is LF_ASSERT | LF_VERIFIER | LF_GC in other contexts.
+//
+// Lastly, we have GC logging for some very low level operations, so by default
+// we don't want to even have the check that logging is enabled for performance
+// reasons.  Right now we are very conservative and only allow dprintf(1) to go
+// to the stress log in default builds, but we could consider allowing more in
+// the future.
+
+// -----------------------------
+// Stress log / dprintf settings
+// -----------------------------
+//
+// (See above for details.)
+//
+// The following line works for normal debug/checked builds (where STRESS_LOG is
+// defined and SIMPLE_DPRINTF is not).  All dprintf sites are checked for
+// compilation errors, yet all but those with level 1 can be statically
+// optimized away.  In the future after more auditing, this could be expanded to
+// more levels.
+//
+// Note that zero is passed because STRESS_LOG_VA/LogMsg will add LF_GC and in
+// normal builds we don't want conflicts in the upper bits of LogFacility.
+#define dprintf(l,x) if (l == 1) {STRESS_LOG_VA(0,x);}
+
+// For private builds where it is ok (and useful) to have conflicts in the upper
+// bits of LogFacility, more events can be allowed and the dprintf level can be
+// passed through.  Usually this is going to be a GC investigation and the other
+// logging will be disabled, so the theoretical conflict won't happen in
+// practice.  Note that in these examples, 'l' ("ell", not "one") is passed
+// rather than '0'.
+//#define dprintf(l,x) STRESS_LOG_VA(l,x);
 //#define dprintf(l,x) {if ((l <= 2) || (l == 6666)) {STRESS_LOG_VA(l,x);}}
+
+#define SIMPLE_DPRINTF_ARG(x)
 #else //HOST_64BIT
 #error Logging dprintf to stress log on 32 bits platforms is not supported.
 #endif //HOST_64BIT

src/coreclr/gc/gcpriv.h

@@ -1573,6 +1573,8 @@ class gc_heap
 
 private:
 
+    PER_HEAP_ISOLATED_METHOD const char* get_str_gc_type();
+
 #ifdef TRACE_GC
     PER_HEAP_METHOD void print_free_list (int gen, heap_segment* seg);
 #endif // TRACE_GC