Improve GC stress log instrumentation (#53547)

src/coreclr/gc/env/gcenv.h

@@ -195,131 +195,7 @@ enum LogLevel
 class ThreadStressLog
 {
 public:
-    static const char* gcStartMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "{ =========== BEGINGC %d, (requested generation = %lu, collect_classes = %lu) ==========\n";
-    }
-
-    static const char* gcEndMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "========== ENDGC %d (gen = %lu, collect_classes = %lu) ===========}\n";
-    }
-
-    static const char* gcRootMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "    GC Root %p RELOCATED %p -> %p  MT = %pT\n";
-    }
-
-    static const char* gcRootPromoteMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "    IGCHeap::Promote: Promote GC Root *%p = %p MT = %pT\n";
-    }
-
-    static const char* gcPlugMoveMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "GC_HEAP RELOCATING Objects in heap within range [%p %p) by -0x%x bytes\n";
-    }
-
-    static const char* gcServerThread0StartMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "%d gc thread waiting...";
-    }
-
-    static const char* gcServerThreadNStartMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "%d gc thread waiting... Done";
-    }
-
-    static const char* gcDetailedStartMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "*GC* %d(gen0:%d)(%d)(alloc: %Id)(%s)(%d)";
-    }
-
-    static const char* gcDetailedEndMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "*EGC* %Id(gen0:%Id)(%Id)(%d)(%s)(%s)(%s)(ml: %d->%d)";
-    }
-
-    static const char* gcStartMarkMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "---- Mark Phase on heap %d condemning %d ----";
-    }
-
-    static const char* gcStartPlanMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "---- Plan Phase on heap %d ---- Condemned generation %d, promotion: %d";
-    }
-
-    static const char* gcStartRelocateMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "---- Relocate phase on heap %d -----";
-    }
-
-    static const char* gcEndRelocateMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "---- End of Relocate phase on heap %d ----";
-    }
-
-    static const char* gcStartCompactMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "---- Compact Phase on heap %d: %Ix(%Ix)----";
-    }
-
-    static const char* gcEndCompactMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "---- End of Compact phase on heap %d ----";
-    }
-
-    static const char* gcMemCopyMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return " mc: [%Ix->%Ix, %Ix->%Ix[";
-    }
-
-    static const char* gcPlanPlugMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "(%Ix)[%Ix->%Ix, NA: [%Ix(%Id), %Ix[: %Ix(%d), x: %Ix (%s)";
-    }
-
-    static const char* gcPlanPinnedPlugMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "(%Ix)PP: [%Ix, %Ix[%Ix](m:%d)";
-    }
-
-    static const char* gcDesiredNewAllocationMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "h%d g%d surv: %Id current: %Id alloc: %Id (%d%%) f: %d%% new-size: %Id new-alloc: %Id";
-    }
-
-    static const char* gcMakeUnusedArrayMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "Making unused array [%Ix, %Ix[";
-    }
-
-    static const char* gcStartBgcThread()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "beginning of bgc on heap %d: gen2 FL: %d, FO: %d, frag: %d";
-    }
+    #include "../../inc/gcmsg.inl"
 };
 
 struct StressLogMsg

src/coreclr/gc/gc.cpp

@@ -29214,6 +29214,7 @@ void gc_heap::relocate_address (uint8_t** pold_address THREAD_NUMBER_DCL)
             }
         }
 
+        dprintf (4, (ThreadStressLog::gcRelocateReferenceMsg(), pold_address, old_address, new_address));
         *pold_address = new_address;
         return;
     }
@@ -29243,7 +29244,9 @@ void gc_heap::relocate_address (uint8_t** pold_address THREAD_NUMBER_DCL)
 #endif
                 )
             {
-                *pold_address = old_address + loh_node_relocation_distance (old_address);
+                new_address = old_address + loh_node_relocation_distance (old_address);
+                dprintf (4, (ThreadStressLog::gcRelocateReferenceMsg(), pold_address, old_address, new_address));
+                *pold_address = new_address;
             }
         }
     }

src/coreclr/inc/gcmsg.inl

