时延检测利器-uftrace-526互联

　　本文来自博客园，作者：T-BARBARIANS，转载请注明原文链接：https://www.cnblogs.com/t-bar/p/16898892.html 谢谢！

　　篇幅较长，阅读耗时告警！

一、前言

　　作为后台程序的开发人员，应用程序的性能一直是我们的核心关注点。

　　大到业务程序的架构设计、支撑业务的组件选型，小到具体某些功能相似方法的性能横向对比、编译优化、甚至抠某一行代码，目的都是为了给我们的程序插上翅膀。

　　有了这些就够了么？显然不是的，因为做到了这些，实际的综合表现还是未知的。就像生产一款新型汽车，组装好了你得拉出来溜一溜，对照众多测试用例，核验各项设计指标。

　　本文要介绍的就是借助uftrace工具，核查C/C++/Rust程序中每一个函数的执行耗时，在此基础上，优化耗时大的函数，真正为我们的程序起飞打下坚实基础。

二、抛砖引玉

　　介绍uftrace之前，先简单聊一聊perf。

　　perf是c/c++领域性能分析的一大利器。perf可以统计过去一段时间里，所有被执行函数和指令的CPU使用总时间，通过统计报表的形式，直观展示热点函数和指令的CPU占比。例如下图一所示，开发者可以通过对热点的针对性分析，达到程序性能优化的目的。

图 1

　　perf完美了么，就没有它不能覆盖的性能分析场景了么？显然不是，perf是基于过去一段时间的所有累计之和，是从宏观的角度去分析。那从微观角度，比如我有一个需求：有没有这样的一种工具，它可以记录某个用户态函数在过去一段时间里，每一次执行的单独耗时，以及它的完整调用链？从而挖出宏观角度发现不了的深坑！

　　例如一个“hello world”函数，大部分时间该函数的执行时长都比较一致，但是会偶发执行时长大幅增加的情况，那这背后的原因就值得我们去深入分析。

图 2

　　perf tools的ftrace具备“记录函数每一次的执行耗时”能力，但是ftrace是基于内核的，只能跟踪分析linux内核中各种函数的执行耗时。这里我使用trace-cmd工具（ftrace的一个命令行工具，大大简化ftrace的使用）来记录“do_page_fault”缺页中断函数在一段时间范围的执行耗时。

　　1、只查看函数的每一次执行耗时。

图 3

　　由图3可知，do_page_fault在内核的每一次执行，耗时都集中在1us左右，短时间内未见异常。

　　2、查看do_page_fault每次耗时，以及函数内部各子函数的执行耗时。

图 4

图 5

　　图5直接展示了do_page_fault函数内部各子函数的执行耗时。假设当某一次do_page_fault耗时异常，那就可以通过日志准确定位到某个异常的子函数，这样对我们定位问题是非常有用的。

　　那用户态呢，有分析和记录用户态函数执行耗时的工具么？答案是当然有，优秀的工具凤毛麟角，uftrace百里挑一！

三、uftrace简介

　　uftrace是一个分析C/C++/Rust用户态程序性能，且支持多线程性能分析的开源工具。

（1）安装简介

　　1、获取最新Release安装包，https://github.com/namhyung/uftrace

　　2、解压安装包，执行相关配置，编译，安装命令　　

　　最后，在指定的安装目录：/usr/local/uftrace下，有如下目录，uftrace的可执行程序就位于bin目录下。

（2）uftrace初露锋芒

　　如何使用uftrace呢？通过一个demo，我们先来实践一下uftrace的基本使用方法，以及初步介绍uftrace的时延分析方法。

　　有如下malloc多线程程序，每一个线程执行10S，且在每一个线程里会不断的多次重复执行malloc()和free()。

　　另外：

　　1、编译选项里要添加参数 -pg（使编译器在函数入口插入对mcount()桩函数的调用，从而实现每个函数的耗时记录）；

　　2、去掉所有优化选项-O，否则对于庞大的程序，uftrace只能展示优化后代码的串行执行顺序，非常不利于我们对照代码进行问题排查。

 1 #include <iostream>
 2 #include <pthread.h>
 3 #include <unistd.h>
 4 #include <sys/syscall.h>  
 5 
 6 using namespace std;
 7 
 8 #define gettid() syscall(__NR_gettid)
 9 
