PROFILE技术总结(一): 应用微秒级精度定时器的方法

作者：liswei   可惜此人没有开辟BLOG

摘要：Profile在英文中解释为分类,文档管理。在我们计算机世界中，我们可以通过各种方法来测试我们程序或整个系统的性能，这些方法包括通过测试运行时间、访问cpu的次数，占用多少资源等，我们把这类方法统称为Profile技术。以下我将从应用微秒级精度定时器测试、利用Monte Carlo Profiler 工具、Perfalyzer 方法测试这三方面来介绍Profile技术。本篇先介绍应用应用微秒级精度定时器测试程序的效率。

一、应用微秒级精度定时器测试原理

高精度运行计数器（high-resolution performance counter），利用它可以获得高精度定时间隔，其精度与CPU的时钟频率有关。采用这种方法的基本思想如下：

（1）、首先调用QueryPerformanceFrequency函数取得高精度运行计数器的频率f。单位是每秒多少次（n/s），此数一般很大

（2）、在需要定时的代码的两端分别调用QueryPerformanceCounter以取得高精度运行计数器的数值n1，n2。两次数值的差值通过f换算成时间间隔，t=(n2-n1)/f。

二、微秒级精度定时器测试具体实现

       为了更好的提高该测试函数的可用性，我根据原理把实现函数封装成一个类，使其可以更好的被使用，并且我们这个类可以通过建立链表一次性可以测试很多个函数。本类包括两个文件FunctionProfile.h和FunctionProfile.cpp

1、“被测试函数”结点结构体的实现

 我们为每个测试函数建立一个结点Node，这个Node用如下结构体来实现：

typedef struct

{

    LONG64 StartTime;      //记录函数开始运行的时间

    int functionIndex;            //函数的标识号

    TCHAR name[80];        //函数名称

    int nProfiler_functionCountCalls;          //函数被调用次数

    LONG64 Profiler_functionTimings;      //函数本身的运行时间

    LONG64 Profiler_functionPlusChildTimings;//函数和子函数的运行时间

    LONG64 TestFunctionTime;    //记录测试函数的时间

    void *parent;                  //记录父结点

}FunctionNode;

2、CFunctionProfile类的定义

 1class CFunctionProfile
 2
 3{
 4
 5    public:  
 6
 7         CFunctionProfile::CFunctionProfile(TCHAR * wcsProfilerName);  
 8
 9         ~CFunctionProfile();   
10
11           //设置函数名称  
12
13         void SetFunctionName(int nFunctionId, TCHAR * tFunctionName); 
14
15           //函数测试开始       
16
17         void FunctionProfileStart(int nFunctionID);    
18
19           //函数测试结束   
20
21         void FunctionProfileStop(int nFunctionID);
22
23           //写数据到文件中
24
25         void WriteProfilerDataToFile();
26
27        
28
29   private:
30
31        //private variable
32
33           //被测试函数个数
34
35        FunctionNode m_aFNode[MAX_FUNCTIONS_TO_PROFILE];
36
37           //函数结点指针
38
39        FunctionNode * m_Profiler_lastFunctionProfiler;     
40
41           //测试函数开始时间
42
43        LONG64 m_TestFunctionStartTime;
44
45           //测试函数结束时间
46
47        LONG64 m_TestFunctionEndTime;
48
49           //总的函数运行时间
50
51        LONG64 m_Profiler_totalTime;    
52
53           //输出文件句柄   
54
55        HANDLE m_hProfile;        
56
57  
58
59        //private function
60
61           //测试函数时间
62
63        void QueryTimer(LONG64* pi64Time);    
64
65           //打印数据  
66
67        void Profiler_print(TCHAR* szMsg);
68
69       
70
71};
72
73

 

3、现在对类中几个主要的函数介绍如下：

    (1)、QueryTimer函数的实现

    这个函数用来获得当前计数器的数值，我们先来介绍下LARGE_INTEGER这个数据结构，这个数据结构如下所示：

 1typedef union _LARGE_INTEGER
 2
 3 {
 4
 5   struct
 6
 7   {
 8
 9     DWORD LowPart ;// 4字节整型数
10
11     LONG  HighPart;// 4字节整型数
12
13   };
14
15   LONGLONG QuadPart ;// 8字节整型数           
16
17 }LARGE_INTEGER ;
18

