本文来自博客园,作者: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
自从解决了上面的重大问题,现场业务再也没有出现过超时告警了,老板最近也不叫我立马滚蛋了。可是好景不长,线程超时告警又出现了,不过这次是出现在家里,还用不着被老板威胁!
再次秀出独门绝技,三下五除二就把问题给捉住了,老板扬起嘴角笑了笑并说道:“下午请你吃个饼”,但是闭口不提涨工资。
结果如下图所示:
图 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 谢谢!
标签:malloc,超时,函数,耗时,利器,时延,uftrace,执行 From: https://www.cnblogs.com/t-bar/p/16898892.html