Skip to content

Commit

Permalink
增加lock_image的数据关联分析
Browse files Browse the repository at this point in the history
  • Loading branch information
@albertxu216
albertxu216 committed Jul 19, 2024
1 parent 7afa47c commit 4de9fea
Showing 1 changed file with 307 additions and 0 deletions.
307 changes: 307 additions & 0 deletions eBPF_Supermarket/CPU_Subsystem/eBPF_proc_image/docs/测试与数据关联.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -341,3 +341,310 @@ exit可以用于终止进程, 会导致当前进程的执行终止，并返回

- 原理：挂载点在sys_enter_exit、sys_enter_exit_group上，用户态进程执行exit时会通过系统调用在内核中进行相关操作，通过sys_enter_exit、sys_enter_exit_group便可以获取到用户态进程终止时的信息；



## 2.lock_image

lock_image 是一个用于捕获进程持有用户态锁的工具，聚焦于进程持有的所有用户态锁(互斥锁、自旋锁、读写锁)。通过ebpf技术将其挂载固定的挂载点上，并在进程持有以上几种锁时进行数据收集，并对数据进行处理；

本次测试以及数据关联工作分为三部分：

- lock_image工具逻辑正确性的测试；
- lock_image工具数据正确性的测试；
- lock_image工具数据的关联关系，以及原理梳理；

### 2.1 测试用例 test_lock

为了完成以上三步测试与数据关联工作，需要设计一个测试用例，使用该测试用例可以测试lock_image工具的逻辑正确性，并通过和lttng工具测试的结果进行对比，判断lock_image数据正确性；

lock_image工具关注的是进程持有用户态锁的情况，故需要用到lttng-ust，我们需要在lttng中自定义跟踪函数用以跟踪测试用例中涉及到的进程对锁的相关行为；

#### 2.1.1 测试用例设计思路

测试用例主要目的是为了模拟进程或线程成功持有锁、未成功持有锁以及争用一个锁的情景。

测试用例主要思路

- 对测试用例进程进行cpu绑核,提高优先级,保证当前cpu仅运行一个或一组进程;
- 分别定义一个自旋锁、互斥锁以及读写锁并初始化，用于线程争用持有这些锁，来查看lock_image是否能准确的获取到线程持有锁的状态以及锁的信息；
- 创建两个线程分别去申请持有提前定义好的锁，并在特殊点插入lttng-ust跟踪函数，用来和lock_image进行数据对比；
- 线程1分别去持有互斥锁、解锁互斥锁，持有读写锁-写锁、释放读写锁，持有自旋锁、释放自旋锁；
- 考虑到创建线程2的时间稍晚于线程1，故通过pthread_mutex_trylock等函数去尝试持有互斥锁1（这里涉及到pthread_mutex_lock，pthread_mutex_trylock实现方式差别，后面会提到），若尝试失败，则通过pthread_mutex_trylock去持有互斥锁2；读写锁和自旋锁同理；

#### 2.1.2 lttng-ust跟踪用户应用事件

由于lttng不能像ebpf一样方便的使用uprobe和uretprobe来跟踪用户态的函数，所以我们要自己定义适合本次测试用例的跟踪点定义文件，并将`lttng_ust_tracepoint`加在测试用例相应的跟踪位置；

我们以mutex互斥锁为例，展示线程触发互斥锁时相关跟踪点的定义，其余锁类似：

- 请求互斥锁时的跟踪点；

```c
TRACEPOINT_EVENT(
lock_monitor,
mutex_lock_start,
TP_ARGS(int, thread_id, void*, lock_ptr, long long unsigned int, time),
TP_FIELDS(
ctf_integer(int, thread_id, thread_id)
ctf_integer_dec(void*, lock_ptr, lock_ptr)
ctf_integer(long long unsigned int, time, time)
)
)
```

- 获取互斥锁成功的跟踪点：

```c
TRACEPOINT_EVENT(
lock_monitor,
mutex_lock_acquired,
TP_ARGS(int, thread_id, void*, lock_ptr, long long unsigned int, time),
TP_FIELDS(
ctf_integer(int, thread_id, thread_id)
ctf_integer_dec(void*, lock_ptr, lock_ptr)
ctf_integer(long long unsigned int, time, time)
)
)
```

- 互斥锁解锁成功的跟踪点：