如果系统支持64位可以直接使用QuadPart来读取该计数值，如果不支持使用      LowPart和HighPart来取得直。

 1void CFunctionProfile::QueryTimer(LONG64* pi64Time)
 2
 3{
 4
 5        LARGE_INTEGER PerformCounter;
 6
 7         Bool ret;
 8
 9           r es=QueryPerformanceCounter(&PerformCounter);
10
11           //判断查询是否成功
12
13           if(res && (pi64Time!=NULL))
14
15           {//取得当前计数值
16
17*pi64Time = (PerformCounter.HighPart<<32)+PerformCounter.LowPart ;
18
19           }
20
21           else if(!res)
22
23           {
24
25           *pi64Time = 0;
26
27           }
28
29} 
30

(2)SetFunctionName函数的实现

正如函数名所示的意思，这个函数是用来个被测试函数命名添加标识

 1void CFunctionProfile::SetFunctionName(int nFunctionId,TCHAR *tFunctionName)
 2
 3{ 
 4
 5       //获得测试函数开始时间
 6
 7QueryTimer(&m_TestFunctionStartTime);    
 8
 9_tcscpy(m_aFNode[nFunctionId].name,tFunctionName);
10
11//如果被测试函数是第一个则不要记录测试浪费时间
12
13if(m_aFNode[nFunctionId].parent  == NULL)   
14
15       {
16
17return ;
18
19       }
20
21       //获得测试函数结束时间
22
23QueryTimer(&m_TestFunctionEndTime);   
24
25//增加浪费时间到前一个父亲结点
26
27    m_aFNode[((FunctionNode*)(m_aFNode[nFunctionId].parent))->functionIndex].TestFunctionTime +=(m_TestFunctionEndTime-m_TestFunctionStartTime);
28
29}
30
31

这样不是被测试函数的时间也被记录下来，也就提高了准确性。

(3)、 FunctionProfileStart函数的实现
这个函数记录被测试函数的开始时间和处理测试函数的时间。

 1void CFunctionProfile::FunctionProfileStart(int nFunctionID)
 2
 3{  
 4
 5    QueryTimer(&m_TestFunctionStartTime);
 6
 7    //构建一个被测试函数链表
 8
 9    m_aFNode[nFunctionID].functionIndex = nFunctionID;
10
11    m_aFNode[nFunctionID].parent = m_Profiler_lastFunctionProfiler;
12
13m_Profiler_lastFunctionProfiler = &m_aFNode[nFunctionID];   
14
15//增加被测试函数条用次数
16
17    m_aFNode[nFunctionID].nProfiler_functionCountCalls++;
18
19    QueryTimer(&m_TestFunctionEndTime);    
20
21       //如果父结点存在，把测试函数的时间加到父结点上面
22
23    if(m_aFNode[nFunctionID].parent != NULL)
24
25    {
26
27         m_aFNode[((FunctionNode*)(m_aFNode[nFunctionID].parent))->functionIndex].TestFunctionTime +=(m_TestFunctionEndTime-m_TestFunctionStartTime);
28
29    }
30
31    //子结点开始记录时间
32
33    QueryTimer(&(m_aFNode[nFunctionID].StartTime));  
34
35}
36
37

这样就完成了被测试函数结点的开始时间的记录。

 

(4)、 FunctionProfileStop函数的实现

       这个函数记录被测试函数的运行时间并对父结点进行处理。

 1void CFunctionProfile::FunctionProfileStop(int nFunctionID)
 2
 3{    
 4
 5    LONG64 endTime;
 6
 7    LONG64 time;
 8
 9       //记录被测试函数的结束时间
10
11    QueryTimer(&endTime); 
12
13    //记录测试函数的开始时间
14
15       QueryTimer(&m_TestFunctionStartTime);
16
17       //计算被测试函数的具体运行时间
18
19time = (endTime-m_aFNode[nFunctionID].StartTime);
20
21//增加函数调用时间
22
23m_aFNode[nFunctionID].Profiler_functionTimings += time;
24
25//如果父结点存在，父结点的本身函数运行时间减去当前结束函数时间
26
27    if (m_aFNode[nFunctionID].parent != NULL) 
28
29    {
30
31        m_aFNode[((FunctionNode*)(m_aFNode[nFunctionID].parent))->functionIndex].Profiler_functionTimings -= time;    //front node only function time
32
33    } 
34
35    else 
36
37{
38
39      //否则记录总的时间
40
41        m_Profiler_totalTime+=time; 
42
43}
44
45//增加记录包括子函数运行时间
46
47    m_aFNode[nFunctionID].Profiler_functionPlusChildTimings += time;
48
49    m_Profiler_lastFunctionProfiler = ((FunctionNode*)(m_aFNode[nFunctionID].parent));
50
51       //如果函数是第一个被测试函数结点，就不用记录这段测试函数的运行时间
52
53if(m_aFNode[nFunctionID].parent  == NULL)     
54
55{       
56
57        return ;
58
59    }
60
61    QueryTimer(&m_TestFunctionEndTime);  
62
63    //把测试函数的时间加到前一个结点上面
64
65    m_aFNode[((FunctionNode*)(m_aFNode[nFunctionID].parent))->functionIndex].TestFunctionTime += (m_TestFunctionEndTime-m_TestFunctionStartTime);   
66
67}
68
69

