时延检测利器-uftrace

时间:2022-05-01 00:43:52

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

  篇幅较长,阅读耗时告警!

一、前言

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

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

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

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

二、抛砖引玉

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

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

时延检测利器-uftrace

图 1

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

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

时延检测利器-uftrace

图 2

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

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

时延检测利器-uftrace

图 3

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

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

时延检测利器-uftrace

图 4

时延检测利器-uftrace

 图 5

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

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

 三、uftrace简介

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

(1)安装简介

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

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

  时延检测利器-uftrace

  时延检测利器-uftrace

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

  时延检测利器-uftrace

(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会保存程序结束前的采集数据,方便我们分析长时间运行的程序。

时延检测利器-uftrace

 图 6

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

  结果截取片段:

时延检测利器-uftrace

图 7

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

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

时延检测利器-uftrace

图 8

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

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

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

  结果截取片段:

时延检测利器-uftrace

图 9

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

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

时延检测利器-uftrace


时延检测利器-uftrace

图 10

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

四、uftrace大显身手

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

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

(1)背景

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

(2)问题现象

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

时延检测利器-uftrace

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

时延检测利器-uftrace

(3)尝试的解决手段

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

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

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

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

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

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

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

(4)问题举例

  问题1:循环+树遍历

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

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

  功夫不负有心人,先上图(图比较宽,受排版影响,有些模糊)。

时延检测利器-uftrace

图 11

时延检测利器-uftrace

图 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

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

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

  结果如下图所示:

时延检测利器-uftrace

图 13

  日志说明:

  使用了条件“-t 2”,查看日志里是否存在大于2s以上的函数耗时。结果还真有,居然是access,真是想不到是它!

  问题分析:

  为什么access系统调用造成了长延时?后来才知道是有位兄弟会使劲的往某个目录下新增文件,一个目录下居然达到了上万个文件,然后某个时候又会去读取其中的某个文件,结果就是卡死!还是印证了前面提到过的一句话:代码没问题不代表就是份好代码。

  解决方法:

  写文件改为写数据库,把所有要保存的文件信息按id存到数据库。

 

  uftrace使用技巧tip:

  1、record模式,使用-F,只记录你怀疑的大函数,可以减少日志量;

  2、record模式,使用-t,只记录大于时间参数t的执行日志,相当于检查业务运行过程中是否存在偶发时延,同时可以减少很多日志量;

  3、replay模式,可以使用-t,查看结果中是否存在大于指定时间参数以上的运行函数,帮助我们快速定位时延位置;

  4、replay模式,可以使用-r,快速获取指定时间范围内的日志信息,也是一种很好的过滤能力。这个能力,我给社区提过一个BUG,且得到了修正。https://github.com/namhyung/uftrace/issues/1593

  其它技巧,uftrace安装包的 /doc/uftrace.html文档有很详细的介绍,真的写得非常好,朋友们可以多多参考。

五、结语

  通常,我们很难观察到业务程序的偶发时延,想挖掘出偶发时延的背后原因更是难上加难!万幸还有uftrace的存在,可以针对性的解决这一类问题。

  现实中总有很多意料之外的事情,不仅仅是技术,生活亦是如此,即使我们在这之前已经做了很充分的准备工作。遇到问题时只要我们不放弃,且经得住持久战,那解决问题后的成就感就会让自己觉得之前的所有付出都是值得的。

  技术是不断实践积累的,在此分享出来与大家一起共勉!

  码字不易,把解决问题的方法阐述清楚更不容易。如果文章对你有些许帮助,还请各位技术爱好者登录点赞呀,非常感谢!

 

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