[Profiler] Fix missing CPU samples (#4046)

Author: chrisnas

profiler/src/ProfilerEngine/Datadog.Profiler.Native.Linux/OsSpecificApi.cpp

@@ -155,15 +155,17 @@ uint64_t GetThreadCpuTime(ManagedThreadInfo* pThreadInfo)
     return cpuTime;
 }
 
-bool IsRunning(ManagedThreadInfo* pThreadInfo, uint64_t& cpuTime)
+bool IsRunning(ManagedThreadInfo* pThreadInfo, uint64_t& cpuTime, bool& failed)
 {
     bool isRunning = false;
     if (!GetCpuInfo(pThreadInfo->GetOsThreadId(), isRunning, cpuTime))
     {
         cpuTime = 0;
+        failed = true;
         return false;
     }
 
+    failed = false;
     return isRunning;
 }
 

profiler/src/ProfilerEngine/Datadog.Profiler.Native.Windows/OsSpecificApi.cpp

@@ -35,13 +35,38 @@ uint64_t GetThreadCpuTime(ManagedThreadInfo* pThreadInfo)
     FILETIME creationTime, exitTime = {}; // not used here
     FILETIME kernelTime = {};
     FILETIME userTime = {};
+    static bool isFirstError = true;
 
     if (::GetThreadTimes(pThreadInfo->GetOsThreadHandle(), &creationTime, &exitTime, &kernelTime, &userTime))
     {
         uint64_t milliseconds = GetTotalMilliseconds(userTime) + GetTotalMilliseconds(kernelTime);
         return milliseconds;
     }
-
+    else
+    {
+        DWORD errorCode = GetLastError();
+        if (isFirstError && (errorCode != ERROR_INVALID_HANDLE)) // expected invalid handle case
+        {
+            isFirstError = false;
+            LPVOID msgBuffer;
+
+            if (errorCode == 0)
+            {
+                Log::Error("GetThreadCpuTime() error calling GetThreadTimes (last error = 0)");
+            }
+            else
+            {
+                FormatMessage(FORMAT_MESSAGE_ALLOCATE_BUFFER | FORMAT_MESSAGE_FROM_SYSTEM | FORMAT_MESSAGE_IGNORE_INSERTS,
+                              NULL, errorCode, MAKELANGID(LANG_NEUTRAL, SUBLANG_DEFAULT), (LPTSTR)&msgBuffer, 0, NULL);
+
+                if (msgBuffer != NULL)
+                {
+                    Log::Error("GetThreadCpuTime() error calling GetThreadTimes (last error = 0x", std::hex, errorCode, std::dec, "): ", (LPCTSTR)msgBuffer);
+                    LocalFree(msgBuffer);
+                }
+            }
+        }
+    }
     return 0;
 }
 
@@ -131,8 +156,11 @@ bool IsRunning(ULONG threadState)
     // If some callstacks show non cpu-bound frames at the top, return true only for Running state
 }
 
