AIX下C/C++函数性能统计实现方法

在AIX中，xlc编译器有个选项-qfunctrace，使用此选项编译的程序，自动会在每个函数的入口出口处调用以下自定义函数。

extern "C" void
__func_trace_enter(const char * const proc_name,
                   const char * const file_name,
                   const int line_no,
                   void ** const id);

extern "C" void
__func_trace_exit(const char * const proc_name,
                   const char * const file_name,
                   const int line_no,
                   void ** const id);

extern "C" void
__func_trace_catch(const char * const proc_name,
                   const char * const file_name,
                   const int line_no,
                   void ** const id);

在函数调用前，执行__func_trace_enter()，函数正常返回后，执行__func_trace_exit()。如果函数是通过throw异常抛出的，那么在异常被catch捕获处，执行__func_trace_catch()，但是遇到catch(...)捕获不会执行。值得注意的是，如果时throw抛出，不会触发__func_trace_exit()。

使用这个功能，可以实现无需修改源程序，进行性能统计的效果。程序如下。

tr.cpp为自定义函数出入口程序，每个函数执行时都会经过。编译成为libfunctr.so。

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

using std::vector;
using std::string;
using std::clog;
using std::endl;

extern "C" void print_trace();

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) {}
};

static vector<Stat> tracev;
static int clvl = 0;

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;
    for (auto s = tracev.begin(); s!=tracev.end(); s++)
    {
        if (s->etm == 0)
            s->oitv += itv;
    }
    --clvl;
    if (clvl == 0)
        print_trace();
}

extern "C" void print_trace()
{
    time_t t;
    char buf[30];
    for (auto s = tracev.begin(); s!=tracev.end(); s++)
    {
        clog << s->lvl << "\t";
        t=s->stm/1000000;
        strftime(buf, sizeof(buf), "%Y%m%d%H%M%S", localtime(&t));
        clog << buf << "." << s->stm % 1000000 << "\t";
        t=s->etm/1000000;
        strftime(buf, sizeof(buf), "%Y%m%d%H%M%S", localtime(&t));
        clog << buf << "." << s->etm % 1000000 << "\t";
        clog << s->etm-s->stm << "\t" << s->oitv << "\t" << s->etm-s->stm-s->oitv << "\t";
        clog << string(s->lvl-1, ' ') << s->name << endl;
    }
}

tt.c为演示的例子程序。编译成可执行文件tt。

#include <stdio.h>

int f2(int i)
{
    return i*2;
}

int f1(int i)
{
    return f2(i+1);
}

int main(int argc, char **argv)
{
        for (int i=0;i<2;i++)
            f1(i);
}

makefile为把tr.cpp编译成so库，给tt.c连接使用（不修改tt.c任何代码）。注意编译tt.c时使用了-qfunctrace和-lC。

all:
xlC -bnoentry -G -o libfunctr.so -qlanglvl=extended0x tr.cpp
chmod go-rwx libfunctr.so
xlc -bdynamic -brtl -qfunctrace -o tt tt.c -L. -lfunctr -lC

执行后，效果如下：
$tt
1       20170429170216.354105   20170429170216.354151   46      27      19      main() : tt.c
2       20170429170216.354123   20170429170216.354137   14      6       8        f1() : tt.c
3       20170429170216.354130   20170429170216.354136   6       0       6         f2() : tt.c
2       20170429170216.354138   20170429170216.354151   13      6       7        f1() : tt.c
3       20170429170216.354144   20170429170216.354150   6       0       6         f2() : tt.c

分别表示：函数的层次，开始时间，结束时间，总耗时（包含嵌套调用），嵌套调用其他函数总耗时，函数自身代码耗时，函数名和源文件名。