AIX下C/C++函数性能统计实现方法--改进版

上一篇实现，是统计了每一次函数调用的层次关系和耗时。如果在函数调用比较多的情况下，更关心的是减少输出，只需要总计的耗时即可。另外如果是后台程序，输出到文件会更好。

因此，对程序做了改进。当设置TRACELOG环境变量，则输出到这个环境变量指定的文件中。如果设置了DETAILF，则会输出调用层次关系和每一次的耗时，否则只输出总计时间。

tr.cpp改进后的程序如下。

#include <iostream>
#include <fstream>
#include <vector>
#include <map>
#include <string>
#include <sys/time.h>

using std::vector;
using std::map;
using std::string;
using std::clog;
using std::endl;
using std::ofstream;
using std::ostream;

extern "C" void print_trace(const char * const procname);

struct Stat
{
    int lvl;
    string name;
    long stm;
    long etm;
    long oitv;
    Stat(int l, const string& s, long st) : lvl(l), name(s), stm(st), etm(0), oitv(0) {}
};

struct Sum
{
    int cnt;
    long itv;
    Sum() : cnt(0), itv(0) {}
    Sum operator+=(long i)
    {
        ++cnt;
        itv+=i;
        return *this;
    }
};

namespace
{
vector<Stat> tracev;
map<string, Sum> itvm;
int clvl = 0;
bool detailf = (getenv("DETAILF")!=NULL);
}

extern "C" void
__func_trace_enter(const char * const proc_name,
                   const char * const file_name,
                   const int line_no,
                   void ** const id)
{
// printf("{ %s (%s:%d) %p %s\n", proc_name, file_name, line_no, id[0], (char*)*id);
    struct timeval nowtm;
    gettimeofday(&nowtm, NULL);
    ++clvl;
    tracev.push_back(Stat(clvl, string(proc_name)+"() : "+file_name, nowtm.tv_sec * 1000000 + nowtm.tv_usec));
}

extern "C" void
__func_trace_exit(const char * const proc_name,
                  const char * const file_name,
                  const int line_no,
                  void ** const id)
{
// printf("} %s (%s:%d) %p %s\n", proc_name, file_name, line_no, id[0], (char*)*id);
    struct timeval nowtm;
    int itv;
    gettimeofday(&nowtm, NULL);
    auto iter = tracev.end() - 1;
    while (iter->etm != 0)
        --iter;
    iter->etm = nowtm.tv_sec * 1000000 + nowtm.tv_usec;
    itv = iter->etm - iter->stm - iter->oitv;
    itvm[proc_name]+=itv;
    for (auto s = tracev.begin(); s!=iter; ++s)
    {
        if (s->etm == 0)
            s->oitv += itv;
    }
    --clvl;
    if (!detailf)
        tracev.erase(iter, tracev.end());
    if (clvl == 0)
    {
        print_trace(proc_name);
        tracev.clear();
        itvm.clear();
    }
}

extern "C" void print_trace(const char * const procname)
{
    time_t t;
    char buf[30];
    ofstream logf(getenv("TRACELOG"), std::ios::app);
    ostream &log = logf ? logf : clog;
    if (detailf)
    {
        log<<"Detail of "<< procname <<"() :\n";
        for (auto s = tracev.begin(); s!=tracev.end(); ++s)
        {
            log << s->lvl << "\t";
            t=s->stm/1000000;
            strftime(buf, sizeof(buf), "%Y%m%d%H%M%S", localtime(&t));
            log << buf << "." << s->stm % 1000000 << "\t";
            t=s->etm/1000000;
            strftime(buf, sizeof(buf), "%Y%m%d%H%M%S", localtime(&t));
            log << buf << "." << s->etm % 1000000 << "\t";
            log << s->etm-s->stm << "\t" << s->oitv << "\t" << s->etm-s->stm-s->oitv << "\t";
            log << string(s->lvl-1, ' ') << s->name << "\n";
        }
    }
    log<<"Total of "<< procname <<"() :\n";
    for (auto s = itvm.begin(); s!=itvm.end(); ++s)
    {
        log << s->first << "()\t count "<< (s->second).cnt << "\ttime " << (s->second).itv << "\n";
    }
    log<<endl;
}

设置DETAILF后，运行后输出结果如下。

Detail of main() :
1       20170801152000.103879   20170801152000.104034   155     58      97      main() : tt.c
2       20170801152000.103954   20170801152000.103997   43      3       40       f1() : tt.c
3       20170801152000.103958   20170801152000.103961   3       0       3         f2() : tt.c
2       20170801152000.104017   20170801152000.104032   15      3       12       f1() : tt.c
3       20170801152000.104021   20170801152000.104024   3       0       3         f2() : tt.c
Total of main() :
f1()     count 2        time 0.000052 s
f2()     count 2        time 0.000006 s
main()   count 1        time 0.000097 s