10 // g++ -g -pg -o multi_thread_malloc -std=c++11 multi_thread_malloc.c -lpthread
11 
12 void *malloc_time_delay(void *para)
13 {
14     int last_time;
15     int current_time;
16     int malloc_times = 0;
17     char *ptr;
18     
19     last_time = time(NULL);
20     current_time = time(NULL);
21     
22     //cout << "thread id:" << gettid() << ", malloc test begin" << endl << endl;
23     
24     while(1) {
25     
26         if(current_time - last_time >= 10) {
27             break;
28         }
29 
30         ptr = (char *)malloc(1024);
31         if(ptr == NULL) {
32             cout << "malloc error" << endl;
33             break;
34         }
35 
36         free(ptr);
37 
38         malloc_times++;
39         current_time = time(NULL);
40         usleep(1000);
41     }
42 
43     cout << "thread id:" << gettid() << ", malloc test over, malloc total times:" << malloc_times << endl;
44     pthread_exit(NULL);
45 }
46 
47 int main(int argc, char *argv[])
48 {
49     int cnt;
50     int max_thread_num = 2;
51 
52     pthread_t thread_ptr[8];
53     
54     for(cnt = 0; cnt < max_thread_num; ++cnt) {
55         if(pthread_create(&thread_ptr[cnt], NULL, malloc_time_delay, NULL)) {
56             cout << "malloc_time_delay thread create failed" << endl;
57             return -1;
58         }
59     }
60 
61     for(cnt = 0; cnt < max_thread_num; ++cnt) {
62         pthread_join(thread_ptr[cnt], NULL);
63     }
64 
65     return 0;
66 }

　　执行如图6所示的命令：

　　/usr/local/uftrace/bin/uftrace --time record ./multi_thread_malloc

　　--time表示记录时间信息，record表示使用分析模式。程序执行完毕后，会在当前目录生成uftrace.data目录，里面记录了程序运行过程中采集到的相关信息。当然，也可以在程序运行过程中通过：kill -15 $(pid)结束程序，uftrace会保存程序结束前的采集数据，方便我们分析长时间运行的程序。

图 6

　　通过replay模式查看multi_thread_malloc程序的时延信息。虽然记录了函数调用链和每个函数的执行时间，是不是总感觉乱乱的？那是因为uftrace把多线程的所有信息按时间顺序串行记录啦，导致记录信息有交叉。

　　结果截取片段：

图 7

　　升级一下命令，增加对线程id的过滤，一下子就清爽了很多，只展示了thread-8374随时间串行执行的执行链（结果只截取了片段）。

　　/usr/local/uftrace/bin/uftrace replay -f time,delta,duration,tid --tid 8374

图 8

　　但是问题又来了，我怎么知道众多的malloc函数里是否存在超长执行的情况呢？

　　那就使用时间过滤条件和函数过滤条件试试，比如查看是否存在执行耗时大于1us的malloc函数。

　　/usr/local/uftrace/bin/uftrace replay -f time,delta,duration,tid --tid 8374 -t 1us --filter=malloc

　　结果截取片段：

图 9

　　问题又来了，受屏幕限制，没法查看完所有的malloc函数执行耗时。那就把过滤后的结果进行重定向吧，通过文档查看所有的malloc执行耗时。

　　/usr/local/uftrace/bin/uftrace replay -f time,delta,duration,tid --tid 8374 -t 1us > thread-8374.log

图 10

　　multi_thread_malloc只是一个简单示例，通过uftrace分析，还真有波动较大的malloc执行耗时，不过都是us级，影响不大。但是uftrace提供的这种分析能力，可以让我们有机会发现大型，多线程用户态程序在运行过程中的明显耗时异常，从而挖掘出业务代码中隐藏的深坑，这与内核使用的ftrace异曲同工！

四、uftrace大显身手

　　我的代码逻辑没有问题（高光时刻）！看似很OK，现实很打脸（尬得一匹）。其实逻辑没有问题，不代表就是一份好代码。

　　接下来说说uftrace在我们业务系统中解决的问题吧。

（1）背景

　　我们有一个大型的多线程应用程序，代码量大，框架逻辑非常复杂。基于历史原因，该进程里同时有一个超时检测线程，专门用于检测是否存在任务运行超时、超长的工作线程，如果有工作线程出现超时运行情况，就会产生相关告警信息。

（2）问题现象