```c
TRACEPOINT_EVENT(
lock_monitor,
mutex_lock_released,
TP_ARGS(int, thread_id, void*, lock_ptr, long long unsigned int, time),
TP_FIELDS(
ctf_integer(int, thread_id, thread_id)
ctf_integer_dec(void*, lock_ptr, lock_ptr)
ctf_integer(long long unsigned int, time, time)
)
)
```

- 尝试申请互斥锁的跟踪点，对应`pthread_mutex_trylock`函数

```c
TRACEPOINT_EVENT(
lock_monitor,
mutex_trylock_start,
TP_ARGS(int, thread_id, void*, lock_ptr, long long unsigned int, time),
TP_FIELDS(
ctf_integer(int, thread_id, thread_id)
ctf_integer_dec(void*, lock_ptr, lock_ptr)
ctf_integer(long long unsigned int, time, time)
)
)
```

通过以下指令，将跟踪点定义文件生成跟踪点头文件和实现文件：

```shell
lttng-gen-tp lock_tracepoint.tp
```

这将生成 `lock_tracepoint.h` 和 `lock_tracepoint.c` 文件,便可以将我们定义的跟踪点用在测试用例中，以下是一个示例：

```c
#include <lttng/tracepoint.h>
#include "lock_tracepoint.h"
...
void *thread_lock_func1(void *arg) {
...
/*准备开始申请互斥锁*/
tracepoint(lock_monitor, mutex_lock_start, tid,&mutex1,(long long unsigned int)(ts.tv_sec*1000000000+ts.tv_nsec));
pthread_mutex_lock(&mutex1)；
/*锁申请成功*/
tracepoint(lock_monitor, mutex_lock_acquired, tid,&mutex1,(long long unsigned int)(ts.tv_sec*1000000000+ts.tv_nsec));
...
}
```
编译时将我们定义好的lttng跟踪点头文件包含在测试用例中，并进行编译和链接：
```shell
gcc -o test_lock lock_monitor.c lock_tracepoint.c -lpthread -llttng-ust
```

#### 2.1.3 测试脚本:

在通过测试用例对lock_image工具进行逻辑正确性的验证之后,需要验证lock_image工具采集到的数据是否是可靠的;

这里通过一个测试脚本实现lock_image工具和lttng同时监测测试用例的数据，并将数据导出；

```shell
#!/bin/bash

# 获取脚本所在目录的绝对路径
SCRIPT_DIR=$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)

# 指定输出目录
OUTPUT_DIR="$SCRIPT_DIR/lttng-traces/lock_test_$(date +'%Y%m%d_%H:%M:%S')"
CSV_FILE="$OUTPUT_DIR/lock_test_data.csv"
mkdir -p "$SCRIPT_DIR/ebpf/ebpf_output_$(date +'%Y%m%d_%H:%M:%S')"
EBPF_OUTPUT_DIR="$SCRIPT_DIR/ebpf/ebpf_output_$(date +'%Y%m%d_%H:%M:%S')"

# 获取目标进程的 PID
TARGET_PID=$(pidof test_proc_image)

if [ -z "$TARGET_PID" ]; then
echo "目标进程未运行，请先启动目标进程。"
exit 1
fi
echo "测试程序 PID: $TARGET_PID"

# 创建会话并指定输出目录
sudo lttng create xhb_lock --output=$OUTPUT_DIR

# 启用内核事件，仅针对特定 PID
sudo lttng enable-event -u 'lock_monitor:*'

# 添加上下文信息
sudo lttng add-context --kernel --type pid

sudo lttng track --kernel --pid $TARGET_PID

# 运行proc_image监测工具
cd /home/xhb/lmp2/lmp/eBPF_Supermarket/CPU_Subsystem/eBPF_proc_image/
sudo ./proc_image -l > $EBPF_OUTPUT_DIR/lock_output.log &
PROC_IMAGE_PID=$!
sleep 1
sudo ./controller -l -P $TARGET_PID -a
# 启动会话
sudo lttng start
read

sudo lttng stop
sudo lttng view
sudo lttng destroy
echo "追踪数据已保存到 $OUTPUT_DIR 目录中"
# 将 LTTng 跟踪数据转换为文本格式
babeltrace2 $OUTPUT_DIR > $OUTPUT_DIR/trace_data.txt

echo "lttng、eBPF 程序数据收集完毕，请 Ctrl+C 结束"
read
echo "数据已导出到 $CSV_FILE"
```

