基于ltrace的linux自定义函数耗时统计方法

一.背景

• 某个linux动态库里有许多c/c++ API,没有头文件
• 想知道哪一个API最耗时最多,哪一个API调用的频次最多
• 因为没有头文件,且API众多.基于LD_PRELOAD机制的API拦截方式不友好

二.方法

• 基于ltrace -e <api名字> 和 ltrace_add_callback 已有的功能
• 增加从配置文件中添加add_filter_rule的功能
• 在ltrace_add_callback回调中打印API的库名、函数名以及耗时
• 采用shell脚本统计耗时最多的API,以及频次最高的API
• 进一步,可基于该方法生成timeline

三.演示步骤

1.下载源码

git clone https://gitlab.com/cespedes/ltrace.git
cd ltrace
git checkout 8eabf684ba6b11ae7a1a843aca3c0657c6329d73

2.打patch

cat > ltrace.patch <<-'EOF'
diff --git a/main.c b/main.c
index ff7c2c0..084389d 100644
--- a/main.c
+++ b/main.c
@@ -42,6 +42,25 @@ endcallback(Event *ev) {}*/+#include "proc.h"
+#include <time.h>
+#include <sys/time.h>
+#include "summary.h"
+static void
+callback_call_usr(Event * ev) {
+       if(ev->proc->func_name)
+       {
+               unsigned d = ev->proc->callstack_depth;
+               if(d>0)
+               {
+                    struct callstack_element *elem = &ev->proc->callstack[d-1];
+                    struct timedelta spent = calc_time_spent(elem->enter_time);
+                   unsigned long long dur=spent.tm.tv_sec*1000000+spent.tm.tv_usec;
+                   printf("[perf](%s) (%s) %lld\n",ev->proc->so_name,ev->proc->func_name,dur);
+               }
+       }
+}
+intmain(int argc, char *argv[]) {ltrace_init(argc, argv);
@@ -51,7 +70,7 @@ main(int argc, char *argv[]) {ltrace_add_callback(callback_ret, EVENT_SYSRET);ltrace_add_callback(endcallback, EVENT_EXIT);*/
-
+        ltrace_add_callback(callback_call_usr, EVENT_SYSRET);ltrace_main();return 0;}
diff --git a/options.c b/options.c
index e602848..975787b 100644
--- a/options.c
+++ b/options.c
@@ -514,7 +514,28 @@ opt_F_get_kind(struct opt_F_t *entry)assert(entry->kind != OPT_F_UNKNOWN);return entry->kind;}
-
+static void
+add_filter_from_cfg(const char *cfg_file, struct filter **retp)
+{
+        struct filter *filt = malloc(sizeof(*filt));
+        if (filt == NULL) {
+           return;
+        }
+        filter_init(filt);
+        FILE *file;
+        char line[256];
+
+        file = fopen(cfg_file, "r");
+        if (file == NULL) {
+             return;
+       }
+       while (fgets(line, sizeof(line), file)) {
+               line[strcspn(line, "\n")] = '\0';
+               add_filter_rule(filt,"",0,line,0,"*",0);
+       }
+       fclose(file);
+       *slist_chase_end(retp) = filt;
+}char **process_options(int argc, char **argv){
@@ -563,7 +584,7 @@ process_options(int argc, char **argv)#if defined(HAVE_UNWINDER)"w:"#endif
-                       "cfhiLrStTVba:A:D:e:F:l:n:o:p:s:u:x:";
+                       "cfhiLrStTVba:A:D:e:E:F:l:n:o:p:s:u:x:";#ifdef HAVE_GETOPT_LONGc = getopt_long(argc, argv, opts, long_options, &option_index);
@@ -606,7 +627,9 @@ process_options(int argc, char **argv)case 'e':parse_filter_chain(optarg, &options.plt_filter);break;
-
+                case 'E':
+                       add_filter_from_cfg(optarg, &options.plt_filter);
+                       break;case 'f':options.follow = 1;break;
diff --git a/output.c b/output.c
index 9b20e09..6e5ff82 100644
--- a/output.c
+++ b/output.c
@@ -568,6 +568,8 @@ output_left(enum tof type, struct process *proc,libsym->lib->soname));const char *name = libsym->name;
+       proc->so_name=libsym->lib->soname;
+        proc->func_name=name;#ifdef USE_DEMANGLEif (options.demangle)name = my_demangle(libsym->name);
diff --git a/proc.h b/proc.h
index a611456..7733464 100644
--- a/proc.h
+++ b/proc.h
@@ -89,6 +89,9 @@ struct process {struct process *parent;         /* needed by STATE_BEING_CREATED */char * filename;pid_t pid;
+       const char * so_name;
+       const char * func_name;
+/* Dictionary of breakpoints (which is a mapping* address->breakpoint).  This is NULL for non-leader
EOF
git apply --ignore-whitespace ltrace.patch

3.编译

./autogen.sh
apt install libelf-dev -y
./configure --disable-werror
make -j
cd ..

4.生成测试程序

cat > api.h <<-'EOF'
typedef struct
{int   arg0;float arg1;char  arg2;char  *arg3;int   arg4[32];
}param;extern "C"
{int api_0(int arg0,int arg1,char *arg2,param arg3,param *arg4);int api_1(int arg0,int arg1,char *arg2,param arg3);int api_2(int arg0,int arg1,char *arg2,param *arg4);
}int api_cxx_0(int arg0,int arg1,char *arg2,param arg3,param *arg4);
int api_cxx_1(int arg0,int arg1,char *arg2,param arg3);
int api_cxx_2(int arg0,int arg1,char *arg2,param *arg4);
EOFcat > api.cpp <<-'EOF'
#include <stdio.h>
#include <unistd.h>
#include <stdlib.h>
#include "api.h"extern "C"
{int api_0(int arg0,int arg1,char *arg2,param arg3,param *arg4){    usleep(100);return 0x51;}int api_1(int arg0,int arg1,char *arg2,param arg3){usleep(1000);return 0x51;    }int api_2(int arg0,int arg1,char *arg2,param *arg4){usleep(10000);return 0x51;   }
}int api_cxx_0(int arg0,int arg1,char *arg2,param arg3,param *arg4)
{    usleep(200);return 0x51;
}int api_cxx_1(int arg0,int arg1,char *arg2,param arg3)
{usleep(2000);return 0x51;    
}int api_cxx_2(int arg0,int arg1,char *arg2,param *arg4)
{usleep(20000);return 0x51;   
}
EOFcat > demo.cpp <<-'EOF'
#include <stdio.h>
#include <string.h>
#include "api.h"int main(int argc,char *argv[])
{int arg0=1;int arg1=2;char *arg2="hello";param arg3;param arg4;    memset(&arg3,0,sizeof(arg3));memset(&arg4,0,sizeof(arg4));arg3.arg0=21;arg3.arg1=22.0;arg3.arg2='2';arg3.arg3="24";arg3.arg4[0]=25;arg3.arg4[31]=26;arg4.arg0=31;arg4.arg1=32.0;arg4.arg2='3';arg4.arg3="34";arg4.arg4[0]=35;arg4.arg4[31]=36;for(int i=0;i<2;i++){api_0(arg0,arg1,arg2,arg3,&arg4);api_1(arg0,arg1,arg2,arg3);api_2(arg0,arg1,arg2,&arg4); }for(int i=0;i<3;i++){api_cxx_0(arg0,arg1,arg2,arg3,&arg4);api_cxx_1(arg0,arg1,arg2,arg3);api_cxx_2(arg0,arg1,arg2,&arg4);}return 0;
}
EOF

5.编译测试程序,查看动态库中的符号

g++ -fPIC -O0 -shared -o libapi.so api.cpp
nm -D libapi.so | grep api

输出

0000000000001196 T _Z9api_cxx_0iiPc5paramPS0_
00000000000011c1 T _Z9api_cxx_1iiPc5param
00000000000011e8 T _Z9api_cxx_2iiPcP5param
0000000000001119 T api_0
0000000000001144 T api_1
000000000000116b T api_2

6.编译demo,使用ltrace工具统计API耗时

g++ -o demo -O0  demo.cpp  -L . -lapi -Wl,-rpath=.
./demo
nm -D libapi.so | grep -w T | awk '{print $3}' | grep  -e "api" > cfg.txt
./ltrace/ltrace -T -o /dev/null -E cfg.txt ./demo 2>&1 | tee prof.log

输出

[perf](demo) (api_0) 160
[perf](demo) (api_1) 1060
[perf](demo) (api_2) 10060
[perf](demo) (api_0) 160
[perf](demo) (api_1) 1060
[perf](demo) (api_2) 10060
[perf](demo) (_Z9api_cxx_0iiPc5paramPS0_) 260
[perf](demo) (_Z9api_cxx_1iiPc5param) 2061
[perf](demo) (_Z9api_cxx_2iiPcP5param) 20062
[perf](demo) (_Z9api_cxx_0iiPc5paramPS0_) 259
[perf](demo) (_Z9api_cxx_1iiPc5param) 2060
[perf](demo) (_Z9api_cxx_2iiPcP5param) 20062
[perf](demo) (_Z9api_cxx_0iiPc5paramPS0_) 259
[perf](demo) (_Z9api_cxx_1iiPc5param) 2060
[perf](demo) (_Z9api_cxx_2iiPcP5param) 20061

7.生成c++filt脚本

cat > dump.sh <<-'EOF'
#!/bin/bash
name=`c++filt $1`
echo "$name $2"
EOF
chmod +x dump.sh

8.API耗时统计

cat prof.log | egrep  "^\[perf\]" \| sort -n -t ' ' -k 3 -r \| head -n 10 | sed 's/[()]//g' \| awk '{print $2" "$3}' \| xargs -L2 ./dump.sh
cat prof.log | egrep  "^\[perf\]" \| sed 's/[()]//g' \| awk '{count[$2]++} END {for (k in count) print k, count[k]}' \| sort -n -t ' ' -k 2 -r \| head -n 5 \| xargs -L2 ./dump.sh

输出

# 按耗时最长的排序
api_cxx_2(int, int, char*, param*) 20062
api_cxx_2(int, int, char*, param*) 20061
api_2 10060
api_cxx_1(int, int, char*, param) 2060
api_1 1060# 统计调用次数
api_cxx_2(int, int, char*, param*) 3
api_cxx_0(int, int, char*, param, param*) 3
api_1 2