　　家里测试千百遍，运行很爽，很流畅，从未报线程运行超时。但是用户现场却不定时，不定期的出现任务线程超时告警，少的时候一两个，多的时候所有线程都在报任务超时，且超时都是秒级往上。好比监测中的心电图，突然出现一个突刺冲高，或者多个线程某段时间集体冲高，简直要了老命。

　　线程超时少发时，还能扛住现场业务流量。线程超时多发时，完全cover不住，丢包严重，造成了非常大的负面影响。老板说：“解决不了就给我立马滚蛋！”

（3）尝试的解决手段

　　问题很棘手，脑瓜嗡嗡嗡。

　　1、尝试过perf，但是perf是基于长时间的综合统计，根本不知道偶发的超时突刺出现在哪；

　　2、尝试过pstack，可是这个命令又卡又慢，等返回信息时，采集到的说不定是已经超时后的栈信息；

　　3、尝试过超时出现时，主动抛异常，并打印堆栈信息。看似有希望，但是捕捉到的有可能只是其中一段信息，或者说是超时执行链中的某一小段，信息量太少，根本没法站在更宏观的角度去观察问题所在。

　　确实，对于这种偶发性超时突刺问题，之前并没有发现比较好的定位手段。

　　4、带着相关问题搜索了很多信息，gprof是第一个我觉得有希望解决问题的工具，它是一个程序运行时间监测工具，可以统计出各个函数的调用次数、时间、以及产生函数的调用图。但是使用后发现一个致命缺点：不支持多线程，只有放弃。

　　5、继续带着相关关键词，github搜索一通，终于发现了uftrace，作用跟gprof类似，且完全支持多线程。写了一个前文第三部分，第（2）节“uftrace初露锋芒”的demo，经过验证后，得到了上面例举图片的结果。心中一阵莫名的惊喜，至少我有了可以尝试定位问题的手段。

（4）问题举例

　　问题1：循环+树遍历

　　使用uftrace运行我们的被监测程序，出现超时告警日志后，手动Kill掉程序，得到了过去一段时间该进程的所有运行日志。

　　心情忐忑又焦急，一是担心抓不到问题点；二是日志量很大，需要使用前面的相关过滤手段产生日志文件，然后再把日志切割分片（split命令，推荐）为很多小份日志（日志大了电脑没法打开了。。。），最后才能详细的研究相关日志。

　　功夫不负有心人，先上图（图比较宽，受排版影响，有些模糊）。

图 11

图 12

　　抓取结果如上图所示，执行链实在太长，只截取了开始和结束的部分信息。

　　日志说明：

　　1、上帝角度。函数调用链非常清楚。线程ID：68963随时间递增的执行过程打印得明明白白。

　　2、问题证据。记录了函数StreamTcpReassembleAppLayer的执行耗时为4.542秒，直接把线程68963卡死。

　　3、耗时原因。在函数里有一个while循环，第一次while循环时，SBB_RB_NEXT函数只执行了1次；第二次while循环时，SBB_RB_NEXT执行了2次；依次递增，到最后一次while循环时，SBB_RB_NEXT执行了8800+次；整个while循环里，执行了300多万次SBB_RB_NEXT！

　　站在上帝的视角，发现问题的同时还抓到了证据！这就是uftrace的价值所在！

　　问题分析：

　　1、为什么家里不会复现？家里的测试数据，while执行几十，上百次到顶。通常也是几百或者上千微秒，耗时很短，问题根本无法复现。

　　2、耗时原因是什么？数据重组导致外层按数据总个数循环，每一次的外层循环再嵌套了一次里层按偏移遍历树的操作，导致出现N*M的操作。万万没想到居然还有这种流量存在，也进一步说明了当前使用的数据结构存在缺陷。

　　解决方法：

　　现场的快速解决方式：某个异常数据超过设定的阈值后直接砍断。业务先恢复了再说，哈哈哈！

　　问题2：系统调用access

　　自从解决了上面的重大问题，现场业务再也没有出现过超时告警了，老板最近也不叫我立马滚蛋了。可是好景不长，线程超时告警又出现了，不过这次是出现在家里，还用不着被老板威胁！

　　再次秀出独门绝技，三下五除二就把问题给捉住了，老板扬起嘴角笑了笑并说道：“下午请你吃个饼”，但是闭口不提涨工资。

　　结果如下图所示：