4、在这个类中定义一个开关：

       在FunctionProfile.h文件中定义一个，形式如下：

       //如果用户定义PROFILE，则我们开启测试功能，否则不做处理，具体定义  可以参看FunctionProfile.h文件

              ifdef  PROFILE

                     ……………

              else

.                    ……………

              Endif

5、定义一些宏定义方便用户使用

       (1)、定义被测试函数的个数和被测试函数的标识符号：

              //被测试函数个数

              #define MAX_FUNCTIONS_TO_PROFILE 20

              //被测试函数标识号

              #define PROFILE_1     0

              #define PROFILE_2     1

              #define PROFILE_3     2

              …………..

       (2)、具体操作宏定义（下面是在PROFILE编译开关中定义的）

       //定义一个类指针

       static CFunctionProfile  * Cprofile =NULL;

       //实例化该类指针，并对该类初始化

       #define PROFILE_INIT(szFileName)( Cprofile = new CFunctionProfile(szFileName) )

       //虚构该类指针

       #define PROFILE_DEINIT()  {delete Cprofile; Cprofile = NULL;}

       //设置被测试函数的名称

       #definePROFILE_NAME(nFunctionID,szFunctionName)                                                                              Cprofile->SetFunctionName(nFunctionID,szFunctionName)

       //开始测试被测试函数

       #define PROFILE_START(nFunctionID)  Cprofile->FunctionProfileStart(nFunctionID)

       //结束测试

       #define PROFILE_STOP(nFunctionID)  Cprofile->FunctionProfileStop(nFunctionID)

       //把数据输出到文件中去

       #define PROFILE_DUMP()  Cprofile->WriteProfilerDataToFile()

6、做一个测试的sample Code：

       代码如下：

 1int WINAPI WinMain( HINSTANCE hInstance,
 2
 3                    HINSTANCE hPrevInstance,
 4
 5                    LPTSTR    lpCmdLine,
 6
 7                    int       nCmdShow)
 8
 9{
10
11    PROFILE_INIT(TEXT("ProfileTest926.txt"));
12
13  
14
15    PROFILE_NAME(PROFILE_1, TEXT("MAIN_FUNCTION PROFILE"));
16
17PROFILE_START(PROFILE_1);
18
19 
20
21testProfile1(); 
22
23 
24
25    PROFILE_STOP(PROFILE_1);
26
27    PROFILE_DUMP ();
28
29    PROFILE_DEINIT();
30
31    return 0;
32
33 
34
35}
36
37void testProfile1( )
38
39{
40
41    PROFILE_NAME( PROFILE_2, TEXT("testProfile1 PROFILE"));
42
43    PROFILE_START(PROFILE_2);
44
45    for(int i=0;i<8;i++)
46
47          testProfile2();
48
49    PROFILE_STOP(PROFILE_2);
50
51}
52
53 
54
55void testProfile2( )
56
57{
58
59    PROFILE_NAME(PROFILE_3, TEXT("testProfile2 PROFILE"));
60
61    PROFILE_START(PROFILE_3);
62
63       for(int i=0;i<1000;i++)
64
65              ;          
66
67       PROFILE_STOP(PROFILE_3);
68
69}
70
71

运行程序后输出如下结果到ProfileTest926.txt，如下：

Total Time      1.352 ms

Function   Function  Function  Function        Function
+ child     only     + child   only            only
  time      time     ratio     ratio     Count  time/count  Function Name

 1.317   0.098  0.97359   0.07258       1      0.098    MAIN_FUNCTION PROFILE,

 0.789   0.618  0.58326   0.45689       1      0.618    testProfile1 PROFILE,

 0.171   0.171  0.12637   0.12637       8      0.021    testProfile2 PROFILE,

       对以上数据解释如下：

●    第一列代表：本身函数和自己的子函数所用时间

●    第二列代表：本身函数的运行时间

●    第三列代表：第一列所代表的时间总用总时间的比例

●    第四列代表：第二列所表示的时间总用总时间的比例

●    第五列代表：函数被调用的次数

●    第六列代表：本测试函数运行一次的平均时间

●    第七列代表：被测试函数的函数名称

至此，利用微秒级精度定时器测试时间的程序就介绍到这，希望对大家有帮助。