### 2 .2 结果分析：

通过测试用例和测试脚本，对lock_image工具的逻辑正确性和数据正确性进行了评估，本小节将针对输出的数据进行正确性检测；

#### 1.2.1.逻辑正确性：

通过脚本，可以获取到lock_image监测测试用例进程的全过程；以下是输出的数据：

```
#PID24685绑定CPU4：√
#PID24685 被绑定在以下cpu上: 4
test_proc进程的TGID:24685 PID:24685 CPU_id:4
输入任意数字继续程序的运行:1
程序开始执行...
LOCK_TEST--------------------------------------------------
用户态自旋锁地址:94014792843640
用户态互斥锁地址:94014792843456 , 94014792843520
用户态读写锁地址:94014792843584
线程1 tid:24994 ...
tid :24994 申请互斥锁成功,并将持有1s
线程2 tid:24995 ...
tid :24995 申请互斥锁1失败
tid :24995 尝试申请读写锁2...
tid :24995 申请互斥锁2成功,并将持有1s
tid :24994 互斥锁解锁成功
tid:24994 尝试申请读写锁...
tid :24994 申请读写锁-读锁成功,并将持有1s
tid :24995 互斥锁解锁2成功
tid:24995 尝试申请读写锁...
tid :24995 申请读写锁-写锁失败
tid:24995 尝试申请自旋锁...
tid :24995 申请自旋锁成功,并将持有1s
tid :24994 读写锁-读锁解锁成功
tid:24994 尝试申请自旋锁...
tid :24995 自旋锁解锁成功
tid :24994 申请自旋锁成功,并将持有1s
tid :24994 自旋锁解锁成功
```

**【测试用例逻辑分析】**：我们可以根据测试用例输出的信息，对该进程争用锁的整体画像进行梳理，以此为基准，对照lock_image工具查看其逻辑是否正确；

- 目标锁：【用户态自旋锁: 94014792843640】、【用户态互斥锁1:94014792843456]】,【用户态互斥锁2: 94014792843520】、【用户态读写锁:94014792843584】。
- 目标线程：线程1：24994 ；线程2：24995；
- 主要行为：
- 1.主体进程24685 初始化所有锁；
- 2.线程1被创建后，立即申请【用户态互斥锁1:94014792843456】，并将持有该锁1s；
- 3.线程2被创建后，立即尝试申请【用户态互斥锁1:94014792843456】，由于该锁被线程1持有，线程2申请失败，并尝试申请【用户态互斥锁2: 94014792843520】，申请成功并持有该锁1s；
- 4.线程1持有【用户态互斥锁1:94014792843456】1s后将其释放，解锁成功；
- 5.线程1申请持有【用户态读写锁:94014792843584】，并将持有1s；
- 6.线程2解锁【用户态互斥锁2: 94014792843520】成功；
- 7.线程2尝试持有【用户态读写锁:94014792843584】，由于该锁被线程1持有，线程2申请失败，则放弃申请该锁；
- 8.线程2尝试持有【用户态自旋锁: 94014792843640】，由于该锁未被持有，故线程2申请成功，并将持有1s
- 9.线程1持有【用户态读写锁:94014792843584】1s后解锁成功；
- 10.线程1申请持有【用户态自旋锁: 94014792843640】，由于该锁被线程2持有，故线程1等待该锁被释放后再申请持有；
- 11.线程2持有【用户态自旋锁: 94014792843640】1s并解锁成功；
- 12.线程1申请持有【用户态自旋锁: 94014792843640】并将持有1s；
- 13.线程1解锁【用户态自旋锁: 94014792843640】；

**【lock_image跟踪结果】**

lock_image工具跟踪的是整个进程组的数据，故会有父进程24685关于非指定锁的一些使用情况，这里选择性的删除，仅关注我们提前定义好可以跟踪的锁。

lock_image跟踪到的数据：

