[MERGE #5426 @mike-kaufman] Adding CPU times to timing counters where UI thread is blocked by GC

Merge pull request #5426 from mike-kaufman:build/mkaufman/get-cpu-time-for-wait-periods

We've been capturing wall-clock times for how long the user thread is blocked by GC.  This is useful but the data can be skewed by suspended tabs in the browser.  Adding capture of CPU time to give us better insight here.

Author: Mike Kaufman

lib/Common/Memory/Recycler.cpp

@@ -5712,6 +5712,22 @@ Recycler::FinishConcurrentCollectWrapped(CollectionFlags flags)
     return collected;
 }
 
+
+ /**
+  *  Compute ft1 - ft2, return result as a uint64
+  */
+uint64 DiffFileTimes(LPFILETIME ft1, LPFILETIME ft2)
+{
+    ULARGE_INTEGER ul1;
+    ULARGE_INTEGER ul2;
+    ul1.HighPart = ft1->dwHighDateTime;
+    ul1.LowPart = ft1->dwLowDateTime;
+    ul2.HighPart = ft2->dwHighDateTime;
+    ul2.LowPart = ft2->dwLowDateTime;
+    ULONGLONG result = ul1.QuadPart - ul2.QuadPart;
+    return result;
+}
+
 BOOL
 Recycler::WaitForConcurrentThread(DWORD waitTime, RecyclerWaitReason caller)
 {
@@ -5726,8 +5742,22 @@ Recycler::WaitForConcurrentThread(DWORD waitTime, RecyclerWaitReason caller)
     }
 
 #ifdef ENABLE_BASIC_TELEMETRY
-    bool isBlockingMainThread = this->telemetryStats.IsOnScriptThread();
-    Js::Tick start = Js::Tick::Now();
+    bool isBlockingMainThread = false;
+    Js::Tick start;
+    FILETIME kernelTime1;
+    FILETIME userTime1;
+    HANDLE hProcess = GetCurrentProcess();
+    if (this->telemetryStats.ShouldStartTelemetryCapture())
+    {
+        isBlockingMainThread = this->telemetryStats.IsOnScriptThread();
+        if (isBlockingMainThread)
+        {
+            start = Js::Tick::Now();
+            FILETIME creationTime;
+            FILETIME exitTime;
+            GetProcessTimes(hProcess, &creationTime, &exitTime, &kernelTime1, &userTime1);
+        }
+    }
 #endif
 
     DWORD ret = WaitForSingleObject(concurrentWorkDoneEvent, waitTime);
@@ -5737,7 +5767,24 @@ Recycler::WaitForConcurrentThread(DWORD waitTime, RecyclerWaitReason caller)
     {
         Js::Tick end = Js::Tick::Now();
         Js::TickDelta elapsed = end - start;
+
+        FILETIME creationTime;
+        FILETIME exitTime;
+        FILETIME kernelTime2;
+        FILETIME userTime2;
+
+        GetProcessTimes(hProcess, &creationTime, &exitTime, &kernelTime2, &userTime2);
+        uint64 kernelTime = DiffFileTimes(&kernelTime2 , &kernelTime1);
+        uint64 userTime = DiffFileTimes(&userTime2, &userTime1);
+
+        // userTime & kernelTime reported from GetProcessTimes is the number of 100-nanosecond ticks
+        // for consistency convert to microseconds.
+        kernelTime = kernelTime / 10;
+        userTime = userTime / 10;
+
         this->telemetryStats.IncrementUserThreadBlockedCount(elapsed.ToMicroseconds(), caller);
+        this->telemetryStats.IncrementUserThreadBlockedCpuTimeUser(userTime, caller);
+        this->telemetryStats.IncrementUserThreadBlockedCpuTimeKernel(kernelTime, caller);
     }
 #endif
 

lib/Common/Memory/RecyclerTelemetryInfo.cpp

@@ -252,6 +252,41 @@ namespace Memory
         }
     }
 
