怎样简单地跟踪函数的执行效率

在项目完成后，发现性能不达标，往往是一件非常麻烦的事情。虽然有gprof,purify等工具可以帮助我们测试程序的性能，但是使用起来并不方便。

 本文介绍一种非常简单的方法，使程序员在单元测试阶段就可以发现程序中潜在的性能问题。 基本思路是，统计每个函数被调用的次数，以及每次调用所用掉的时间。

具体做法是，在函数体的第一行，生成一个统计对象，这个统计对象在构造函数中，记录下函数的开始时间，然后在函数退出时，在析构函数中记录函数的退出时间，再将函数的调用次数加一。

当然，这种方法统计的时间并不准确（应该除掉统计函数的开销，还有系统切换等因素的影响），但是可以作为一个非常重要的参考。

 程序很简单，就不做解释了。（注意，不支持多线程，可以稍微改一下，加个线程锁）

具体实现如下：

 

#include <stdio.h>
#include <stdlib.h>
#include <time.h>
#include <sys/time.h>
#include <unistd.h>


#include <map>
#include <string>
#include <vector>

using namespace std;


namespace FuncStat
...{
inline int DiffUSec(const struct timeval &t1, const struct timeval &t2)
...{
    return (t1.tv_sec * 1000 - t2.tv_sec * 1000) + (t1.tv_usec / 1000 - t2.tv_usec/1000); 
}

struct SFuncCallInfo
...{
    string FuncName;
    string FileName;
    int LineNum;
    struct timeval StartTime;
    struct timeval EndTime; 
};


typedef vector<SFuncCallInfo> FuncCallList;

class CFuncStat
...{
public:

    CFuncStat(const char *file, const char *func, int line);
    ~CFuncStat();
    static void PrintStatInfo();
private:
    void AddToCallList();
    SFuncCallInfo m_CallInfo;
    static map<string,FuncCallList> m_StatInfo;

};

map<string, FuncCallList> CFuncStat::m_StatInfo;


CFuncStat::CFuncStat(const char *file, const char *func, int line)
...{
    struct timezone tz;
    gettimeofday(&(m_CallInfo.StartTime), &tz);
    
    
    m_CallInfo.FileName = file;
    m_CallInfo.FuncName = func;
    m_CallInfo.LineNum = line;    
}

CFuncStat::~CFuncStat()
...{
    struct timezone tz;
    gettimeofday(&(m_CallInfo.EndTime), &tz);
    AddToCallList();    
}


void CFuncStat::PrintStatInfo()
...{
    
    map<string , FuncCallList>::iterator itr = m_StatInfo.begin();
    while(itr != m_StatInfo.end())
    ...{
        
        vector<SFuncCallInfo>::iterator vitr = itr->second.begin();    
        int total_time = 0;
        while(vitr != itr->second.end())
        ...{
            total_time += DiffUSec(vitr->EndTime, vitr->StartTime);
            ++vitr;
        }
        
        printf("%s total call times = %d, total use time = %d usec, ave time = %f usec ", 
            itr->first.c_str(), itr->second.size(), total_time, 
            itr->second.size() == 0 ? 0 : total_time * 1.0 / itr->second.size());
        
        ++itr;
    }

}


void CFuncStat::AddToCallList()
...{

    string tmp(m_CallInfo.FileName);
    char buf[32] = ...{0};
    sprintf(buf, "[%d]:", m_CallInfo.LineNum);
    tmp+=buf;
    
    tmp += m_CallInfo.FuncName;

    map<string , FuncCallList>::iterator itr = m_StatInfo.find(tmp);
    if(itr == m_StatInfo.end())
    ...{
        FuncCallList tlist;
        tlist.push_back(m_CallInfo);
        m_StatInfo[tmp] = tlist;
    }
    else
    ...{
        (*itr).second.push_back(m_CallInfo);
    }         
}

};




#define _FUNC_STAT_



#ifdef _FUNC_STAT_

#define FUNC_STAT   FuncStat::CFuncStat _FuncStatObj_(__FILE__, __FUNCTION__, __LINE__);
#define PRINT_STAT_INFO FuncStat::CFuncStat::PrintStatInfo();

#else

#define FUNC_STAT   
#define PRINT_STAT_INFO

#endif




void test()
...{

    FUNC_STAT
    usleep(1);
}

int main()
...{
    test();
    test();
    test();
    test();
    test();
    PRINT_STAT_INFO;
    return 0;

}