uprobe trace多线程mutex等待耗时

问题背景环境

ubuntu2204 服务器支持debugfs uprobe，为了提升应用程序的性能，需要量化不同参数下多线程主程序等待在mutex上的耗时区别

linux document中对uprobe events的说明如下

uprobetracer.rst - Documentation/trace/uprobetracer.rst - Linux source code (v6.1.34) - BootlinElixir Cross Referencer - Explore source code in your browser - Particularly useful for the Linux kernel and other low-level projects in C/C++ (bootloaders, C libraries...)https://elixir.bootlin.com/linux/v6.1.34/source/Documentation/trace/uprobetracer.rst

uprobe event基本使用

uprobe event 测试追踪共享库中的符号func_test和执行文件中的符号main_test

//test.c 
#include <stdio.h>
int func_test(void)
{printf("uprobe test\n");
}//main.c 
#include <stdio.h>
extern int func_test(void);
void main_test(void)
{printf("main test\n");
}
int main(void)
{func_test();main_test();return 0;
}

//run.sh 
if [ "_$1" = "_set" ]; then
echo build...
gcc -shared -fPIC -o libuptest.so ./test.c 
gcc main.c -o uptestbin -L./ -luptest
else
echo run...
export LD_LIBRARY_PATH=$LD_LIBRARY_PATH:./ 
./uptestbin
fi
//编译完成后文件列表
tree ./
./
├── libuptest.so
├── main.c
├── run.sh
├── test.c
└── uptestbin

查看main_test 与 func_test符号地址

readelf -s ./libuptest.so | grep func_test6: 0000000000001119    26 FUNC    GLOBAL DEFAULT   14 func_test23: 0000000000001119    26 FUNC    GLOBAL DEFAULT   14 func_test
readelf -s ./uptestbin | grep main_test24: 0000000000001169    26 FUNC    GLOBAL DEFAULT   16 main_test

//1.先清一下trace，disable uprobe trace
echo 0 > /sys/kernel/debug/tracing/events/uprobes/enable 
echo "" > /sys/kernel/debug/tracing/trace//2.把追踪事件注册成uprobe events，具体语法参见kernel文档中描述
echo 'p /home/path/test_prj/libuptest.so:0x1119' > /sys/kernel/debug/tracing/uprobe_events 
echo 'r /home/path/test_prj/uptestbin:0x1169' > /sys/kernel/debug/tracing/uprobe_events //3.确认events注册成功
cat /sys/kernel/debug/tracing/uprobe_events
p:uprobes/p_libuptest_0x1119 /home/path/test_prj/libuptest.so:0x0000000000001119
r:uprobes/p_uptestbin_0x1169 /home/path/test_prj/uptestbin:0x0000000000001169tree /sys/kernel/debug/tracingevents/uprobes/
events/uprobes/
├── enable
├── filter
├── p_libuptest_0x1119
│   ├── enable
│   ├── filter
│   ├── format
│   ├── hist
│   ├── id
│   ├── inject
│   └── trigger
└── p_uptestbin_0x1169├── enable├── filter├── format├── hist├── id├── inject└── trigger//4.重新enable uprobe trace
echo 1 > /sys/kernel/debug/tracing/events/uprobes/enable //5.执行程序并查看trace log
./run.sh
cat /sys/kernel/debug/tracing/trace#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |uptestbin-20980   [003] DNZff 109458.753460: p_libuptest_0x1119: (0x7f4fc9d6d119)uptestbin-20980   [003] DNZff 109458.753487: p_uptestbin_0x1169: (0x5576f8d4f195 <- 0x5576f8d4f169)

app源码修改

我们想追踪某一个多个线程调用某个mutex_lock至mutex_unlock的事件，mutex_lock和mutex_unlock被使用的地方太多，需要加以改造加一层函数，改为追踪fake_lock与fake_unlock事件，来排除一下干扰信息

void fake_lock()
{mutex_lock();
}void fake_unlock()
{mutex_unlock();
}

另外uprobe event在追踪共享库中的符号的时候需要指定共享库的绝对路径，同时要保证执行程序的编译时候指定的共享库的路径没有多余的路径(遇到过ldd 结果是../libuptest.so的注册时候用绝对路径trace不到)，要么是绝对路径要么没有路径，可以使用ldd uptestbin来检查 。共享库的名称也要注意不要libup_test.so，中间不要有"_"

ldd uptestbin linux-vdso.so.1 (0x00007ffed1dd9000)libuptest.so (0x00007f25f46a9000)

分析trace log

得到trace 到的log，假设fake_lock是0x1119，fake_unlock是0x1169，每次事件都有一个精确到us的时间戳，正符合需求统计耗时

thread-1624   [007] DNZff 21606.070168: p_libuptest_0x1119:
thread-1624   [007] DNZff 21606.080370: p_libuptest_0x1169:
thread-1624   [007] DNZff 21606.080654: p_libuptest_0x1119:
thread-1624   [007] DNZff 21606.090877: p_libuptest_0x1169:

 用awk处理trace.log最终得到奇数与偶数行的差值的平均值

awk -F'[ :]' '{ if(NR%2==0) {sum+=$6} else{sum-=$6};} END {print sum/(NR/2)}' ./trace.log