个人中心
文章发布
退出
作者热门文章
- Java锁的逻辑（结合对象头和ObjectMonitor）
- 还在用饼状图？来瞧瞧这些炫酷的百分比可视化新图形（附代码实现）⛵
- 自动注册实体类到EntityFrameworkCore上下文，并适配ABP及ABPVNext
- 基于Sklearn机器学习代码实战
32
4
本文来自博客园，作者： T-BARBARIANS ，转载请注明原文链接： https://www.cnblogs.com/t-bar/p/16898892.html 谢谢！ 。
篇幅较长，阅读耗时告警！ 。
1、前言 。
作为后台程序的开发人员，应用程序的性能一直是我们的核心关注点.
大到业务程序的架构设计、支撑业务的组件选型，小到具体某些功能相似方法的性能横向对比、编译优化、甚至抠某一行代码，目的都是为了给我们的程序插上翅膀.
有了这些就够了么？显然不是的，因为做到了这些，实际的综合表现还是未知的。就像生产一款新型汽车，组装好了你得拉出来溜一溜，对照众多测试用例，核验各项设计指标.
本文要介绍的就是借助uftrace工具，核查C/C++/Rust程序中每一个函数的执行耗时，在此基础上，优化耗时大的函数，真正为我们的程序起飞打下坚实基础.
2、抛砖引玉 。
介绍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百里挑一！ 。
3、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异曲同工！ 。
4、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文档有很详细的介绍，真的写得非常好，朋友们可以多多参考.
5、结语 。
通常，我们很难观察到业务程序的偶发时延，想挖掘出偶发时延的背后原因更是难上加难！万幸还有uftrace的存在，可以针对性的解决这一类问题.
现实中总有很多意料之外的事情，不仅仅是技术，生活亦是如此，即使我们在这之前已经做了很充分的准备工作。遇到问题时只要我们不放弃，且经得住持久战，那解决问题后的成就感就会让自己觉得之前的所有付出都是值得的.
技术是不断实践积累的，在此分享出来与大家一起共勉！ 。
码字不易，把解决问题的方法阐述清楚更不容易。如果文章对你有些许帮助，还请各位技术爱好者登录点赞呀，非常感谢！ 。
。
本文来自博客园，作者： T-BARBARIANS ，转载请注明原文链接： https://www.cnblogs.com/t-bar/p/16898892.html 谢谢！ 。
最后此篇关于时延检测利器-uftrace的文章就讲到这里了,如果你想了解更多关于时延检测利器-uftrace的内容请搜索CFSDN的文章或继续浏览相关文章，希望大家以后支持我的博客！ 。
32
4
0
本文来自博客园，作者： T-BARBARIANS ，转载请注明原文链接： https://www.cnblogs.com/t-bar/p/16898892.html 谢谢！
我正在尝试 uftrace分析以下简单的 C++ 程序: #include class A { public: A() {std::cout << "A is created" <<
我是一名优秀的程序员,十分优秀！