对老赵写的简单性能计数器的修改续- 关于 GetThreadTimes

关于 GetThreadTimes

    昨天我在一篇博文中 《对老赵写的简单性能计数器的修改》  提到用 GetThreadTimes 这个Win32 API 来获取线程实际运行时间。今天我又深入研究了一下，发现这个API 返回的时间并不准确。

    首先我们先看一下 GetThreadTimes 的实现原理：

    在 kernel32.dll 内部 GetThreadTimes 首先调用 NtQueryInformationThread 获取线程TCB信息，然后从TCB 中获取线程的内核态计数和用户态计数。然而这个计数值并不是实时增加的，操作系统只是在时间中断（10/15ms一次，单处理器通常是10ms，多处理器15ms）发生时增加当前线程的计数。这里就出现一个问题，如果时间中断发生时，被统计线程恰好不在活动状态，即不是当前线程，那么这个线程就不会增加计数。所以只有线程长时间连续占用CPU，或者每次都正好连续占用一个完整的时间片（10/15ms一次），才能确保这个线程的统计结果是准确的。但实际情况是，线程不可能连续占用CPU（否则其他程序就别玩了，如果你一定要这样我也没办法），也不可能每次都恰巧占用完整的时间片（线程工作过程中往往会需要Sleep，或者阻塞等待资源或者被高优先级线程打断）。所以显而易见，这个计数是不精确的。

    下面给出我写的一个示例代码。

    这个代码在我机器上运行，如果将Thread.Sleep(1); 这行注释掉，显示耗时是140毫秒，但如果不注释这行，显示耗时是0毫秒。

    原因就是我们将140毫秒的时间强行分成了1000个很小的时间，每次线程只消耗大约0.14 毫秒的CPU时间，而在这1秒左右的时间（约 1000*1ms+140ms)

 时间里，共发生1140 / 15 = 74 次时间中断（我的机器是双核的），每次中断时，主线程正好在运行的概率不高，如果这74次中断中没有一次击中当前线程，

 则当前线程的计数增长始终为0。

   

       
        [DllImport("kernel32.dll", SetLastError = true)]
        static extern bool GetThreadTimes(IntPtr hThread, out long lpCreationTime,
           out long lpExitTime, out long lpKernelTime, out long lpUserTime);

        [DllImport("kernel32.dll")]
        static extern IntPtr GetCurrentThread();

        private static long GetCurrentThreadTimes()
        {
            long l;
            long kernelTime, userTimer;
            GetThreadTimes(GetCurrentThread(), out l, out l, out kernelTime, out 
               userTimer);
            return kernelTime + userTimer;
        }

        static void TestGetThreadTimes()
        {
            long lst = GetCurrentThreadTimes();
            string a = "";

            for (int i = 0; i < 10000; i++)
            {
                a += "a";

                if (i % 10 == 0)
                {
                    Thread.Sleep(1); //休眠1毫秒
                }
            }

            Console.Write((GetCurrentThreadTimes() - lst) / (10 * 1000));
            Console.WriteLine("ms");
        }

 

参考文章：

http://blog.kalmbachnet.de/?postid=28

这是一个德国人写的博客，我看了好几遍，对他写的德式英语还是不太明白，（本人英文水平不高也是事实），所以我理解的不对的地方还望大家指正。不过结论肯定是正确的，就是通过GetThreadTimes 得到的线程占用时间是不准确的，在某种条件下甚至是很不准确的。

另外我发现调用GetThreadTimes获取其它线程的计数基本得不到，我还没有搞明白是什么原因。

 

进一步分析：

这篇文章发出后，老蔡回帖认为我的理解有偏差，他认为只有线程经历了完整的时间片才会被计数，我为此做了进一步分析，

看如下代码

 

 

 

 

        static void TestGetThreadTimes()
        {
            QueryPerfCounter q = new QueryPerfCounter();

            long lst = GetCurrentThreadTimes();
            string a = "";
            const int BreakTimes = 10000;
            const int Iteration = 100000;

            double[] timeList = new double[BreakTimes];

            int times = 0;

            for (int i = 0; i < Iteration; i++)
            {
                a += "a";
                if (i % (Iteration / BreakTimes) == 0)
                {
                    if (i > 0)
                    {
                        q.Stop();
                        timeList[times++] = q.Duration(1);
                    }
                    Thread.Sleep(1);
                    q.Start();
                }
            }

            q.Stop();
            timeList[times++] = q.Duration(1);

            Console.Write("GetThreadTimes:");
            Console.Write((GetCurrentThreadTimes() - lst) / (10 * 1000));
            Console.WriteLine("ms");

            double max = 0;
            double sum = 0;
            foreach (double time in timeList)
            {
                if (max < time)
                {
                    max = time;
                }

                sum += time;
            }


            Console.WriteLine(string.Format("Avg time {0} ms", (sum / BreakTimes) / 1000000));
            Console.WriteLine(string.Format("max time {0} ms", (max) / 1000000));
            Console.WriteLine(string.Format("Total time {0} ms", sum / 1000000));

        }

 

 

