Linux内核实时机制x - 中断响应测试Cyclitest

1 实时性测试工具 rt-test

1.1 源码下载

 1.下载源码： 
~/0-code/5.15$ git clone git://git.kernel.org/pub/scm/utils/rt-tests/rt-tests.git
正克隆到 'rt-tests'...
remote: Enumerating objects: 5534, done.
remote: Counting objects: 100% (7/7), done.
remote: Compressing objects: 100% (7/7), done.
remote: Total 5534 (delta 1), reused 0 (delta 0), pack-reused 5527
接收对象中: 100% (5534/5534), 1.08 MiB | 654.00 KiB/s, 完成.
处理 delta 中: 100% (3569/3569), 完成.

1.2 源码编译

 2. cd rt-tests  && git checkout stable/v1.0
 3. make all && make install 
 4. ./cyclictest -p 90 -m -n -c 0 -t 4 -D5m -b 60 --tracemark

1.3 实测图

2 Cyclitest详解

2.1 中断响应、延时概念：

• 无论系统运行在任何代码路径，当事件发生时，系统响应 该事件的时间即为延时。
• 延时在不同的上下文有不同的含义，而Cyclitest所测得的延时是中断响应延时 和 调度延时，如下图：
  • 中断延时（interrupt latency），即中断发生到进入中断处理程序ISR的延时。
  • 调度延时（scheduing latency），即当前任务被唤醒到任务真正获得CPU使用权中间的延时。
    

2.2 Cyclitest 原理

• 1、首先通过启动一个master的普通进程

• 2、然后matser进程在启动指定数量，指定优先级的实时进程，
  -实时进程会设置一个timer周期性的唤醒自己
  -从timer溢出触发中断并进入ISR调用 wake_up_process唤醒实时进程，到进程真正能被运行，这中间的时间即我们需要测量的延时。

• 3、并通过共享内存将该值传递给master进程进行统计，如此周而复始，最终由master进程将结果输出。

• 当造成延时的事件发生在timer溢出之前，那么这样的延时将不会被捕捉到，所以我们需要足够久的运行cyclitest才能更大概率的抓取全面的延时数据。

master线程逻辑

