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