QueryPerfCounter 类见 dotnet下时间精度测量  感谢 xiaotie

运行结果：

GetThreadTimes:11218ms
Avg time 1.58978048886101 ms
max time 5.64513087557217 ms
Total time 15897.8048886101 ms

也就是说 通过GetThreadTimes 我们测量到了 11218ms CPU用时。实际用时大概是 15897 ms

但Sleep(1) 之间间隔的时间平均是 1.59 ms 最大间隔时间是 5.6 ms 。可见没有一次的间隔时间达到了一个完整时间片（15ms)

如果只有跑满一个完整时间片才会计数，那么通过 GetThreadTimes 得到的结果应该是0ms。但实际并非如此。

所以跑满一个完整时间片才计数的说法在这里很难解释这种现象。这个现象我在写这篇文章前已经发现了。

我们再用击中概率的方法来验证。

每次时钟中断击中的概率大概是

15897 / (10000 + 15897) = 0.61

那么按照这个概率计算，GetThreadTimes 可以统计到的时间是15897 * 0.61 = 9697.17 ms

这个数值和实际数值基本上是吻合的。所以综上所述，我倾向于认同那个德国专家的说法。

 

备注

下面是 Jochen Kalmbach  写的C++代码，我没有调试过，不过他的代码是用其他线程获取计数的，不知道是不是对.Net的托管线程这样不行,反正我在.Net下试是不行的。

 

 

  #include <windows.h>
  #include <stdio.h>

  DWORD loopCounter = 0;
  DWORD loopCounterMax = 1000;
  DWORD internalCounter = 0xFFF00000;

  DWORD __stdcall CalcThread(LPVOID)
  {
    while(loopCounter <= loopCounterMax)
    {
      DWORD cnt = internalCounter;
      while(cnt != 0) cnt++;
      Sleep(1);
      loopCounter++;
    } return 0;
  }

  DWORD WINAPI IdleThread(LPVOID)
  {
    while(loopCounter <= loopCounterMax)
    {
      Sleep(0);  // just do something
    } return 0;
  }

  int _tmain(int argc, _TCHAR* argv[])
  {
    // be sure we only use 1 processor!
    SetProcessAffinityMask(GetCurrentProcess(), 1);

    LARGE_INTEGER liStart, liEnd, liFreq;

    // test, how much time the inc is using
    QueryPerformanceCounter(&liStart);
    DWORD cnt = internalCounter;
    while(cnt != 0) cnt++;
    QueryPerformanceCounter(&liEnd);
    QueryPerformanceFrequency(&liFreq);
    double ms = ((double) (liEnd.QuadPart-liStart.QuadPart) * 1000) /
  (double)liFreq.QuadPart;
    printf("Inc duration: %.3f msnn", ms);
    // test-end

    DWORD id;
    HANDLE hThread[ 2 ];
    QueryPerformanceCounter(&liStart);

    hThread[ 0 ] = CreateThread(NULL, 0, CalcThread, 0, 0, &id);
    hThread[ 1 ] = CreateThread(NULL, 0, IdleThread, 0, 0, &id);

    WaitForMultipleObjects(2, hThread, TRUE, INFINITE);

    QueryPerformanceCounter(&liEnd);
    QueryPerformanceFrequency(&liFreq);

    ms = ((double) (liEnd.QuadPart-liStart.QuadPart) * 1000) / (double)
  liFreq.QuadPart;
    printf("Duration: %.3f msnn", ms);

    FILETIME ftCreate, ftExit, ftKernel, ftUser;
    for(DWORD i=0; i<2; i++)
    {
      GetThreadTimes(hThread[i], &ftCreate, &ftExit, &ftKernel, &ftUser);

      printf("Reported time for thread %dn", i+1);

      SYSTEMTIME st;
      FileTimeToSystemTime(&ftKernel, &st);
      printf("Kernel: %2.2d:%2.2d.%3.3dn", st.wMinute, st.wSecond,
  st.wMilliseconds);

      FileTimeToSystemTime(&ftUser, &st);
      printf("User: %2.2d:%2.2d.%3.3dnn", st.wMinute, st.wSecond,
  st.wMilliseconds);
    }
  return 0;
  }