• 先创建num_threads个指定优先级的实时线程，然后在while循环中读取实时线程放在共享内存中的数据。

	for (i = 0; i < num_threads; i++) {
		pthread_attr_t attr;
		int node;
		struct thread_param *par;
		struct thread_stat *stat;
		par->prio = priority;				//设置线程优先级，由-p参数指定
 
 
		par->clock = clocksources[clocksel];	//由-c 设置
		par->mode = mode;
		par->timermode = timermode;			//默认为static int timermode = TIMER_ABSTIME;，可由-r指定
		//当使用 TIMER_ABSTIME 模式时，定时器的时间值是一个绝对时间点。
		//也就是说，定时器将在指定的确切时间点触发,适用于需要定时器在特定的日期和时间点触发的场景
		
		//当使用 TIMER_RELTIME 模式时，定时器的时间值是一个相对当前时间的偏移量。
		//定时器将在从当前时间开始经过指定的时间间隔后触发。适用于需要定时器在当前时间之后的一段时间内触发的场景
	 
		par->interval = interval;			//默认睡眠时间为DEFAULT_INTERVAL或者 -i 10000 参数指定
		
 
		par->max_cycles = max_cycles;
		par->stats = stat;
		par->node = node;
		par->tnum = i;
		switch (setaffinity) {
		case AFFINITY_UNSPECIFIED: par->cpu = -1; break;
		case AFFINITY_SPECIFIED:
			par->cpu = cpu_for_thread(i, max_cpus);	//设置CPU亲和性
			if (verbose)
				printf("Thread %d using cpu %d.\n", i,
					par->cpu);
			break;
		case AFFINITY_USEALL: par->cpu = i % max_cpus; break;
		}
		stat->min = 1000000;
		stat->max = 0;
		stat->avg = 0.0;
		stat->threadstarted = 1;
		stat->smi_count = 0;
		status = pthread_create(&stat->thread, &attr, timerthread, par);	//创建线程

3 Cyclitest 参数详解

3.1、常用的基本选项

参数	完整参数	用法	作用
-a	–affinity	-a 0,1 表将线程绑定到 CPU 0 和 CPU 1 上运行	通过绑定线程到特定CPU，减少上下文切换开销，提高测试准确性。
-d ：	–distance	-d 500 表示线程之间的唤醒间隔为 500 微秒。	设置线程间的唤醒间隔时间（微秒），控制线程的唤醒频率，影响测试的负载
-D	–duration=TIME、–latency=PM_QOS	-D 10m 表示测试持续 10 分钟。	控制测试的运行时间， 单位 ‘m’ ‘h’ ‘d’ 分钟 小时 天
-F	–fifo	–fifo=path	在指定路径下创建一个管道，用来向它写stats
-i	–interval=INTV	-i 1000 表示线程每隔 1000 微秒唤醒一次	设置线程的唤醒间隔时间（微秒），控制线程的唤醒频率，影响测试的负载。
-l	–loops=LOOPS、–laptop	-l 10000 表示测试运行 10000 次循环。	设置测试的循环次数，控制测试的运行次数，避免无限运行。
-m	–mlockall	-m 表示锁定所有内存	锁定所有内存，防止内存被交换到磁盘，避免内存交换对测试结果的影响，确保测试的准确性
-n	–nanosleep、–notrace	-n 表示使用 clock_nanosleep	使用 clock_nanosleep 进行高精度睡眠，减少系统调用的开销
-p	–priority=PRIO	-p 99 表示设置线程的优先级为 99。	设置线程的调度优先级，影响线程的调度顺序。

3.2、关于timer和时间的选项

3.3、关于输出打印的选项

3.4、tracing相关的选项

• –tracemark：结合-b和ftrace可以抓取和优化实时问题

3.5、参考测试参数

• cyclictest -p 90 -m -n -c 0 -t 4 -D5m -b 60 --tracemark

-p 90: 指定线程优先级为90，
-m: 内存锁定
-n: 使用 clock_nanosleep 进行高精度睡眠
-c: 选择默认时钟类型
-t: 创建4个线程
-D5m: 测试5分钟
-b 60: 最大延时超过60us时，退出
--tracemark：将程序测试获取的超时比较日志打印到ftrace中。

• ./cyclictest -S -p 95 -d 0 -i 1000 -D 48h -m -n

 -S：每个core分配了一个thread
-d 0: 当每个CPU上只有一个线程时，将他设置为0，否则需使用-d 将其唤醒时间隔离开来，累加到interval上，默认为500
-i 1000：设置睡眠唤醒时间interval
-D 48h: 测试48小时 

• ./cyclictest -p 95 -t 16 -d 500 -i 1000 -D 48h -m -a -n

 使用时也可以去掉-S，自己指定threads数量和设置亲和性
 -t 16：创建16个线程
 -d 500: 每个线程间隔500唤醒

3.6、输出参数的使用

• 比较常用的参数有-h和-q

-h  用来输出直方图
-q  用来在测试完成后再打印结果

• Cyclitest 绘制直方图

https://zhuanlan.zhihu.com/p/336381111
https://www.osadl.org/Create-a-latency-plot-from-cyclictest-hi.bash-script-for-latency-plot.0.html

#!/bin/bash

# 1. Run cyclictest   将cyclictest的输出重定向到一个文件
cyclictest -l100000000 -m -Sp90 -i200 -h400 -q >output 

# 2. Get maximum latency	获取最大延迟时间
max=`grep "Max Latencies" output | tr " " "\n" | sort -n | tail -1 | sed s/^0*//`

# 3. Grep data lines, remove empty lines and create a common field separator
grep -v -e "^#" -e "^$" output | tr " " "\t" >histogram 

# 4. Set the number of cores, for example
cores=4

# 5. Create two-column data sets with latency classes and frequency values for each core, for example
for i in `seq 1 $cores`
do
  column=`expr $i + 1`
  cut -f1,$column histogram >histogram$i
done

# 6. Create plot command header
echo -n -e "set title \"Latency plot\"\n\
set terminal png\n\
set xlabel \"Latency (us), max $max us\"\n\
set logscale y\n\
set xrange [0:400]\n\
set yrange [0.8:*]\n\
set ylabel \"Number of latency samples\"\n\
set output \"plot.png\"\n\
plot " >plotcmd

# 7. Append plot command data references
for i in `seq 1 $cores`
do
  if test $i != 1
  then
    echo -n ", " >>plotcmd
  fi
  cpuno=`expr $i - 1`
  if test $cpuno -lt 10
  then
    title=" CPU$cpuno"
   else
    title="CPU$cpuno"
  fi
  echo -n "\"histogram$i\" using 1:2 title \"$title\" with histeps" >>plotcmd
done

# 8. Execute plot command
gnuplot -persist <plotcmd

3.7、追踪参数的使用+ftrace

• traceing的过程中我们通常使用–ftrace，
• 而ftrace的原理是通过在函数入口和出口产生异常，这样得到latency结果包含ftrace的overhead，
• 通常会是几十微秒的数量级，所以在设置-b参数时，我们需要预估一下ftrace带来的overhead。

方式1、接口参数
//当latency大于100时，cyclictest会自动退出，
1、cyclictest -S -p 95 -t -i 1000 -D 1h -m -d 1000 -b 100 --context --event --ftrace -T function_graph
//通过ftrace接口，可以抓取到的context_switch事件。
2、cat /sys/kernel/debug/tracing/trace |grep cyclictest

方式2、trace-cmd
1、trace-cmd reset
2、trace-cmd start -e all;./cyclictest -p 90 -m -n -c 0 -t 4 -D5m -b 60 --tracemark
3、 trace-cmd extract
4、 trace-cmd report -l > log-t9.txt
5、日志：
rcuc/2-30      2d.h34 69432.307127: irq_handler_entry:    irq=2 name=arch_timer
rcuc/2-30      2d.h44 69432.307127: hrtimer_cancel:       hrtimer=0xffffff9ffe293de0
rcuc/2-30      2d.h34 69432.307127: hrtimer_expire_entry: hrtimer=0xffffff9ffe293de0 now=69432656559745 function=hrtimer_wakeup/0x0
  
Line 376096: cyclicte-1768059   2d..20 69432.305162: sched_switch:         cyclictest:1768059 [9] S ==> ksoftirqd/2:31 [120]
Line 376096: cyclicte-1768059   2d..20 69432.305162: sched_switch:         cyclictest:1768059 [9] S ==> ksoftirqd/2:31 [120]
Line 385395:   rcuc/2-30      2d.h54 69432.307127: sched_waking:         comm=cyclictest pid=1768059 prio=9 target_cpu=002
Line 385396:   rcuc/2-30      2d.h54 69432.307127: sched_migrate_task:   comm=cyclictest pid=1768059 prio=9 orig_cpu=2 dest_cpu=0
Line 385398:   rcuc/2-30      2d.h64 69432.307127: sched_wakeup:         cyclictest:1768059 [9] success=1 CPU:000
Line 385591: kylin-as-5018    0d..20 69432.307176: sched_switch:         kylin-assistant:5018 [120] R ==> cyclictest:1768059 [9]

//添加--tracemark则会打印超时日志
cyclicte-1768059   0....0 69432.307210: print:   tracing_mark_write: hit latency threshold (66 > 50)