-bool IsRunning(ManagedThreadInfo* pThreadInfo, uint64_t& cpuTime)
+bool IsRunning(ManagedThreadInfo* pThreadInfo, uint64_t& cpuTime, bool& failed)
 {
+    failed = true;
+    cpuTime = 0;
+
     if (NtQueryInformationThread == nullptr)
     {
         if (!InitializeNtQueryInformationThreadCallback())
@@ -144,14 +172,41 @@ bool IsRunning(ManagedThreadInfo* pThreadInfo, uint64_t& cpuTime)
     SYSTEM_THREAD_INFORMATION sti = {0};
     auto size = sizeof(SYSTEM_THREAD_INFORMATION);
     ULONG buflen = 0;
+    static bool isFirstError = true;
     NTSTATUS lResult = NtQueryInformationThread(pThreadInfo->GetOsThreadHandle(), SYSTEMTHREADINFORMATION, &sti, static_cast<ULONG>(size), &buflen);
+    // deal with an invalid thread handle case (thread might have died)
     if (lResult != 0)
     {
+#if BIT64 // Windows 64-bit
+        if (isFirstError && (lResult != STATUS_INVALID_HANDLE))
+        {
+            isFirstError = false;
+            LPVOID msgBuffer;
+            DWORD errorCode = GetLastError();
+
+            if (errorCode == 0)
+            {
+                Log::Error("IsRunning() error 0x", std::hex, lResult, " calling NtQueryInformationThread");
+            }
+            else
+            {
+                FormatMessage(FORMAT_MESSAGE_ALLOCATE_BUFFER | FORMAT_MESSAGE_FROM_SYSTEM | FORMAT_MESSAGE_IGNORE_INSERTS,
+                              NULL, errorCode, MAKELANGID(LANG_NEUTRAL, SUBLANG_DEFAULT), (LPTSTR)&msgBuffer, 0, NULL);
+
+                if (msgBuffer != NULL)
+                {
+                    Log::Error("IsRunning() error 0x", std::hex, lResult, " calling NtQueryInformationThread (last error =  0x", std::hex, errorCode, std::dec, "): ", (LPTSTR)msgBuffer);
+                    LocalFree(msgBuffer);
+                }
+            }
+        }
+#endif
         // This always happens in 32 bit so uses another API to at least get the CPU consumption
         cpuTime = GetThreadCpuTime(pThreadInfo);
         return false;
     }
 
+    failed = false;
     cpuTime = GetTotalMilliseconds(sti.UserTime) + GetTotalMilliseconds(sti.KernelTime);
 
     return IsRunning(sti.ThreadState);

profiler/src/ProfilerEngine/Datadog.Profiler.Native/OsSpecificApi.h

@@ -19,6 +19,6 @@ namespace OsSpecificApi
 {
    std::unique_ptr<StackFramesCollectorBase> CreateNewStackFramesCollectorInstance(ICorProfilerInfo4* pCorProfilerInfo, IConfiguration const* pConfiguration);
    uint64_t GetThreadCpuTime(ManagedThreadInfo* pThreadInfo);
-   bool IsRunning(ManagedThreadInfo* pThreadInfo, uint64_t& cpuTime);
+   bool IsRunning(ManagedThreadInfo* pThreadInfo, uint64_t& cpuTime, bool& failed);
    int32_t GetProcessorCount();
 } // namespace OsSpecificApi

profiler/src/ProfilerEngine/Datadog.Profiler.Native/StackSamplerLoop.cpp

@@ -244,15 +244,21 @@ void StackSamplerLoop::CpuProfilingIteration()
         _targetThread = _pManagedThreadList->LoopNext(_iteratorCpuTime);
         if (_targetThread != nullptr)
         {
+            // detect Windows API call failure
+            bool failure = false;
+
             // sample only if the thread is currently running on a core
             uint64_t currentConsumption = 0;
             uint64_t lastConsumption = _targetThread->GetCpuConsumptionMilliseconds();
-            bool isRunning = OsSpecificApi::IsRunning(_targetThread.get(), currentConsumption);
-            // Note: it is not possible to get this information on Windows 32-bit
-            //       so true is returned if this thread consumed some CPU since
-            //       the last iteration
+            bool isRunning = OsSpecificApi::IsRunning(_targetThread.get(), currentConsumption, failure);
+            // Note: it is not possible to get this information on Windows 32-bit or in some cases in 64-bit
+            //       so isRunning should be true if this thread consumed some CPU since the last iteration
 #if _WINDOWS
-    #if BIT64  // nothing to do for Windows 64-bit
+    #if BIT64  // Windows 64-bit
+            if (failure)
+            {
+                isRunning = (lastConsumption < currentConsumption);
+            }
     #else  // Windows 32-bit
             isRunning = (lastConsumption < currentConsumption);
     #endif