+
+    void RecyclerTelemetryInfo::IncrementUserThreadBlockedCpuTimeUser(uint64 userMicroseconds, RecyclerWaitReason caller)
+    {
+        RecyclerTelemetryGCPassStats* lastPassStats = this->GetLastPassStats();
+#ifdef DBG
+        if (this->inPassActiveState)
+        {
+            AssertMsg(lastPassStats != nullptr && lastPassStats->isGCPassActive == true, "unexpected Value in  RecyclerTelemetryInfo::IncrementUserThreadBlockedCpuTimeUser");
+        }
+#endif
+
+        if (this->inPassActiveState && lastPassStats != nullptr)
+        {
+            AssertOnValidThread(this, RecyclerTelemetryInfo::IncrementUserThreadBlockedCpuTimeUser);
+            lastPassStats->uiThreadBlockedCpuTimesUser[caller] += userMicroseconds;
+        }
+    }
+
+    void RecyclerTelemetryInfo::IncrementUserThreadBlockedCpuTimeKernel(uint64 kernelMicroseconds, RecyclerWaitReason caller)
+    {
+        RecyclerTelemetryGCPassStats* lastPassStats = this->GetLastPassStats();
+#ifdef DBG
+        if (this->inPassActiveState)
+        {
+            AssertMsg(lastPassStats != nullptr && lastPassStats->isGCPassActive == true, "unexpected Value in  RecyclerTelemetryInfo::IncrementUserThreadBlockedCpuTimeKernel");
+        }
+#endif
+
+        if (this->inPassActiveState && lastPassStats != nullptr)
+        {
+            AssertOnValidThread(this, RecyclerTelemetryInfo::IncrementUserThreadBlockedCpuTimeKernel);
+            lastPassStats->uiThreadBlockedCpuTimesKernel[caller] += kernelMicroseconds;
+        }
+    }
+
     bool RecyclerTelemetryInfo::IsOnScriptThread() const
     {
         bool isValid = false;

lib/Common/Memory/RecyclerTelemetryInfo.h

@@ -59,6 +59,8 @@ namespace Memory
         Js::TickDelta computeBucketStatsElapsedTime;
         FILETIME lastScriptExecutionEndTime;
         Js::TickDelta uiThreadBlockedTimes[static_cast<size_t>(RecyclerWaitReason::Other) + 1];
+        uint64 uiThreadBlockedCpuTimesUser[static_cast<size_t>(RecyclerWaitReason::Other) + 1];
+        uint64 uiThreadBlockedCpuTimesKernel[static_cast<size_t>(RecyclerWaitReason::Other) + 1];
         bool isInScript;
         bool isScriptActive;
         bool isGCPassActive;
@@ -99,7 +101,9 @@ namespace Memory
         void StartPass(CollectionState collectionState);
         void EndPass(CollectionState collectionState);
         void IncrementUserThreadBlockedCount(Js::TickDelta waitTime, RecyclerWaitReason source);
-        
+        void IncrementUserThreadBlockedCpuTimeUser(uint64 userMicroseconds, RecyclerWaitReason caller);
+        void IncrementUserThreadBlockedCpuTimeKernel(uint64 kernelMicroseconds, RecyclerWaitReason caller);
+
         inline const Js::Tick& GetRecyclerStartTime() const { return this->recyclerStartTime;  }
         RecyclerTelemetryGCPassStats* GetLastPassStats() const;
         inline const Js::Tick& GetLastTransmitTime() const { return this->lastTransmitTime; }
@@ -116,6 +120,8 @@ namespace Memory
         AllocatorDecommitStats* GetRecyclerWithBarrierPageAllocator_decommitStats() { return &this->recyclerWithBarrierPageAllocator_decommitStats; }
 #endif
 
+        bool ShouldStartTelemetryCapture() const;
+
     private:
         Recycler* recycler;
         DWORD mainThreadID;
@@ -135,7 +141,6 @@ namespace Memory
         AllocatorDecommitStats recyclerWithBarrierPageAllocator_decommitStats;
 #endif
 
-        bool ShouldStartTelemetryCapture() const;
         bool ShouldTransmit() const;
         void FreeGCPassStats();
         void Reset();