Fix GCStart message in StressLog and StressLogAnalyzer

eng/pipelines/common/evaluate-default-paths.yml

@@ -203,6 +203,12 @@ jobs:
       - src/coreclr/pal/*
       - src/coreclr/vm/*
 
+    # We have some GC code variants that only effect GC code.
+    # Only run legs that validate those variants on GC changes.
+    - subset: coreclr_GC
+      include:
+      - src/coreclr/gc/*
+
     #
     # ** WASM **
     # Changes in *only* Wasm.Build.Tests, debugger, or runtime-tests are very

eng/pipelines/global-build.yml

@@ -81,6 +81,24 @@ extends:
                 eq(stageDependencies.EvaluatePaths.evaluate_paths.outputs['SetPathVars_non_wasm.containsChange'], true),
                 eq(variables['isRollingBuild'], true))
 
+      #
+      # Build CoreCLR GC with TRACE_GC
+      #
+      - template: /eng/pipelines/common/platform-matrix.yml
+        parameters:
+          jobTemplate: /eng/pipelines/common/global-build-job.yml
+          buildConfig: Checked
+          runtimeFlavor: coreclr
+          platforms:
+            - linux_x64
+          jobParameters:
+            nameSuffix: CoreCLR_GC_TRACE_GC
+            buildArgs: -s clr.runtime -c $(_BuildConfig) -cmakeargs -DTRACE_GC=1
+            condition: >-
+              or(
+                eq(stageDependencies.EvaluatePaths.evaluate_paths.outputs['SetPathVars_coreclr_GC.containsChange'], true),
+                eq(variables['isRollingBuild'], true))
+
       #
       # Build Libraries AllConfigurations. This exercises the code path where we build libraries and tests for all
       # configurations on a non Windows operating system.

src/coreclr/gc/CMakeLists.txt

@@ -100,6 +100,10 @@ list(APPEND GC_SOURCES ${GC_HEADERS})
 
 convert_to_absolute_path(GC_SOURCES ${GC_SOURCES})
 
+if (TRACE_GC)
+  add_compile_definitions(TRACE_GC)
+endif (TRACE_GC)
+
 # clrgcexp is build with standalone+regions
 if (CLR_CMAKE_TARGET_ARCH_ARM64 OR CLR_CMAKE_TARGET_ARCH_AMD64)
   add_library_clr(clrgcexp SHARED ${GC_SOURCES})

src/coreclr/gc/env/gcenv.h

@@ -192,19 +192,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)

src/coreclr/gc/gc.cpp

@@ -43444,7 +43444,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 ----", str_gc_type()));
 #endif //BACKGROUND_GC
     settings.heap_expansion = TRUE;
 
@@ -48171,7 +48171,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"))));
+        str_gc_type()));
 #else
     dprintf (2,("[%s]GC#%zu: Verifying heap - begin",
                 (begin_gc_p ? "BEG" : "END"), VolatileLoad(&settings.gc_index)));
@@ -48578,7 +48578,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")),
+                 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));
@@ -48631,7 +48631,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"))));
+        str_gc_type()));
 #else
     dprintf (2,("GC#d: Verifying heap - end", VolatileLoad(&settings.gc_index)));
 #endif //BACKGROUND_GC
@@ -50392,6 +50392,13 @@ last_recorded_gc_info* gc_heap::get_completed_bgc_info()
 }
 #endif //BACKGROUND_GC
 
+#ifdef BACKGROUND_GC
+const char* gc_heap::str_gc_type()
+{
+    return (settings.concurrent ? "BGC" : (gc_heap::background_running_p () ? "FGC" : "NGC"));
+}
+#endif // BACKGROUND_GC
+
 void gc_heap::do_pre_gc()
 {
     STRESS_LOG_GC_STACK;
@@ -50420,14 +50427,18 @@ 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
 
 #ifdef 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,
@@ -50440,17 +50451,17 @@ 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")),
+        str_gc_type(),
         settings.b_state,
-        n_heaps,
-        (heap_size_before / 1000.0 / 1000.0),
-        (max_peak_heap_size / 1000.0 / 1000.0)));
+        n_heaps
+        SIMPLE_DPRINTF_ARG(heap_size_before / 1000.0 / 1000.0)
+        SIMPLE_DPRINTF_ARG(max_peak_heap_size / 1000.0 / 1000.0)));
 #else
-    dprintf (1, ("*GC* %d(gen0:%d)(%d)(alloc: %zd)",
+    dprintf (1, (ThreadStressLog::gcDetailedStartMsgNoBGC(),
         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])));
+        (total_allocated_since_last_gc[gc_oh_num::soh] + total_allocated_since_last_gc[gc_oh_num::loh] + total_allocated_since_last_gc[gc_oh_num::poh])));
 #endif //BACKGROUND_GC
 
     if (heap_hard_limit)
@@ -50871,17 +50882,17 @@ 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"));
+    const char* string_gc_type = str_gc_type();
 #else
-    const char* str_gc_type = "NGC";
+    const char* string_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,
+        string_gc_type,
         (settings.compaction ? "C" : "S"),
         (settings.promotion ? "P" : "S"),
         settings.entry_memory_load,

src/coreclr/gc/gc.h

@@ -344,7 +344,7 @@ inline bool IsServerHeap()
 #define MAX_LONGPATH 1024
 #endif // MAX_LONGPATH
 
-// #define TRACE_GC
+#define TRACE_GC
 // #define SIMPLE_DPRINTF
 
 #ifdef TRACE_GC
@@ -375,10 +375,14 @@ 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);
 //#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

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

src/coreclr/inc/gcmsg.inl

@@ -41,12 +41,39 @@
         return "%d gc thread waiting... Done";
     }
 
-    static const char* gcDetailedStartMsg()
+#define GC_DETAILED_START_PREFIX "*GC* %d(gen0:%d)(%d)"
+#define GC_DETAILED_START_STRESSLOG "(alloced for %.3fms, g0 %zd (b: %zd, %zd/h) (%.3fmb/ms), g3 %zd (%.3fmb/ms), g4 %zd (%.3fmb/ms))(%s)(%d)(%d)"
+#define GC_DETAILED_START_DPRINTF_EXTRA "(heap size: %.3fmb max: %.3fmb)"
+
+    static const char* gcDetailedStartPrefix()
+    {
+        STATIC_CONTRACT_LEAF;
+        return GC_DETAILED_START_PREFIX;
+    }
+
+    static const char* gcDetailedStartMsg(bool compatibleWithStressLog)
     {
         STATIC_CONTRACT_LEAF;
-        return "*GC* %d(gen0:%d)(%d)(alloced for %.3fms, g0 %zd (b: %zd, %zd/h) (%.3fmb/ms), g3 %zd (%.3fmb/ms), g4 %zd (%.3fmb/ms))(%s)(%d)(%d)(heap size: %.3fmb max: %.3fmb)";
+        if (compatibleWithStressLog)
+        {
+            return GC_DETAILED_START_PREFIX GC_DETAILED_START_STRESSLOG;
+        }
+        else
+        {
+            return GC_DETAILED_START_PREFIX GC_DETAILED_START_STRESSLOG GC_DETAILED_START_DPRINTF_EXTRA;
+        }
     }
 
+    static const char* gcDetailedStartMsgNoBGC()
+    {
+        STATIC_CONTRACT_LEAF;
+        return GC_DETAILED_START_PREFIX "(alloc: %zd)";
+    }
+
+#undef GC_DETAILED_START_PREFIX
+#undef GC_DETAILED_START_STRESSLOG
+#undef GC_DETAILED_START_DPRINTF_EXTRA
+
     static const char* gcDetailedEndMsg()
     {
         STATIC_CONTRACT_LEAF;

src/coreclr/inc/stresslog.h

@@ -371,19 +371,24 @@ typedef USHORT
     static StressLog theLog;    // We only have one log, and this is it
 };
 
-
-template<>
-void* StressLog::ConvertArgument(float arg) = delete;
-
 #if TARGET_64BIT
 template<>
 inline void* StressLog::ConvertArgument(double arg)
 {
     return (void*)(size_t)(*((uint64_t*)&arg));
 }
+
+// COMPAT: Convert 32-bit floats to 64-bit doubles.
+template<>
+inline void* StressLog::ConvertArgument(float arg)
+{
+    return StressLog::ConvertArgument((double)arg);
+}
 #else
 template<>
 void* StressLog::ConvertArgument(double arg) = delete;
+template<>
+void* StressLog::ConvertArgument(float arg) = delete;
 
 // COMPAT: Truncate 64-bit integer arguments to 32-bit
 template<>

src/coreclr/nativeaot/Runtime/inc/stressLog.h

@@ -344,19 +344,26 @@ class StressLog {
 };
 
 
-template<>
-void* StressLog::ConvertArgument(float arg) = delete;
-
 #if TARGET_64BIT
 template<>
 inline void* StressLog::ConvertArgument(double arg)
 {
     return (void*)(size_t)(*((uint64_t*)&arg));
 }
+
+// COMPAT: Convert 32-bit floats to 64-bit doubles.
+template<>
+inline void* StressLog::ConvertArgument(float arg)
+{
+    return StressLog::ConvertArgument((double)arg);
+}
 #else
 template<>
 void* StressLog::ConvertArgument(double arg) = delete;
 
+template<>
+void* StressLog::ConvertArgument(float arg) = delete;
+
 // COMPAT: Truncate 64-bit integer arguments to 32-bit
 template<>
 inline void* StressLog::ConvertArgument(uint64_t arg)

src/coreclr/tools/StressLogAnalyzer/StressLogDump.cpp

@@ -109,7 +109,7 @@ const char *getFacilityName(DWORD_PTR lf)
 /* be altered if format string contains %s                                         */
 // TODO: This function assumes the pointer size of the target equals the pointer size of the host
 // TODO: replace uses of void* with appropriate TADDR or CLRDATA_ADDRESS
