proc_image：提交测试与数据关联文档说明 (#905)

* modify mfutex * add test_mfutex * modify mfutex.bpf.c * 扩充测试与数据关联文档 --------- Co-authored-by: 徐晗博 <[email protected]>
linuxkerneltravel · Sep 14, 2024 · ffba937 · ffba937
1 parent 8282cb3
commit ffba937
Show file tree

Hide file tree

Showing 4 changed files with 341 additions and 0 deletions.
diff --git a/eBPF_Supermarket/CPU_Subsystem/eBPF_proc_image/docs/images/syscall_image数据对比图1.png b/eBPF_Supermarket/CPU_Subsystem/eBPF_proc_image/docs/images/syscall_image数据对比图1.png
diff --git a/eBPF_Supermarket/CPU_Subsystem/eBPF_proc_image/docs/images/syscall_image数据对比图2.png b/eBPF_Supermarket/CPU_Subsystem/eBPF_proc_image/docs/images/syscall_image数据对比图2.png
diff --git a/eBPF_Supermarket/CPU_Subsystem/eBPF_proc_image/docs/images/syscall_image数据对比图3.png b/eBPF_Supermarket/CPU_Subsystem/eBPF_proc_image/docs/images/syscall_image数据对比图3.png
diff --git a/eBPF_Supermarket/CPU_Subsystem/eBPF_proc_image/docs/测试与数据关联.md b/eBPF_Supermarket/CPU_Subsystem/eBPF_proc_image/docs/测试与数据关联.md
@@ -648,3 +648,344 @@ TIME             TGID    PID     LockAddr         LockStatus
 
 由于lttng-ust仅仅是将自定义的跟踪点挂到了测试用例上，而不是像uprobe一样挂载到libc用户态函数中，在时间上会存在一定的误差，从实现原理上讲，我们的lock_image所采集到的时间点更贴近真实时间；
 
+### 2.3 关键数据点的联系：
+
+时间点，进程或线程号，锁的地址，对锁的相关操作的结果这些数据点可以描绘出一个进程的行为：哪个线程在具体的时间点对具体哪个锁进行了什么操作？结果如何？
+
+缺乏功能：线程申请锁失败后，不能找到哪个线程持有该锁；
+
+## 3.schedule_image
+
+为了完成以上三步测试与数据关联工作，需要设计一个测试用例，使用该测试用例可以测试schedule_image工具的逻辑正确性，并通过和lttng工具测试的结果进行对比，判断schedule_image数据正确性；
+
+schedule_image工具关注的是进程被调度时的延迟，具体点就是进程从被唤醒到上cpu这段时间的延迟，为了比较数据的正确性，我们采用lttng，将lttng跟踪点放在`sched_switch`、`sched_wakeup`、`sched_wakeup_new`。
+
+### 3.1 测试用例test_sched
+
+#### 3.1.1 测试用例设计思路:
+
+测试用例主要思路是：创建多个线程去执行CPU密集型任务，查看这些线程在被调度时的延迟情况，与此同时采用sysbench工具产生高负载环境，产生大量调度事件，增加系统整体调度频率。
+
+测试用例主要思路
+
+- 对测试进程进行绑核，绑定在cpu4上；
+- 创建16个线程去执行CPU密集型任务，营造出调度的环境；
+- 线程执行完任务后退出；
+
+在执行测试用例前需要用sysbench创建36个进程执行大量的CPU密集型任务，去提高系统负载，此时再通过`schedule_image()`监测该环境下的线程组的行为。
+
+#### 3.1.2 测试脚本:
+
+在通过测试用例对schedule_image工具进行逻辑正确性的验证之后,需要验证schedule_image工具采集到的数据是否是可靠的;
+
+这里通过一个测试脚本实现schedule_image工具和lttng同时监测测试用例的数据，并将数据导出；
+
+由于lttng输出的结果是详细的单个线程每次发生调度时的数据，为了符合schedule_image的输出结果，设计了python脚本对lttng原始数据进行计算处理；
+
+### 3.2 结果分析：
+
+通过测试用例和测试脚本，对schedule_image工具的逻辑正确性和数据正确性进行了评估，本小节将针对输出的数据进行正确性检测；
+
+#### 3.2.1.逻辑正确性
+
+通过脚本，可以获取到schedule_image监测测试用例进程的在被调度时的延迟情况；由于本次测试仅关注单个进程或线程组的情况，忽略对整个系统当前的调度延迟情况的验证；
+
+下面是测试用例在执行了相关操作后的输出，可以看出测试用例创建了30255~30270共计16个线程来执行cpu密集型任务,在schedule_image的输出中信息中也可以查看到相关线程的调度延迟情况,证明了工具可以监测线程调度延迟;
+
+```
+    #PID29705绑定CPU4：√
+    #PID29705 被绑定在以下cpu上: 4 
+test_proc进程的TGID:29705        PID:29705       CPU_id:4
+输入任意数字继续程序的运行:1
+程序开始执行...
+  #1.PID:30255 TGID:29705
+  #CPU密集型
+
+  #1.PID:30256 TGID:29705
+  #CPU密集型
+
+  #1.PID:30257 TGID:29705
+  #CPU密集型
+
+  #1.PID:30258 TGID:29705
+  #CPU密集型
+
+  #1.PID:30259 TGID:29705
+  #CPU密集型
+
+  #1.PID:30260 TGID:29705
+  #CPU密集型
+
+  #1.PID:30261 TGID:29705
+  #CPU密集型
+
+  #1.PID:30262 TGID:29705
+  #CPU密集型
+
+  #1.PID:30263 TGID:29705
+  #CPU密集型
+
+  #1.PID:30264 TGID:29705
+  #CPU密集型
+
+  #1.PID:30270 TGID:29705
+  #CPU密集型
+
+  #1.PID:30269 TGID:29705
+  #CPU密集型
+
+  #1.PID:30268 TGID:29705
+  #CPU密集型
+
+  #1.PID:30267 TGID:29705
+  #CPU密集型
+
+  #1.PID:30266 TGID:29705
+  #CPU密集型
+
+  #1.PID:30265 TGID:29705
+  #CPU密集型
+    #30263退出
+    #30260退出
+    #30256退出
+    #30269退出
+    #30261退出
+    #30262退出
+    #30255退出
+    #30264退出
+    #30257退出
+    #30270退出
+    #30266退出
+    #30258退出
+    #30259退出
+    #30268退出
+    #30267退出
+```
+
+schedule_image工具监测到的结果:
+
+```
+SCHEDULE ----------------------------------------------------------------------------------------------------------------------
+TIME      TGID    PID     PRIO  | P_AVG_DELAY(ms) S_AVG_DELAY(ms) | P_MAX_DELAY(ms) S_MAX_DELAY(ms) | P_MIN_DELAY(ms) S_MIN_DELAY(ms) |
+21:55:14  29705   30263   120   | 59.439293       4.486027        | 72.030970       4629.971274     | 37.406719       0.000882        |
+21:55:14  29705   30265   120   | 59.277075       4.486027        | 74.783045       4629.971274     | 14.999412       0.000882        |
+21:55:14  29705   30267   120   | 59.200207       4.486027        | 71.837144       4629.971274     | 28.286873       0.000882        |
+21:55:14  29705   29705   120   | 0.004809        4.486027        | 0.004809        4629.971274     | 0.004809        0.000882        |
+21:55:14  29705   30256   120   | 60.343717       4.486027        | 80.016246       4629.971274     | 48.131959       0.000882        |
+21:55:14  29705   30269   120   | 60.828869       4.486027        | 104.015723      4629.971274     | 44.202620       0.000882        |
+21:55:14  29705   30264   120   | 62.809482       4.486027        | 202.431816      4629.971274     | 41.031998       0.000882        |
+21:55:14  29705   30257   120   | 60.246384       4.486027        | 96.055618       4629.971274     | 47.910671       0.000882        |
+21:55:14  29705   30260   120   | 59.768547       4.486027        | 92.002259       4629.971274     | 25.142902       0.000882        |
+21:55:14  29705   30259   120   | 59.845333       4.486027        | 108.348840      4629.971274     | 19.561148       0.000882        |
+21:55:14  29705   30258   120   | 60.156634       4.486027        | 122.003156      4629.971274     | 13.581161       0.000882        |
+21:55:14  29705   30262   120   | 58.650610       4.486027        | 104.011502      4629.971274     | 0.019427        0.000882        |
+21:55:14  29705   30270   120   | 60.002680       4.486027        | 72.012554       4629.971274     | 44.008079       0.000882        |
+21:55:14  29705   30261   120   | 59.596674       4.486027        | 72.089872       4629.971274     | 29.450209       0.000882        |
+21:55:14  29705   30268   120   | 60.397836       4.486027        | 82.019640       4629.971274     | 36.338791       0.000882        |
+21:55:14  29705   30255   120   | 60.714674       4.486027        | 77.784962       4629.971274     | 48.009419       0.000882        |
+21:55:14  29705   30266   120   | 59.679530       4.486027        | 76.011399       4629.971274     | 39.815206       0.000882        |
+
+```
+
+
+
+#### 3.2.2 数据正确性
+
+通过将schedule_image获取的数据同lttng作对比，便可得到  schedule_image工具获取到的调度延迟数据是否正确，同时也验证了schedule_image工具在逻辑上的正确性。以下是schedule_image和lttng获取到的数据进行比对：
+
+在时间【21:55:14】时，schedule_image以及lttng产生了如下数据：
+
+- **线程30259**：
+	- 平均时延
+		- schedule_image：59.845333 ms
+		- lttng：60.044201ms
+		- 二者相差误差在0.198868ms
+	- 最大时延
+		- schedule_image：108.348840 ms
+		- lttng：108.34258ms
+		- 二者相差误差在0.00626ms
+	- 最小时延
+		- schedule_image：19.561148 ms
+		- lttng：19.57056ms
+		- 二者相差误差在0.009412ms
+- **线程3025966**：
+
+- 平均时延
+	- schedule_image：59.679530 ms
+	- lttng：59.530130ms
+	- 二者相差误差在0.1494ms
+- 最大时延
+	- schedule_image：76.011399 ms
+	- lttng：76.00721ms
+	- 二者相差误差在0.004189ms
+- 最小时延
+	- schedule_image：39.815206 ms
+	- lttng：39.82198ms
+	- 二者相差误差在0.006774ms
+- **线程3025969**：
+- 平均时延
+	- schedule_image：60.736575 ms
+	- lttng：60.496016 ms
+	- 二者相差误差在0.2405598ms
+- 最大时延
+	- schedule_image：104.015723 ms
+	- lttng：104.01492  ms
+	- 二者相差误差在0.000803ms
+- 最小时延
+	- schedule_image：44.202620 ms
+	- lttng：44.19760ms
+	- 二者相差误差在0.00502ms
+
+由于数据量过于庞大，仅从中抽取以上三条数据作为对比，两种监测数据之差可以看出，schedule_image采集到的数据和lttng官方工具采集到的数据是完全一致的（误差小于0.01%），故得到结论schedule_image工具的逻辑正确性与数据正确性完全成立；
+
+
+
+### 3.3 关键数据点的关联关系
+
+由于每秒钟产生调度事件十分繁多，schedule_image工具关注于每秒钟线程调度延迟的最大、最小以及平均值。可以将这三个指标作为测评单个进程调度延迟性能的指标，而不关注进程单次调度行为而产生的延迟（这一部分可以通过keytime_image中的上下CPU功能来监测其具体行为）。
+
+schedule_image采集到的这个调度延迟数据指标可以和keytime_image相关联，用于研究当线程发生上cpu行为时，该线程此次调度所等待的时间。
+
+
+
+## 4.syscall_image
+
+syscall_image 是一个用于捕获进程发生系统调用的时工具，他致力于发现系统中每一个线程/进程的系统调用行为，他通过将挂载点放在sys_enter，sys_exit来发现系统中产生的系统调用，并计算没每次系统调用的延迟时间，做到在宏观上对系统中产生系统调用进行分析；
+
+本次测试以及数据关联工作分为三部分：
+
+- syscall_image工具逻辑正确性的测试；
+- syscall_image工具数据正确性的测试；
+- syscall_image工具数据的关联关系，以及原理梳理；
+
+### 4.1 测试用例test_sys
+
+为了完成以上三步测试与数据关联工作，需要设计一个测试用例，使用该测试用例可以测试syscall_image工具的逻辑正确性，并通过和lttng工具测试的结果进行对比，判断syscall_image数据正确性；
+
+syscall_image工具关注的是单个进程发生系统调用时的延迟以及其系统调用序列，为了比较数据的正确性，我们采用lttng，由于lttng没有像sys_enter,sys_exit对应的跟踪点，所以我们将和系统调用有关的全部跟踪点打开，便于捕获所有的系统调用；
+
+#### 4.1.1 测试用例设计思路
+
+测试用例主要思路是：参考 UnixBench 中的 syscall 测试，我们通过syscall(SYS_getpid);来不停地直接调用getpid系统调用，在经过多次调用后，便可以通过查看syscall_image工具监测的结果来验证其正确性。
+
+测试用例主要思路
+
+- 对测试进程进行绑核，绑定在cpu4上；
+- 连续执行10次系统调用`syscall(SYS_getpid);`每执行一次休息1s
+
+```c
+   if(env.syscall_test){
+      printf("SYSCALL_TEST----------------------------------------------\n");
+
+      // 系统调用序列逻辑(参考 UnixBench 中的 syscall 测试)
+      printf("系统调用序列逻辑:\n");
+      printf("每调用一次 SYS_getpid 系统调用睡眠 1 s,循环 10 次\n");
+      int count = 10;
+      while(count){
+         syscall(SYS_getpid);
+         count--;
+         sleep(1);
+      }
+   }
+```
+
+在执行我们指定的系统调用SYS_getpid的同时,一定会伴随着其他系统调用的使用,需要用syscall-image工具对结果进行进一步的分析;
+
+#### 4.1.2 测试脚本:
+
+在通过测试用例对syscall_image工具进行逻辑正确性的验证之后,需要验证syscall_image工具采集到的数据是否是可靠的;
+
+这里通过一个测试脚本实现syscall_image工具和lttng同时监测测试用例的数据，并将数据导出；测试脚本主要完成的工作:
+
+- 再打开测试用例之后,使用syscalll_image和lttng两种放法对其进行数据监测;
+- 将采集到的数据输入进指定的文件中;
+- 为了方便数据分析和结果对比,需要将syscall_image工具拿到的由系统调用号组成的系统调用序列转换为由系统调用名组成的序列;
+- 将lttng采集到的数据进行逻辑计算,计算出每个系统调用的时延并作统计;
+
+### 4.2 结果分析：
+
+通过测试用例和测试脚本，已经将采集到的数据处理结束,接下来就需要对syscall_image工具进行逻辑正确性以及数据正确性的验证;
+
+#### 4.2.1.逻辑正确性
+
+由于syscall_image工具主要检测的是进程所产生的系统调用情况,所以在逻辑上我们需要进行一下对比:
+
+- 测试用例所用到的系统调用,syscall_image工具是否全部监测到;
+- syscall_image工具检测到的系统调用是否和ttng所检测到的一致;
+
+通过脚本，可以获取到syscall_image监测测试用例进程所用到的系统调用,以及lttng所检测到的系统调用序列,由于本次测试仅关注单个进程或线程组的情况，忽略对整个系统当前的系统调用情况的验证；
+
+**【syscall_image 对比 测试用例】**
+
+测试用例会连续10次调用SYS_getpid，每调用完一次就会睡眠1s；
+
+我们可以在syscall_image工具的输出数据中看到如下信息：
+
+![](./images/syscall_image数据对比图1.png)
+
+正好是十次连续的系统调用，证明我们的工具是逻辑正确的；
+
+**【syscall_image 对比 lttng结果】**
+
+lttng监测到的结果:
+
+![](./images/syscall_image数据对比图2.png)
+
+通过lttng以及syscall_image的对比，可以证明我们的syscall_image工具在逻辑上是正确无误的；
+
+其中还有很多细节没有展示，可以在以下几个原始数据中进行对比：
+
+- 
+- 
+
+#### 4.2.2 数据正确性
+
+前面我们已经对syscall-image工具进行了逻辑真确性验证，接下来我们通过对比一些数据来验证数据正确性，这些数据包括：
+
+- 最大系统调用延迟
+- 最小系统调用延迟
+- 平均系统调用延迟；
+- 被调用最多的系统调用;
+
+通过下图我们可以看到lttng采集到的数据中，调用次数最多的前三个系统调用分别是：rt_sigprocmask、close 、 munmap，而这与我们在syscall-image中统计得到的数据一致；
+
+```shell
+SYSCALL ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
+TIME      TGID    PID     1st/num         2nd/num         3nd/num         | P_AVG_DELAY(ns) S_AVG_DELAY(ns) | P_MAX_DELAY(ns) S_MAX_DELAY(ns) | P_MIN_DELAY(ns) S_MIN_DELAY(ns) |  SYSCALLS
+...
+16:08:44  92328   92328   14 /532         3  /131         11 /129         | 12054909        13682568        | 1000994442      10006484305     | 651             281             |  14,14,3,14,14
+```
+
+![](./images/syscall_image数据对比图3.png)
+
+- 最大系统调用延迟：
+	- syscall_image：1000994442ns
+	- lttng：1000996999.999999ns
+	- 差值：2558ns
+- 最小系统调用延迟：
+	- syscall_image：651ns
+	- lttng：1000ns
+	- 差值：349ns
+- 平均系统调用延迟：
+	- syscall_image：11982729ns
+	- lttng：11434793.1428ns
+	- 差值：547935ns
+
+通过以上数据的对比,我们可以得出结论,syscall_image在数据层面是真实可靠的,他与lttng之间存在0.0000255%的误差,是可以忽略的。
+
+详细的原始数据可在这里查看：
+
+- 
+- 
+
+### 4.3 关键数据点的关联关系
+
+由于每秒钟产生系统调用十分繁多，我们可以将其作为分析进程行为非常细粒度的指标，将最大系统调用延迟、最小系统调用延迟以及平均系统调用延迟作为宏观分析指标；
+
+数据关联关系：
+
+- 进程的所有的系统调用信息可以通过以下的数据点进行关联：
+	- 线程号/进程号；系统调用号；系统调用时延；进入系统调用时间点；
+- 系统调用的总体统计数据可以在宏观层面对进程的行为进行指导判断：
+	- 系统调用次数排名；
+	- 最大系统调用延迟、平均系统调用延迟、最小系统调用延迟；