+
+    static const char* gcStartMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "{ =========== BEGINGC %d, (requested generation = %lu, collect_classes = %lu) ==========\n";
+    }
+
+    static const char* gcEndMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "========== ENDGC %d (gen = %lu, collect_classes = %lu) ===========}\n";
+    }
+
+    static const char* gcRootMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "    GC Root %p RELOCATED %p -> %p  MT = %pT\n";
+    }
+
+    static const char* gcRootPromoteMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "    IGCHeap::Promote: Promote GC Root *%p = %p MT = %pT\n";
+    }
+
+    static const char* gcPlugMoveMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "GC_HEAP RELOCATING Objects in heap within range [%p %p) by -0x%x bytes\n";
+    }
+
+    static const char* gcServerThread0StartMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "%d gc thread waiting...";
+    }
+
+    static const char* gcServerThreadNStartMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "%d gc thread waiting... Done";
+    }
+
+    static const char* gcDetailedStartMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "*GC* %d(gen0:%d)(%d)(alloc: %Id)(%s)(%d)";
+    }
+
+    static const char* gcDetailedEndMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "*EGC* %Id(gen0:%Id)(%Id)(%d)(%s)(%s)(%s)(ml: %d->%d)";
+    }
+
+    static const char* gcStartMarkMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "---- Mark Phase on heap %d condemning %d ----";
+    }
+
+    static const char* gcStartPlanMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "---- Plan Phase on heap %d ---- Condemned generation %d, promotion: %d";
+    }
+
+    static const char* gcStartRelocateMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "---- Relocate phase on heap %d -----";
+    }
+
+    static const char* gcEndRelocateMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "---- End of Relocate phase on heap %d ----";
+    }
+
+    static const char* gcStartCompactMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "---- Compact Phase on heap %d: %Ix(%Ix)----";
+    }
+
+    static const char* gcEndCompactMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "---- End of Compact phase on heap %d ----";
+    }
+
+    static const char* gcMemCopyMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return " mc: [%Ix->%Ix, %Ix->%Ix[";
+    }
+
+    static const char* gcPlanPlugMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "(%Ix)[%Ix->%Ix, NA: [%Ix(%Id), %Ix[: %Ix(%d), x: %Ix (%s)";
+    }
+
+    static const char* gcPlanPinnedPlugMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "(%Ix)PP: [%Ix, %Ix[%Ix](m:%d)";
+    }
+
+    static const char* gcDesiredNewAllocationMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "h%d g%d surv: %Id current: %Id alloc: %Id (%d%%) f: %d%% new-size: %Id new-alloc: %Id";
+    }
+
+    static const char* gcMakeUnusedArrayMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "Making unused array [%Ix, %Ix[";
+    }
+
+    static const char* gcStartBgcThread()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "beginning of bgc on heap %d: gen2 FL: %d, FO: %d, frag: %d";
+    }
+
+    static const char* gcRelocateReferenceMsg()
+    {
+        STATIC_CONTRACT_LEAF;
+        return "Relocating reference *(%p) from %p to %p";
+    }

src/coreclr/inc/stresslog.h

@@ -787,131 +787,7 @@ public:
     }
 #endif //STRESS_LOG_READONLY
 