-void formatOutput(struct IDebugDataSpaces* memCallBack, ___in FILE* file, __inout __inout_z char* format, uint64_t threadId, double timeStamp, DWORD_PTR facility, ___in void** args, bool fPrintFormatString)
+void formatOutput(struct IDebugDataSpaces* memCallBack, ___in FILE* file, __inout __inout_z char* format, uint64_t threadId, double timeStamp, DWORD_PTR facility, uint32_t numArgs, ___in void** inArgs, bool fPrintFormatString)
 {
     if (threadId & 0x8000000000000000)
         fprintf(file, "GC%2d %13.9f : ", (unsigned)threadId, timeStamp);
@@ -123,6 +123,15 @@ void formatOutput(struct IDebugDataSpaces* memCallBack, ___in FILE* file, __inou
     {
         fprintf(file, "***|\"%s\"|*** ", format);
     }
+
+    // Below we are going to pass substrings of the format with as-big-as-possibly-needed portions
+    // of the args array.  This allocates a larger args array to avoid buffer overruns.  Formats
+    // will have at most 16 arguments because the EE/GC interface doesn't allow more than that.
+    const int extraArgSlots = 16;
+    void** args = (void**)_alloca((numArgs + extraArgSlots) * sizeof(void*));
+    memcpy(args, inArgs, numArgs * sizeof(void*));
+    memset(&args[numArgs], 0, sizeof(extraArgSlots * sizeof(void*)));
+
     CQuickBytes fullname;
     void** argsPtr = args;
     static char formatCopy[256];
@@ -157,7 +166,7 @@ void formatOutput(struct IDebugDataSpaces* memCallBack, ___in FILE* file, __inou
                         // Print the string up to that point
                     c = *ptr;
                     *ptr = 0;       // Terminate the string temporarily
-                    fprintf(file, format, args[0], args[1], args[2], args[3], args[4], args[5], args[6], args[7], args[8], args[9], args[10]);
+                    fprintf(file, format, args[0], args[1], args[2], args[3], args[4], args[5], args[6], args[7], args[8], args[9], args[10], args[11], args[12], args[13], args[14], args[15]);
                     *ptr = c;       // Put it back
 
                         // move the argument pointers past the part the was printed
@@ -299,7 +308,7 @@ void formatOutput(struct IDebugDataSpaces* memCallBack, ___in FILE* file, __inou
     }
 
     // Print anything after the last special format instruction.
-    fprintf(file, format, args[0], args[1], args[2], args[3], args[4], args[5], args[6], args[7], args[8], args[9], args[10]);
+    fprintf(file, format, args[0], args[1], args[2], args[3], args[4], args[5], args[6], args[7], args[8], args[9], args[10], args[11], args[12], args[13], args[14], args[15]);
     fprintf(file, "\n");
 }
 
@@ -519,8 +528,10 @@ HRESULT StressLog::Dump(ULONG64 outProcLog, const char* fileName, struct IDebugD
                 }
                 else
                 {
+                    uint32_t numberOfArgs = latestMsg.GetNumberOfArgs();
                     args = latestMsg.GetArgs();
-                    formatOutput(memCallBack, file, format, (unsigned)latestLog->threadId, deltaTime, latestMsg.GetFacility(), args);
+                    formatOutput(memCallBack, file, format, (unsigned)latestLog->threadId, deltaTime, latestMsg.GetFacility(),
+                        numberOfArgs, args);
                 }
             }
             msgCtr++;