```shell
USERLOCK ----------------------------------------------------------
TIME TGID PID LockAddr LockStatus
10139926674250 24685 24685 94014792843640 spinlock_unlock
10139926898189 24685 24994 94014792843456 mutex_req
10139926902097 24685 24994 94014792843456 mutex_lock-0
10140927410524 24685 24995 94014792843456 mutex_req
10140927416075 24685 24995 94014792843456 mutex_lock-16
10140927418850 24685 24995 94014792843520 mutex_req
10140927423449 24685 24995 94014792843520 mutex_lock-0
10140927462995 24685 24994 94014792843456 mutex_unlock
10140927489736 24685 24994 94014792843584 rdlock_req
10140927496720 24685 24994 94014792843584 rdlock_lock-0
10141927546414 24685 24995 94014792843520 mutex_unlock
10141927603794 24685 24995 94014792843584 wrlock_req
10141927610998 24685 24995 94014792843584 wrlock_lock-16
10141927621508 24685 24995 94014792843640 spinlock_req
10141927627018 24685 24995 94014792843640 spinlock_lock-0
10141927646065 24685 24994 94014792843584 rdlock_unlock
10141927658509 24685 24994 94014792843640 spinlock_req
10142927736555 24685 24995 94014792843640 spinlock_unlock
10142927920498 24685 24994 94014792843640 spinlock_lock-0
10143928473997 24685 24994 94014792843640 spinlock_unlock
```

针对lock_image跟踪到的数据，对其进行逻辑行为分析：

- 目标锁：【用户态自旋锁: 94014792843640】、【用户态互斥锁1:94014792843456]】,【用户态互斥锁2: 94014792843520】、【用户态读写锁:94014792843584】。

- 目标线程：线程1：24994 ；线程2：24995

- 行为分析：

- **[时间:10139926674250 ]**：由于`pthread_spin_init()`会调用`pthread_spin_unlock()`故主体进程触发pthread_spin_unlock()被检测到,`spinlock_unlock`;
- **[时间:10139926898189]~[时间:10139926902097 ]**: 线程1发出申请【互斥锁1:94014792843456】请求,并申请成功,`mutex_lock-0`;
- **[时间:10140927410524]~[时间:10140927416075]**: 线程2发出申请【互斥锁1:94014792843456】请求,申请失败,返回值-16,`mutex_lock-16`;
- **[时间:10140927418850]~[时间:10140927423449]**:线程2尝试申请用户态互斥锁2: 94014792843520】,申请成功,`mutex_lock-0`;
- **[时间:10140927462995]**:线程1持有锁1s(10140927462995-10139926902097 =1s)，并解锁成功`mutex_unlock`;
- **[时间:10140927489736]~[时间:10140927496720]**:线程1申请持有【用户态读写锁:94014792843584】，申请成功，`rdlock_lock-0`；
- **[时间:10141927546414]** :线程2持有锁1s （10140927423449-10141927546414=1s）并解锁成功`mutex_unlock`；
- **[时间:10141927603794]~[时间:10141927610998]**:线程2尝试申请【用户态读写锁:94014792843584】写锁，失败，返回值-16,`wrlock_lock-16`;
- **[时间:10141927621508]~[时间:10141927627018]**:线程2尝试申请自旋锁【用户态自旋锁: 94014792843640】，申请成功，`spinlock_lock-0`;
- **[时间:10141927646065 ]**:线程1持有【用户态读写锁:94014792843584】1s(10140927496720-10141927646065=1s),并解锁成功，`rdlock_unlock`;
- **[时间:10141927658509 ]**：线程1尝试申请【用户态自旋锁: 94014792843640】，`spinlock_req`
- **[时间:10142927736555]**：线程2持有【用户态自旋锁: 94014792843640】1s，并释放成功，`spinlock_unlock`;
- **[时间:10142927920498]~[时间:10143928473997]**:线程1持有【用户态自旋锁: 94014792843640】，从发出持有申请到实际持有，共等待了10142927920498-10141927658509 =1.00s，并在持有1s后解锁；

通过将lock_image对进程关于锁的行为分析的逻辑同测试用例的逻辑对比，发现lock_image可以完美的观测到测试用的全部行为，包括一些细微的行为；



#### 2.2.2 数据正确

通过将lock_image获取的数据同lttng作对比，便可得到 进程的整体行为是否正确，数据获取是否正确，描述该行为需要哪些数据进行关联；

由于lttng-ust仅仅是将自定义的跟踪点挂到了测试用例上，而不是像uprobe一样挂载到libc用户态函数中，在时间上会存在一定的误差，从实现原理上讲，我们的lock_image所采集到的时间点更贴近真实时间；

0 comments on commit 4de9fea

Please sign in to comment.