博客

通过采样方法获取程序不同函数执行时间的profile，需要每间隔一个固定的时间，查看CPU当前正在执行的代码段及其所属函数。当采样的频率较高时，能从统计意义上还原出程序各个部分的执行时间，但也会带来一定的开销。

整体来看，采样方法的流程为：

1. （根据设定的采样频率）定时发出中断
2. 查看程序当前栈帧
3. 在每一帧上查询符号表获取函数名
4. 采样计数器上累加1
5. 最后程序结束时，收集每个函数的采样数，并（按比例摊分）计算每个函数的执行百分比和时间

定时发出中断

这部分主要参考了一篇

关于Linux定时器设置的博客

。常用的

alarm()

定时器只能精确到秒。因此这里采用支持3种类型的定时器

setitimer()

，其中适用的ITIMER_REAL类型（第一个参数）以系统真实的时间来计算，发出SIGALRM信号。第二个参数为设置的发出SIGALRM信号的第一次的时间和之后每次间隔的时间，可以根据程序输入的采样频率对应地设置间隔（默认最小单位为微秒）。

struct itimerval tick;
memset(&tick, 0, sizeof(tick));// initialize struct
tick.it_value.tv_sec  = 0;// sec
tick.it_value.tv_usec = 5;// micro sec
tick.it_interval.tv_sec  = 0;
tick.it_interval.tv_usec = interval;
printf("sample per %d us = %d Hz\n", interval, 1000000/interval);

// set timer, ITIMER_REAL: real-time to decrease timer, send SIGALRM when timeout
res = setitimer(ITIMER_REAL, &tick, NULL);

if (res) {
  printf("Set timer failed!\n");
  exit(1);
}

SIGALRM信号的自定义处理

发出SIGALRM信号后，接下来要捕获信号、并且相应做出该信号的处理。这部分主要参考一篇

关于Linux系统编程的博客

，下图也引自该博客。



这张图描述了信号发出、捕捉和处理，具体为：

1. 用户程序注册
   
SIGALRM

   信号的处理函数
   
sighandler

2. 在执行某个用户态函数时，发生中断或异常切换到内核态
3. 在中断处理完毕后要返回原来的用户态函数之前，检查到有信号
   
SIGALRM

   递达
4. 内核决定返回用户态后不是恢复原函数的上下文继续执行，而是执行
   
sighandler

   函数，
   
sighandler

   和原用户态函数使用不同的堆栈空间，它们之间不存在调用和被调用的关系，是两个独立的控制流程。

注册

SIGALRM

信号的处理函数

backtrace()

通过头文件

<signal.h>

中的

signal

这个函数。这样就将信号和对应的处理函数绑定了。

int main() {
  signal(SIGALRM, backtrace);
  ...
}
void backtrace(int sig) {
  ...
}

获取栈帧和查询符号表

这部分主要参考一篇

关于在程序中打印C++调用堆栈的博客

。需要用到libunwind库，这个库用起来也比较方便。这里采用的是获取当前程序堆栈，也就必须在被profile的程序中调用libunwind接口才能获取到堆栈信息，可移植性有点差，需要手动对源代码添加以上的设置时钟、处理函数的操作。


backtrace()

函数代码如下，函数依次完成：

1. 获取当前程序执行的上下文：
   
unw_getcontext

2. 本地初始化cursor：
   
unw_init_local

3. 根据cursor遍历所有的调用栈帧：
   
unw_step

4. 获取当前栈帧中的program counter：
   
unw_get_reg

5. 根据这个pc值，查询符号表，获知对应的函数名和在函数内部的地址偏移：
   
unw_get_proc_name

6. 将C++ABI标识符转换成源程序标识符：
   
abi::__cxa_demangle

   （实际统计时，这一步没用，只是为了方便打印出来看而已，但这步demangle操作开销也不大）
7. 对应的计数器+1，这里采用STL库的
   
unordered_map

   来实现
   
string

   类型到
   
int

   类型的统计

void backtrace(int sig) {
  double t = wall_time();
  unw_cursor_t cursor;
  unw_context_t context;
  unw_getcontext(&context);
  unw_init_local(&cursor, &context);

  char sym[256];
  while (unw_step(&cursor) > 0) {
    unw_word_t offset, pc;
    unw_get_reg(&cursor, UNW_REG_IP, &pc);
    if (pc == 0)  break;
    
    double t_queary = wall_time();
    int flag = unw_get_proc_name(&cursor, sym, sizeof(sym), &offset);
    times[TIMER_QUERY] += wall_time() - t_queary;

    if (flag == 0) {
      int status = 99;
      char* demangled = abi::__cxa_demangle(sym, nullptr, nullptr, &status);
      char* nameptr = (status == 0) ? demangled : sym;
      double tt = wall_time();
      hashStr[std::string(nameptr)]++;
      times[TIMER_HASH] += wall_time() - tt;

      free(demangled);
    } else {
      printf(" -- error: unable to obtain symbol name for this frame\n");
    }
  }
  times[TIMER_BACKTRACE] += wall_time() - t;
}

