业务时延检测利器-uftrace
本文来自博客园，作者：T-BARBARIANS，博文严禁转载，转载必究！
篇幅较长，阅读耗时告警！
一、前言
作为后台程序的开发人员，应用程序的性能一直是我们的核心关注点。
大到业务程序的架构设计、支撑业务的组件选型，小到具体某些功能相似方法的性能横向对比、编译优化、甚至抠某一行代码，目的都是为了给我们的程序插上翅膀。
有了这些就够了么？显然不是的，因为做到了这些，实际的综合表现还是未知的。就像生产一款新型汽车，组装好了你得拉出来溜一溜，对照众多测试用例，核验各项设计指标。
本文要介绍的就是借助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
自从解决了上面的重大问题，现场业务再也没有出现过超时告警了，老板最近也不叫我立马滚蛋了。可是好景不长，线程超时告警又出现了，不过这次是出现在家里，还用不着被老板威胁！
再次秀出独门绝技，三下五除二就把问题给捉住了，老板扬起嘴角笑了笑并说道：“下午请你吃个饼”，但是闭口不提涨工资。
结果如下图所示：
图 13
日志说明：
使用了条件“-t 2”，查看日志里是否存在大于2s以上的函数耗时。结果还真有，居然是access，真是想不到是它！
问题分析：
为什么access系统调用造成了长延时？后来才知道是有位兄弟会使劲的往某个目录下新增文件，一个目录下居然达到了上万个文件，然后某个时候又会去读取其中的某个文件，结果就是卡死！还是印证了前面提到过的一句话：代码没问题不代表就是份好代码。
解决方法：
写文件改为写数据库，把所有要保存的文件信息按id存到数据库。
uftrace使用技巧tip：
record模式
1、使用-t，只记录大于时间参数t的执行日志，相当于检查业务运行过程中是否存在偶发时延，可以减少很多日志量。
在摸石头过河的初期，先使用 -t 比较好，因为我们不知道时延发生在哪里，如果真的有大于等于 -t 的时延存在，时延被记录的同时，也会减少非常多的日志。
2、使用-F，只记录上一步通过 -t 得到的，发生大时延的函数，可以过滤掉很多不相关，对分析没有帮助的日志。
先使用 -t 捕捉到时延发生时的调用链，再使用-F跑一次，得到时延发生时的详细日志。
replay模式
1、可以使用-t，查看结果中是否存在大于指定时间参数以上的运行函数，帮助我们快速定位时延位置；
2、可以使用-r，快速获取指定时间范围内的日志信息，也是一种很好的过滤能力。这个能力，我给社区提过一个BUG，且得到了修正。https://github.com/namhyung/uftrace/issues/1593
其它技巧，uftrace安装包的 /doc/uftrace.html文档有很详细的介绍，真的写得非常好，朋友们可以多多参考。
五、结语
通常，我们很难观察到业务程序的偶发时延，想挖掘出偶发时延的背后原因更是难上加难！万幸还有uftrace的存在，可以针对性的解决这一类问题。
现实中总有很多意料之外的事情，不仅仅是技术，生活亦是如此，即使我们在这之前已经做了很充分的准备工作。遇到问题时只要我们不放弃，且经得住持久战，那解决问题后的成就感就会让自己觉得之前的所有付出都是值得的。
技术是不断实践积累的，在此分享出来与大家一起共勉！
如果文章对你有些许帮助，还请各位技术爱好者登录点赞呀，非常感谢！
本文来自博客园，作者：T-BARBARIANS，博文严禁转载，转载必究！
