Implement GetTotalPauseDuration and GC counters (VSadov#50)

* Implement GC counters

* Introduce a separate set of counters

* GCMemoryInfo.PauseTimePercentage

---------

Co-authored-by: vsadov <[email protected]>

Author: hez2010

src/coreclr/gc/satori/SatoriGC.cpp

@@ -299,8 +299,7 @@ bool SatoriGC::RegisterForFinalization(int gen, Object* obj)
 
 int SatoriGC::GetLastGCPercentTimeInGC()
 {
-    // NYI
-    return 0;
+    return m_heap->Recycler()->GetPercentTimeInGcSinceLastGc();
 }
 
 size_t SatoriGC::GetLastGCGenerationSize(int gen)
@@ -444,6 +443,9 @@ size_t SatoriGC::GetLastGCStartTime(int generation)
     return m_heap->Recycler()->GetGcStartMillis(generation);
 }
 
+// This is used internally in some strange AddMemoryPressure heuristics.
+// I am not completely sure what we need to return here.
+// We will return the last pause time in msec. Although it may often be 0 in Satori.
 size_t SatoriGC::GetLastGCDuration(int generation)
 {
     return m_heap->Recycler()->GetGcDurationMillis(generation);
@@ -678,7 +680,8 @@ void SatoriGC::GetMemoryInfo(uint64_t* highMemLoadThresholdBytes, uint64_t* tota
     *pinnedObjectCount = 0;
     *index = lastGcInfo->m_index;
     *generation = lastGcInfo->m_condemnedGeneration;
-    *pauseTimePct = 0;
+    // this is %% spent in STW from the moment of GC initialization, in wall-clock terms.
+    *pauseTimePct = lastGcInfo->m_pausePercentage;
     *isCompaction = lastGcInfo->m_compaction;
     *isConcurrent = lastGcInfo->m_concurrent;
     *genInfoRaw = 0;
@@ -720,8 +723,9 @@ unsigned int SatoriGC::GetGenerationWithRange(Object* object, uint8_t** ppStart,
 
 int64_t SatoriGC::GetTotalPauseDuration()
 {
-    // NYI
-    return 0;
+    return (m_heap->Recycler()->GetGcAccumulatingDurationMillis(0)
+        + m_heap->Recycler()->GetGcAccumulatingDurationMillis(1)
+        + m_heap->Recycler()->GetGcAccumulatingDurationMillis(2)) * 10;
 }
 
 void SatoriGC::EnumerateConfigurationValues(void* context, ConfigurationValueFunc configurationValueFunc)

src/coreclr/gc/satori/SatoriRecycler.cpp

@@ -152,14 +152,15 @@ void SatoriRecycler::Initialize(SatoriHeap* heap)
 
     m_isLowLatencyMode = SatoriUtil::IsLowLatencyMode();
 
-    for (int i = 0; i < 2; i++)
+    for (int i = 0; i < 3; i++)
     {
-        m_gcStartMillis[i] = m_gcDurationMillis[i] = 0;
+        m_gcStartMillis[i] = m_gcDurationUsecs[i] = m_gcAccmulatingDurationUsecs[i] = 0;
     }
 
     m_lastEphemeralGcInfo = { 0 };
     m_lastTenuredGcInfo   = { 0 };
     m_CurrentGcInfo = nullptr;
+    m_startMillis = GetNowMillis();
 }
 
 void SatoriRecycler::ShutDown()
@@ -896,6 +897,8 @@ void SatoriRecycler::BlockingMarkForConcurrent()
 
         size_t blockingDuration = (GCToOSInterface::QueryPerformanceCounter() - blockingStart);
         m_CurrentGcInfo->m_pauseDurations[1] = blockingDuration / m_perfCounterTicksPerMicro;
+        m_gcAccmulatingDurationUsecs[m_condemnedGeneration] += blockingDuration / m_perfCounterTicksPerMicro;
+        UpdateGcCounters(blockingStart);
 
         GCToEEInterface::RestartEE(false);
     }
@@ -1146,8 +1149,14 @@ void SatoriRecycler::BlockingCollect1()
 
     size_t blockingDuration = (GCToOSInterface::QueryPerformanceCounter() - blockingStart);
     m_CurrentGcInfo->m_pauseDurations[0] = blockingDuration / m_perfCounterTicksPerMicro;
-    m_gcDurationMillis[1] = blockingDuration / m_perfCounterTicksPerMicro;
+    m_gcDurationUsecs[1] = blockingDuration / m_perfCounterTicksPerMicro;
+    m_gcAccmulatingDurationUsecs[1] += blockingDuration / m_perfCounterTicksPerMicro;
+
+    size_t fromStartMillis = GetNowMillis() - m_startMillis;
+    m_CurrentGcInfo->m_pausePercentage = (uint32_t)(m_gcAccmulatingDurationUsecs[1] / (int64_t)fromStartMillis / 10);
+
     m_CurrentGcInfo = nullptr;
+    UpdateGcCounters(blockingStart);
 
     // restart VM
     GCToEEInterface::RestartEE(true);
@@ -1165,8 +1174,14 @@ void SatoriRecycler::BlockingCollect2()
 
     size_t blockingDuration = (GCToOSInterface::QueryPerformanceCounter() - blockingStart);
     m_CurrentGcInfo->m_pauseDurations[0] = blockingDuration / m_perfCounterTicksPerMicro;
-    m_gcDurationMillis[2] = blockingDuration / m_perfCounterTicksPerMicro;
+    m_gcDurationUsecs[2] = blockingDuration / m_perfCounterTicksPerMicro;
+    m_gcAccmulatingDurationUsecs[2] += blockingDuration / m_perfCounterTicksPerMicro;
+
+    size_t fromStartMillis = GetNowMillis() - m_startMillis;
+    m_CurrentGcInfo->m_pausePercentage = (uint32_t)( m_gcAccmulatingDurationUsecs[2] / (int64_t)fromStartMillis / 10);
+
     m_CurrentGcInfo = nullptr;
+    UpdateGcCounters(blockingStart);
 
     // restart VM
     GCToEEInterface::RestartEE(true);
@@ -4406,11 +4421,30 @@ size_t SatoriRecycler::GetGcStartMillis(int generation)
 
 size_t SatoriRecycler::GetGcDurationMillis(int generation)
 {
-    return m_gcDurationMillis[generation];
+    return m_gcDurationUsecs[generation] / 1000;
+}
+
+size_t SatoriRecycler::GetGcAccumulatingDurationMillis(int generation)
+{
+    return m_gcAccmulatingDurationUsecs[generation];
 }
 
 bool& SatoriRecycler::IsLowLatencyMode()
 {
     return m_isLowLatencyMode;
 }
 
+void SatoriRecycler::UpdateGcCounters(int64_t blockingStart)
+{
+    // Compute Time in GC
+    int64_t currentPerfCounterTimer = GCToOSInterface::QueryPerformanceCounter();
+
+    int64_t totalTimeInCurrentGc = currentPerfCounterTimer - blockingStart;
+    int64_t timeSinceLastGcEnded = currentPerfCounterTimer - m_totalTimeAtLastGcEnd;
+
+    // should always hold unless we switch to a nonmonotonic timer.
+    _ASSERTE(timeSinceLastGcEnded >= totalTimeInCurrentGc);
+
+    m_percentTimeInGcSinceLastGc = timeSinceLastGcEnded != 0 ? (int)(totalTimeInCurrentGc * 100 / timeSinceLastGcEnded) : 0;
+    m_totalTimeAtLastGcEnd = currentPerfCounterTimer;
+}

src/coreclr/gc/satori/SatoriRecycler.h

@@ -42,6 +42,7 @@ struct LastRecordedGcInfo
 {
     size_t m_index;
     size_t m_pauseDurations[2];
+    uint32_t m_pausePercentage;
     uint8_t m_condemnedGeneration;
     bool m_compaction;
     bool m_concurrent;
@@ -92,6 +93,7 @@ class SatoriRecycler
     size_t GetOccupancy(int i);
     size_t GetGcStartMillis(int generation);
     size_t GetGcDurationMillis(int generation);
+    size_t GetGcAccumulatingDurationMillis(int generation);
 
     int64_t GlobalGcIndex();
 
@@ -108,6 +110,11 @@ class SatoriRecycler
         return m_nextGcIsFullGc;
     }
 
+    inline int GetPercentTimeInGcSinceLastGc()
+    {
+        return m_percentTimeInGcSinceLastGc;
+    }
+
     LastRecordedGcInfo* GetLastGcInfo(gc_kind kind)
     {
         if (kind == gc_kind_ephemeral)
@@ -199,7 +206,11 @@ class SatoriRecycler
 
     int64_t m_gcCount[3];
     int64_t m_gcStartMillis[3];
-    int64_t m_gcDurationMillis[3];
+    int64_t m_gcDurationUsecs[3];
+    int64_t m_gcAccmulatingDurationUsecs[3];
+
+    int64_t m_totalTimeAtLastGcEnd;
+    int m_percentTimeInGcSinceLastGc;
 
     size_t m_gen1Budget;
     size_t m_totalLimit;
@@ -241,6 +252,8 @@ class SatoriRecycler
     LastRecordedGcInfo m_lastTenuredGcInfo;
     LastRecordedGcInfo* m_CurrentGcInfo;
 
+    size_t m_startMillis;
+
 private:
     size_t Gen1RegionCount();
     size_t Gen2RegionCount();
@@ -353,6 +366,8 @@ class SatoriRecycler
     void DrainDeferredSweepQueueWorkerFn();
     void SweepAndReturnRegion(SatoriRegion* curRegion);
 
+    void UpdateGcCounters(int64_t blockingStart);
+
     void ASSERT_NO_WORK();
 };