如果需要单开一个进程跑程序，另外用一个进程来远程地打印堆栈，可以参考

这篇博客

，libunwind也能实现。

累加和统计时间

根据上述得到的各次采样的统计，近似认为每个函数出现的次数在统计总次数中的比例，就是其执行时间占比。而程序运行的总时间是可以通过

gettimeofday()

函数掐表得到的。

std::vector<Func_Time> list;
for(std::unordered_map<std::string, int>::iterator it = hashStr.begin(); it != hashStr.end(); it++) {
  list.push_back(Func_Time(it->first, it->second));
}
sort(list.begin(), list.end());
printf("%-25s %10s %10s\n", "Func", "sample", "time/s");
for (std::vector<Func_Time>::iterator it = list.begin(); it != list.end(); it++){
  if (it->name != "killpg" && it->name != "_start" && it->name != "__libc_start_main")
    printf("%-25s %10d\t %.6lf\n", (it->name).c_str(), it->cnt, (double)it->cnt / (double)list[0].cnt * times[PROGRAM]);
}

在这里忽略掉了函数名为

killpg

，

_start

和

__libc_start_main

的函数，因为前者是调用backtrace时最内的帧，后两者是最外的两帧，所有的采样都会有它们三者（采样数上也等同于

main

函数），所以没什么意义。

对简单程序的分析

写一个简单的demo程序：

#include <stdio.h>
#include <stdlib.h>

int func_a(){
  int i = 0, g = 0;
  while(i++ < 100000){
    g += i;
  }
  return g;
}

int func_b(){
  int i = 0, g = 0;
  while(i++ < 400000){
    g += i;
  }
  return g;
}

void wrapper_a() {
  func_a();
}

void wrapper_b() {
  func_b();
}


int main(int argc, char** argv) {

  int iterations, interval;
  if(argc != 3){
    printf("Usage %s <No of Iterations> <Interval of us>\n", argv[0]);
    exit(-1);
  } else {
    iterations = atoi(argv[1]);
    interval = atoi(argv[2]);
  }

  while (iterations--) {
    wrapper_a();
    wrapper_b();
  }

  return 0;
}

很明显，调用函数

func_a()

的次数与

func_b()

相同，而前者处理的数目是后者的四倍，因此“期待”可以看到采样结果大致为

func_b()

的耗时为

func_a()

的四倍左右。而

wrapper_a()

和

wrapper_b()

的封装只是用来检验栈帧的回溯效果。

不同采样频率下的结果比较

选择测试的

iterations

为8000次，分别设定采样间隔为20000微秒（50Hz），10000微秒（100Hz），5000微秒（200Hz），2000微秒（500Hz）。下表中sample是采样得到的次数，

time

是按次数占比估算的运行时间。



可以看到，不管采样频率多少，基本有

func_b()

的耗时为

func_a()

的四倍左右这个规律。但是其各自的耗时以及总的程序耗时，都随着采样频率增加而增加，这意味着

采样本身带来了不小的开销

。

运行时开销及其最大来源

通过

gettimeofday()

函数掐表得到采样各部分的时间，分别为setup部分、采样部分和最后的排序统计部分。其中采样部分是最耗时的，并且进一步细分插装计时（query和hash均为backtrace的一部分，见上面的backtrace函数的代码），确定了最耗时的是

unw_get_proc_name

函数的执行。也就是说，通过程序计数器的值去查符号表得到函数名的这一步，是整个基于采样的热点分析的瓶颈。而且随着采样频率增加，

额外引入的开销

（采样部分用时占整个程序用时的比例：(setup+backtrace+sort)/program）几乎线性增加。



不加采样时，程序总的运行时间为，所以上述四种采样频率的

运行时开销

（程序的运行时间 与 在采样工具下程序的运行时间 进行对比）分别为

3.6%，9.2%，19.6%和63.3%

。

与gprof的比较

同样的程序，用gprof编译和运行

g++ -pg tick_1.cpp -o tick_1_cpp_pg
./tick_1_cpp_pg 8000 100000 # 生成一份gmon.out文件
gprof tick_1_cpp_pg gmon.out -p

查看得到其profile信息：

可以看到gprof还区分了函数自身运行的时间，例如对

wrapper_a()

和

wrapper_b()

的时间统计就是0。这个也是容易实现的，自身运行的时间应归属于追溯栈帧时除

killpg

外的第一个栈帧的那个函数。所以只要再额外多开一个哈希表记录函数为“第一现场”的采样数目即可，额外引入的开销并不大。

此例子中每次采样0.01s (100Hz)，对比自己实现的结果，可见同在100Hz时，自测的结果偏大（因为采样引入的开销大了）；而更接近于自测的50Hz的结果。