C语言学习网

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

发表于:2022-11-27 作者:安全数据网编辑
编辑最后更新 2022年11月27日,上一篇实现,是统计了每一次函数调用的层次关系和耗时。如果在函数调用比较多的情况下,更关心的是减少输出,只需要总计的耗时即可。另外如果是后台程序,输出到文件会更好。因此,对程序做了改进。当设置TRACE

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

因此,对程序做了改进。当设置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

    0