GCHeap::GetLastGCPercentTimeInGC incorrectly(?) returning 0 value

[gbalykov]

Description

I've been printing some logs in GCHeap::UpdatePreGCCounters and GCHeap::UpdatePostGCCounters and found that GCHeap::GetLastGCPercentTimeInGC can sometimes return 0 value when it doesn't seem to be correct.

When calls to GCHeap::UpdatePreGCCounters and GCHeap::UpdatePostGCCounters for one GC index happen between GCHeap::UpdatePreGCCounters and GCHeap::UpdatePostGCCounters for the other GC index, value of g_TotalTimeInGC becomes equal to the difference for previous gc index, which then makes g_TotalTimeInGC larger then _timeInGCBase and g_percentTimeInGCSinceLastGC is set to 0.

Is this the expected behavior or not?

Reproduction Steps

Patch to print log:

diff --git a/src/coreclr/gc/gcee.cpp b/src/coreclr/gc/gcee.cpp
index 3c07a074586..eab2ccf5209 100644
--- a/src/coreclr/gc/gcee.cpp
+++ b/src/coreclr/gc/gcee.cpp
@@ -37,6 +37,12 @@ void GCHeap::UpdatePreGCCounters()
     gc_mechanisms *pSettings = &gc_heap::settings;
 #endif //MULTIPLE_HEAPS
 
+    {
+        fprintf(stdout, "[GC_INFO] #%d: Reason(%d), Gen(%d), Comp(%d), Time start(%llu ns)\n",
+           (int)pSettings->gc_index, (int)pSettings->reason, (int)pSettings->condemned_generation, (int)pSettings->compaction,
+           (long long unsigned int)g_TotalTimeInGC);
+    }
+
     uint32_t count = (uint32_t)pSettings->gc_index;
     uint32_t depth = (uint32_t)pSettings->condemned_generation;
     uint32_t reason = (uint32_t)pSettings->reason;
@@ -182,6 +188,14 @@ void GCHeap::UpdatePostGCCounters()
     // Compute Time in GC
     uint64_t _currentPerfCounterTimer = GCToOSInterface::QueryPerformanceCounter();
 
+#ifdef FEATURE_EVENT_TRACE
+    {
+        fprintf(stdout, "[GC_INFO] #%d: Reason(%d), Gen(%d), Comp(%d), Time start(%llu ns), Time end(%llu ns)\n",
+           (int)pSettings->gc_index, (int)pSettings->reason, (int)pSettings->condemned_generation, (int)pSettings->compaction,
+           (long long unsigned int)g_TotalTimeInGC, (long long unsigned int)_currentPerfCounterTimer);
+    }
+#endif
+
     g_TotalTimeInGC = _currentPerfCounterTimer - g_TotalTimeInGC;
     uint64_t _timeInGCBase = (_currentPerfCounterTimer - g_TotalTimeSinceLastGCEnd);
 

Then run crossgen2:

./corerun ./crossgen2/crossgen2.dll -O -r:`pwd`/*.dll -o:/tmp/1.ni.dll System.Private.CoreLib.dll

Expected behavior

non-0 value for GCHeap::GetLastGCPercentTimeInGC?

Actual behavior

[GC_INFO] #6: Reason(0), Gen(1), Comp(1), Time start(4351468669403806 ns)
[GC_INFO] #6: Reason(0), Gen(1), Comp(0), Time start(4351468669403806 ns), Time end(4351468688324478 ns)
[GC_INFO] #7: Reason(4), Gen(2), Comp(1), Time start(4351468761984019 ns)
[GC_INFO] #8: Reason(0), Gen(1), Comp(1), Time start(4351468775666020 ns)
[GC_INFO] #8: Reason(0), Gen(1), Comp(1), Time start(4351468775666020 ns), Time end(4351468815018900 ns)
[GC_INFO] #7: Reason(4), Gen(2), Comp(0), Time start(39352880 ns), Time end(4351468825683517 ns)
[GC_INFO] #9: Reason(0), Gen(0), Comp(1), Time start(4351468960137950 ns)
[GC_INFO] #9: Reason(0), Gen(0), Comp(1), Time start(4351468960137950 ns), Time end(4351468968281329 ns)

As you can see, for GC index 7 diff between end and start (g_TotalTimeInGC) will be larger then (_timeInGCBase), which then will lead to 0 value of g_percentTimeInGCSinceLastGC.

Regression?

No response

Known Workarounds

No response

Configuration

Tested on linux x64

Runtimes:

• .net 6
• .net 7
• main

Other information

cc @alpencolt

[gbalykov]

cc @jkotas

[jkotas]

I agree with you that this logic does not look right. @dotnet/gc Thoughts?

[mangod9]

@cshung could you please take a look when you get a chance?

[Maoni0]

this was never meant to work for BGC. this counter is simply not a good counter to use which was why I suggested to actually add a reasonable counter.

[mangod9]

Closing since this is by design