-    static const char* gcStartMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "{ =========== BEGINGC %d, (requested generation = %lu, collect_classes = %lu) ==========\n";
-    }
-
-    static const char* gcEndMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "========== ENDGC %d (gen = %lu, collect_classes = %lu) ===========}\n";
-    }
-
-    static const char* gcRootMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "    GC Root %p RELOCATED %p -> %p  MT = %pT\n";
-    }
-
-    static const char* gcRootPromoteMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "    IGCHeap::Promote: Promote GC Root *%p = %p MT = %pT\n";
-    }
-
-    static const char* gcPlugMoveMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "GC_HEAP RELOCATING Objects in heap within range [%p %p) by -0x%x bytes\n";
-    }
-
-    static const char* gcServerThread0StartMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "%d gc thread waiting...";
-    }
-
-    static const char* gcServerThreadNStartMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "%d gc thread waiting... Done";
-    }
-
-    static const char* gcDetailedStartMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "*GC* %d(gen0:%d)(%d)(alloc: %Id)(%s)(%d)";
-    }
-
-    static const char* gcDetailedEndMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "*EGC* %Id(gen0:%Id)(%Id)(%d)(%s)(%s)(%s)(ml: %d->%d)";
-    }
-
-    static const char* gcStartMarkMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "---- Mark Phase on heap %d condemning %d ----";
-    }
-
-    static const char* gcStartPlanMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "---- Plan Phase on heap %d ---- Condemned generation %d, promotion: %d";
-    }
-
-    static const char* gcStartRelocateMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "---- Relocate phase on heap %d -----";
-    }
-
-    static const char* gcEndRelocateMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "---- End of Relocate phase on heap %d ----";
-    }
-
-    static const char* gcStartCompactMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "---- Compact Phase on heap %d: %Ix(%Ix)----";
-    }
-
-    static const char* gcEndCompactMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "---- End of Compact phase on heap %d ----";
-    }
-
-    static const char* gcMemCopyMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return " mc: [%Ix->%Ix, %Ix->%Ix[";
-    }
-
-    static const char* gcPlanPlugMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "(%Ix)[%Ix->%Ix, NA: [%Ix(%Id), %Ix[: %Ix(%d), x: %Ix (%s)";
-    }
-
-    static const char* gcPlanPinnedPlugMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "(%Ix)PP: [%Ix, %Ix[%Ix](m:%d)";
-    }
-
-    static const char* gcDesiredNewAllocationMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "h%d g%d surv: %Id current: %Id alloc: %Id (%d%%) f: %d%% new-size: %Id new-alloc: %Id";
-    }
-
-    static const char* gcMakeUnusedArrayMsg()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "Making unused array [%Ix, %Ix[";
-    }
-
-    static const char* gcStartBgcThread()
-    {
-        STATIC_CONTRACT_LEAF;
-        return "beginning of bgc on heap %d: gen2 FL: %d, FO: %d, frag: %d";
-    }
+    #include "gcmsg.inl"
 
     static const char* TaskSwitchMsg()
     {

src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/StressLogPlugin.cpp

@@ -139,6 +139,7 @@ d(IS_PLAN_PINNED_PLUG,          ThreadStressLog::gcPlanPinnedPlugMsg())
 d(IS_DESIRED_NEW_ALLOCATION,    ThreadStressLog::gcDesiredNewAllocationMsg())                                               \
 d(IS_MAKE_UNUSED_ARRAY,         ThreadStressLog::gcMakeUnusedArrayMsg())                                                    \
 d(IS_START_BGC_THREAD,          ThreadStressLog::gcStartBgcThread())                                                        \
+d(IS_RELOCATE_REFERENCE,        ThreadStressLog::gcRelocateReferenceMsg())                                                  \
 d(IS_UNINTERESTING,             "")
 
 enum InterestingStringId : unsigned char
@@ -469,6 +470,26 @@ bool FilterMessage(StressLog::StressLogHeader* hdr, ThreadStressLog* tsl, uint32
     case    IS_START_BGC_THREAD:
         RememberThreadForHeap(tsl->threadId, (int64_t)args[0], GC_THREAD_BG);
         break;
+    case    IS_RELOCATE_REFERENCE:
+        if (s_valueFilterCount > 0)
+        {
+            size_t src = (size_t)args[0];
+            size_t dst_from = (size_t)args[1];
+            size_t dst_to = (size_t)args[2];
+            // print this message if the source or destination contain (part of) the range we're looking for
+            for (int i = 0; i < s_valueFilterCount; i++)
+            {
+                if ((s_valueFilter[i].end < src || src < s_valueFilter[i].start) &&
+                    (s_valueFilter[i].end < dst_from || dst_from < s_valueFilter[i].start)) &&
+                    (s_valueFilter[i].end < dst_to || dst_to < s_valueFilter[i].start))
+                {
+                    // empty intersection with both the source and the destination
+                    continue;
+                }
+                return true;
+            }
+        }
+        break;
     }
     return fLevelFilter || s_interestingStringFilter[isd];
 }
@@ -521,7 +542,7 @@ static ThreadStressLogDesc s_threadStressLogDesc[MAX_THREADSTRESSLOGS];
 static int s_threadStressLogCount;
 static LONG s_wrappedWriteThreadCount;
 
-static const LONG MAX_MESSAGE_COUNT = 1024 * 1024 * 1024;
+static const LONG MAX_MESSAGE_COUNT = 64 * 1024 * 1024;
 static StressThreadAndMsg* s_threadMsgBuf;
 static volatile LONG s_msgCount = 0;
 static volatile LONG s_totalMsgCount = 0;
@@ -956,6 +977,10 @@ bool ParseOptions(int argc, wchar_t* argv[])
                 return false;
             }
         }
+        else
+        {
+            return false;
+        }
         i++;
     }
     return true;