Chinaunix首页 | 论坛 | 博客
  • 博客访问: 97789
  • 博文数量: 43
  • 博客积分: 1
  • 博客等级: 民兵
  • 技术积分: 632
  • 用 户 组: 普通用户
  • 注册时间: 2011-07-31 11:19
  • 认证徽章:
个人简介

从事银行核心系统设计开发的程序猿

文章存档

2018年(3)

2017年(11)

2016年(6)

2015年(23)

分类: AIX

2017-08-05 20:24:13

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

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


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

  1. #include <iostream>
  2. #include <fstream>
  3. #include <vector>
  4. #include <map>
  5. #include <string>
  6. #include <sys/time.h>

  7. using std::vector;
  8. using std::map;
  9. using std::string;
  10. using std::clog;
  11. using std::endl;
  12. using std::ofstream;
  13. using std::ostream;

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

  15. struct Stat
  16. {
  17.     int lvl;
  18.     string name;
  19.     long stm;
  20.     long etm;
  21.     long oitv;
  22.     Stat(int l, const string& s, long st) : lvl(l), name(s), stm(st), etm(0), oitv(0) {}
  23. };

  24. struct Sum
  25. {
  26.     int cnt;
  27.     long itv;
  28.     Sum() : cnt(0), itv(0) {}
  29.     Sum operator+=(long i)
  30.     {
  31.         ++cnt;
  32.         itv+=i;
  33.         return *this;
  34.     }
  35. };

  36. namespace
  37. {
  38. vector<Stat> tracev;
  39. map<string, Sum> itvm;
  40. int clvl = 0;
  41. bool detailf = (getenv("DETAILF")!=NULL);
  42. }

  43. extern "C" void
  44. __func_trace_enter(const char * const proc_name,
  45.                    const char * const file_name,
  46.                    const int line_no,
  47.                    void ** const id)
  48. {
  49. // printf("{ %s (%s:%d) %p %s\n", proc_name, file_name, line_no, id[0], (char*)*id);
  50.     struct timeval nowtm;
  51.     gettimeofday(&nowtm, NULL);
  52.     ++clvl;
  53.     tracev.push_back(Stat(clvl, string(proc_name)+"() : "+file_name, nowtm.tv_sec * 1000000 + nowtm.tv_usec));
  54. }

  55. extern "C" void
  56. __func_trace_exit(const char * const proc_name,
  57.                   const char * const file_name,
  58.                   const int line_no,
  59.                   void ** const id)
  60. {
  61. // printf("} %s (%s:%d) %p %s\n", proc_name, file_name, line_no, id[0], (char*)*id);
  62.     struct timeval nowtm;
  63.     int itv;
  64.     gettimeofday(&nowtm, NULL);
  65.     auto iter = tracev.end() - 1;
  66.     while (iter->etm != 0)
  67.         --iter;
  68.     iter->etm = nowtm.tv_sec * 1000000 + nowtm.tv_usec;
  69.     itv = iter->etm - iter->stm - iter->oitv;
  70.     itvm[proc_name]+=itv;
  71.     for (auto s = tracev.begin(); s!=iter; ++s)
  72.     {
  73.         if (s->etm == 0)
  74.             s->oitv += itv;
  75.     }
  76.     --clvl;
  77.     if (!detailf)
  78.         tracev.erase(iter, tracev.end());
  79.     if (clvl == 0)
  80.     {
  81.         print_trace(proc_name);
  82.         tracev.clear();
  83.         itvm.clear();
  84.     }
  85. }

  86. extern "C" void print_trace(const char * const procname)
  87. {
  88.     time_t t;
  89.     char buf[30];
  90.     ofstream logf(getenv("TRACELOG"), std::ios::app);
  91.     ostream &log = logf ? logf : clog;
  92.     if (detailf)
  93.     {
  94.         log<<"Detail of "<< procname <<"() :\n";
  95.         for (auto s = tracev.begin(); s!=tracev.end(); ++s)
  96.         {
  97.             log << s->lvl << "\t";
  98.             t=s->stm/1000000;
  99.             strftime(buf, sizeof(buf), "%Y%m%d%H%M%S", localtime(&t));
  100.             log << buf << "." << s->stm % 1000000 << "\t";
  101.             t=s->etm/1000000;
  102.             strftime(buf, sizeof(buf), "%Y%m%d%H%M%S", localtime(&t));
  103.             log << buf << "." << s->etm % 1000000 << "\t";
  104.             log << s->etm-s->stm << "\t" << s->oitv << "\t" << s->etm-s->stm-s->oitv << "\t";
  105.             log << string(s->lvl-1, ' ') << s->name << "\n";
  106.         }
  107.     }
  108.     log<<"Total of "<< procname <<"() :\n";
  109.     for (auto s = itvm.begin(); s!=itvm.end(); ++s)
  110.     {
  111.         log << s->first << "()\t count "<< (s->second).cnt << "\ttime " << (s->second).itv << "\n";
  112.     }
  113.     log<<endl;
  114. }



设置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

阅读(120) | 评论(1) | 转发(0) |
给主人留下些什么吧!~~

pacman20002017-09-10 10:10:07

如果是查看程序系统调用的情况,可以用命令strace或truss展示。在linux环境是strace,在AIX环境是truss。
命令可以显示参数指定的可执行程序,在运行过程中所有的系统调用和返回值情况,也可以指定pid显示正在运行中的程序情况,也相当不错。

评论热议
请登录后评论。

登录 注册