對(duì)老趙寫(xiě)的簡(jiǎn)單性能計(jì)數(shù)器的修改續(xù)- 關(guān)于 GetThreadTimes
Posted on 2009-03-11 15:57 eaglet 閱讀(5199) 評(píng)論(15) 收藏 舉報(bào)關(guān)于 GetThreadTimes
昨天我在一篇博文中 《對(duì)老趙寫(xiě)的簡(jiǎn)單性能計(jì)數(shù)器的修改》 提到用 GetThreadTimes 這個(gè)Win32 API 來(lái)獲取線程實(shí)際運(yùn)行時(shí)間。今天我又深入研究了一下，發(fā)現(xiàn)這個(gè)API 返回的時(shí)間并不準(zhǔn)確。
首先我們先看一下 GetThreadTimes 的實(shí)現(xiàn)原理：
在 kernel32.dll 內(nèi)部 GetThreadTimes 首先調(diào)用 NtQueryInformationThread 獲取線程TCB信息，然后從TCB 中獲取線程的內(nèi)核態(tài)計(jì)數(shù)和用戶態(tài)計(jì)數(shù)。然而這個(gè)計(jì)數(shù)值并不是實(shí)時(shí)增加的，操作系統(tǒng)只是在時(shí)間中斷（10/15ms一次，單處理器通常是10ms，多處理器15ms）發(fā)生時(shí)增加當(dāng)前線程的計(jì)數(shù)。這里就出現(xiàn)一個(gè)問(wèn)題，如果時(shí)間中斷發(fā)生時(shí)，被統(tǒng)計(jì)線程恰好不在活動(dòng)狀態(tài)，即不是當(dāng)前線程，那么這個(gè)線程就不會(huì)增加計(jì)數(shù)。所以只有線程長(zhǎng)時(shí)間連續(xù)占用CPU，或者每次都正好連續(xù)占用一個(gè)完整的時(shí)間片（10/15ms一次），才能確保這個(gè)線程的統(tǒng)計(jì)結(jié)果是準(zhǔn)確的。但實(shí)際情況是，線程不可能連續(xù)占用CPU（否則其他程序就別玩了，如果你一定要這樣我也沒(méi)辦法），也不可能每次都恰巧占用完整的時(shí)間片（線程工作過(guò)程中往往會(huì)需要Sleep，或者阻塞等待資源或者被高優(yōu)先級(jí)線程打斷）。所以顯而易見(jiàn)，這個(gè)計(jì)數(shù)是不精確的。
下面給出我寫(xiě)的一個(gè)示例代碼。
這個(gè)代碼在我機(jī)器上運(yùn)行，如果將Thread.Sleep(1); 這行注釋掉，顯示耗時(shí)是140毫秒，但如果不注釋這行，顯示耗時(shí)是0毫秒。
原因就是我們將140毫秒的時(shí)間強(qiáng)行分成了1000個(gè)很小的時(shí)間，每次線程只消耗大約0.14 毫秒的CPU時(shí)間，而在這1秒左右的時(shí)間（約 1000*1ms+140ms)
時(shí)間里，共發(fā)生1140 / 15 = 74 次時(shí)間中斷（我的機(jī)器是雙核的），每次中斷時(shí)，主線程正好在運(yùn)行的概率不高，如果這74次中斷中沒(méi)有一次擊中當(dāng)前線程，
則當(dāng)前線程的計(jì)數(shù)增長(zhǎng)始終為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
這是一個(gè)德國(guó)人寫(xiě)的博客，我看了好幾遍，對(duì)他寫(xiě)的德式英語(yǔ)還是不太明白，（本人英文水平不高也是事實(shí)），所以我理解的不對(duì)的地方還望大家指正。不過(guò)結(jié)論肯定是正確的，就是通過(guò)GetThreadTimes 得到的線程占用時(shí)間是不準(zhǔn)確的，在某種條件下甚至是很不準(zhǔn)確的。
另外我發(fā)現(xiàn)調(diào)用GetThreadTimes獲取其它線程的計(jì)數(shù)基本得不到，我還沒(méi)有搞明白是什么原因。
進(jìn)一步分析：
這篇文章發(fā)出后，老蔡回帖認(rèn)為我的理解有偏差，他認(rèn)為只有線程經(jīng)歷了完整的時(shí)間片才會(huì)被計(jì)數(shù)，我為此做了進(jìn)一步分析，
看如下代碼
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 類(lèi)見(jiàn) dotnet下時(shí)間精度測(cè)量 感謝 xiaotie
運(yùn)行結(jié)果：
GetThreadTimes:11218ms
Avg time 1.58978048886101 ms
max time 5.64513087557217 ms
Total time 15897.8048886101 ms
也就是說(shuō) 通過(guò)GetThreadTimes 我們測(cè)量到了 11218ms CPU用時(shí)。實(shí)際用時(shí)大概是 15897 ms
但Sleep(1) 之間間隔的時(shí)間平均是 1.59 ms 最大間隔時(shí)間是 5.6 ms 。可見(jiàn)沒(méi)有一次的間隔時(shí)間達(dá)到了一個(gè)完整時(shí)間片（15ms)
如果只有跑滿一個(gè)完整時(shí)間片才會(huì)計(jì)數(shù)，那么通過(guò) GetThreadTimes 得到的結(jié)果應(yīng)該是0ms。但實(shí)際并非如此。
所以跑滿一個(gè)完整時(shí)間片才計(jì)數(shù)的說(shuō)法在這里很難解釋這種現(xiàn)象。這個(gè)現(xiàn)象我在寫(xiě)這篇文章前已經(jīng)發(fā)現(xiàn)了。
我們?cè)儆脫糁懈怕实姆椒▉?lái)驗(yàn)證。
每次時(shí)鐘中斷擊中的概率大概是
15897 / (10000 + 15897) = 0.61
那么按照這個(gè)概率計(jì)算，GetThreadTimes 可以統(tǒng)計(jì)到的時(shí)間是15897 * 0.61 = 9697.17 ms
這個(gè)數(shù)值和實(shí)際數(shù)值基本上是吻合的。所以綜上所述，我傾向于認(rèn)同那個(gè)德國(guó)專(zhuān)家的說(shuō)法。
備注
下面是 Jochen Kalmbach 寫(xiě)的C++代碼，我沒(méi)有調(diào)試過(guò)，不過(guò)他的代碼是用其他線程獲取計(jì)數(shù)的，不知道是不是對(duì).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; }
浙公網(wǎng)安備 33010602011771號(hào)