一、背景
之前的博客 不修改内核镜像的情况下,使用内核模块实现高效监控调度时延-CSDN博客 里,我们讲了不修改内核镜像高效监控每次的调度时延的方法。这篇博客里,我们对于调度时间片也做这么一个不修改内核镜像的改进。关于调度时间片过长的原因及调度时间片的观测可以见之前的博客 调度时间片“过长”的原因及调度时间片的观测_linux调度延迟测量-CSDN博客,对于普通进程也就是cfs进程而言,调度时间片的监控通过sched_stat_runtime就可以办到,但是对于实时进程而言,不修改内核,只通过sched_stat_runtime是无法进行每个单次的观测的,在 调度时间片“过长”的原因及调度时间片的观测_linux调度延迟测量-CSDN博客 博客里的 4.2 一节我们讲了实时线程的时间片监控需要修改的内核代码,而且这还是不够的,我们会在第二章里,先解释为什么这是不够的,并给出可以做的解决办法,然后,我们在第三章里,会给出了不修改内核镜像的方式进行每个单次调度时间片的监控的方法。
在展开后面的内容前,我先要强调一下标题里的“及时”这个要求。如果不需要“及时”的监控,那么在每次sched_switch时,进行任务切换的时间的记录,在下一次任务切换时,统计这次这个线程执行的时间,这样的监控,能在上下文切换时进行判断和上报,但是做不到及时的发现,一般出现异常时要抓的信息往往是开始阶段的信息,等到过长的时间片结束后进行上下文切换了的时候就已经晚了。
当然这种方式肯定有其价值(在第二章里我们也会讲到对于stop调度类的线程无法通过sched_stat_runtime进行检查和上报,所以对于stop调度类的线程我们也得用下面这种实现进行补充监控,而对于其他调度类的线程,我们可以有通过sched_stat_runtime进行更及时的监控),也是比较简单易懂的,关于tracepoint的使用见之前的博客 内核tracepoint的注册回调及添加的方法_tracepoint 自定义回调-CSDN博客:
该有效但不“及时”的监控逻辑的核心代码如下(下面代码设置的时间片超时阈值是20ms):
struct testruntime_percpu_info {
struct timespec64 last_time;
int last_pid;
u64 last_prev_sum_exec_runtime;
u64 timens;
int last_prev_pid;
int last_next_pid;
};
#define TESTRUNTIME_PERCPU_INFO_INIT \
((struct testruntime_percpu_info){ \
.last_time = {0,0}, \
.last_pid = 0, \
.last_prev_sum_exec_runtime = 0, \
})
static DEFINE_PER_CPU(struct testruntime_percpu_info, _runtime_percpu_info) =
TESTRUNTIME_PERCPU_INFO_INIT;
static void cb_sched_switch(void *i_data, bool i_preempt,
struct task_struct *i_prev,
struct task_struct *i_next,
unsigned int i_prev_state)
{
u64 now = local_clock();
struct testruntime_percpu_info *info = this_cpu_ptr(&_runtime_percpu_info);
if (info->timens != 0) {
if (i_prev->pid != 0 && now - info->timens > 20000000ull) {
printk("[cpu%d][in-switch][runtime]pid=%d,comm=%s,policy=%s,runtime=%llu",
smp_processor_id(), i_prev->pid, i_prev->comm,
i_prev->policy == SCHED_NORMAL ? "normal" :
(i_prev->policy == SCHED_FIFO ? "fifo" : (i_prev->policy == SCHED_RR? "rr" : "NA")),
now - info->timens);
}
}
info->timens = now;
info->last_prev_pid = i_prev->pid;
info->last_next_pid = i_next->pid;
}
测试的方法是:
insmod模块以后,运行两个绑核的实时进程:
可以从dmesg里看到能抓到刚运行的deadloop实时进程单次时间片过长:
二、修改内核方式进行单次时间片监控遇到的问题及解决办法
在第一章背景里,我们也说明了,如果不要求及时的发现,那么通过sched_switch也就可以实现了,所以,在这里第二章还包括后面的第三章里要讲的,是基于要"及时"发现调度单次时间片已经很长超过阈值了这个需求而言的监控。
要实时发现异常,那么就不能等到sched_switch时再去做检查判断,所以,用的是sched_stat_runtime里去做检查判断逻辑。
在 调度时间片“过长”的原因及调度时间片的观测_linux调度延迟测量-CSDN博客 里第四章,我们提到了使用task_struct的调度实体se里的prev_sum_exec_runtime变量结合sched_stat_runtime进行cfs程序的调度时间片的及时发现和监控,在 调度时间片“过长”的原因及调度时间片的观测_linux调度延迟测量-CSDN博客 里 4.2 一节里提到了针对实时线程,我们得修改一下内核代码,因为实时线程并没有使用prev_sum_exec_runtime(没有像cfs线程一样在被调度执行时刻把task_struct.se.sum_exec_runtime赋值给prev_sum_exec_runtime),所以,我们得自己去在实时线程被选做下一个调度线程时,进行这样的赋值:
在kernel/sched/rt.c里 set_next_task_rt 函数(具体的修改代码如下截图里的红框):
上面说的这种修改内核代码rt.c里的方式,配合sched_stat_runtime里进行监控,我们先在 2.1 一节里给出sched_stat_runtime里的监控逻辑并对代码进行阐述,而rt.c对应的是rt_sched_class也就是rt调度类,对于其他的调度类的内核的修改部分(但是stop调度类无法做到监控),在 2.1.1 一节里会给出,这样除了stop调度类,其他调度类的线程都可以配合sched_stat_runtime实施及时时间片超时的监控,然后在 2.2 一节里针对一个疑似的问题,增加debug信息进行分析,然后在 2.3 一节里尝试在sched_switch的tracepoint回调里使用调度实体se的prev_sum_exec_runtime和sum_exec_runtime来判断时间片,发现了一个监控的问题,并进行分析,阐述单使用sched_stat_runtime无法监控stop调度类的线程,最后在 2.4 一节里我们针对 2.3 里的问题给出可以采取的解决办法。
2.1 sched_stat_runtime的tracepoint里进行监控的逻辑
核心代码如下:
static inline u32 testruntime_check_time_diff(struct timespec64* i_pts)
{
struct timespec64 currtime;
ktime_get_real_ts64(&currtime);
if (timespec64_to_ns(&currtime) - timespec64_to_ns(i_pts) >
(s64)1000000000ull) {
return 1;
}
return 0;
}
static void cb_sched_stat_runtime(void *i_data, struct task_struct *i_curr,
u64 i_runtime, u64 i_vruntime)
{
u64 runtime;
runtime = i_curr->se.sum_exec_runtime - i_curr->se.prev_sum_exec_runtime;
if (runtime > 4000000ull) {
// we do not need to use get_cpu_var to disable preempt
struct testruntime_percpu_info *info = this_cpu_ptr(&_runtime_percpu_info);
u32 check_time = 0;
if (i_curr->pid != info->last_pid
|| i_curr->se.prev_sum_exec_runtime != info->last_prev_sum_exec_runtime
|| (check_time = testruntime_check_time_diff(&info->last_time))) {
printk("[cpu%d][in-runtime][runtime]pid=%d,last_pid=%d,comm=%s,policy=%s,runtime=%llu,sum=%llu,prev_sum=%llu,last_prev_sum=%llu,check_time[%u],lastswitchinfo[time:%llu,prev:%d,next:%d]",
smp_processor_id(), i_curr->pid, info->last_pid, i_curr->comm,
i_curr->policy == SCHED_NORMAL ? "normal" :
(i_curr->policy == SCHED_FIFO ? "fifo" : (i_curr->policy == SCHED_RR? "rr" : "NA")),
runtime, i_curr->se.sum_exec_runtime, i_curr->se.prev_sum_exec_runtime, info->last_prev_sum_exec_runtime, check_time,
info->timens, info->last_prev_pid, info->last_next_pid);
info->last_pid = i_curr->pid;
ktime_get_real_ts64(&info->last_time);
info->last_prev_sum_exec_runtime = i_curr->se.prev_sum_exec_runtime;
}
}
}
上面的代码做如下的说明:
1)在一次调度时间片超时的事件打印出来以后,我们会把已经上报的这一次事件的task_struct的pid和se.prev_sum_exec_runtime都记下来,存在per-cpu变量里,这样为了防止短时间内的再次打印输出上报,防止相同事件重复多次上报,所以,需要记录这次上报的时间,通过testruntime_check_time_diff函数来检查是否一样的事件短事件内已经上报一次了
2)为了防止重复多次上报,为什么除了pid要记下来,还要记se.prev_sum_exec_runtime下来呢?这是因为光去判断pid是不够的,因为走到这个超过阈值的逻辑里来的时候,因为是先判断的runtime > 4000000ull的条件,也就是阈值超时的检查逻辑,这一次是pid A,下一次再进入这个阈值超时检查逻辑是true,走到if逻辑里的时候,可能已经进行了多次上下文切换。所以,我们需要增加se.prev_sum_exec_runtime这个数值,因为这个数值是单调递增的,每切换一次上下文,它就会把表示线程的总运行时间se.sum_exec_runtime给赋值给se.prev_sum_exec_runtime,所以不同的调度时间片,它的se.prev_sum_exec_runtime是不一样的
但是要注意,上面这个逻辑是依赖se.prev_sum_exec_runtime的,cfs调度类,内核里是有这个变量的维护,rt调度类,我们在 第二章开始时讲了改发,补充了这个变量的维护,但是对于其他3个调度类,如 deadline/stop/idle,我们还得去加,当然idle我们不用加,那么deadline和stop呢,stop调度类,我们需要增加维护这个se.prev_sum_exec_runtime变量的逻辑。增加方法,我们在 2.1.1 里说明。
下面的截图,我们可以看到它是可以成功抓到调度时间片超时事件的(下图是普通cfs线程的超时事件):
2.1.1 与sched_stat_runtime监控逻辑相关的prev_sum_exec_runtime数值的几个调度类的内核修改
对于rt调度调度类的线程而言,如下图也是可以抓到的(对应的内核改法在第二章开头已经给出):
如下图右边红色框出的,起两个10核上的rt线程,就可以从dmesg里看到能抓到rt线程调度时间片超时的事件(如下面左图红色框出部分):
对于cfs和rt以外的其他调度类,idle调度类用于cpu空闲时,肯定不需要去监控和做prev_sum_exec_runtime的管理,stop调度类会在下面 2.3 一节里讲,所以就剩一个deadline调度类。
对于deadline调度类,如果我们不像rt调度类那样,把prev_sum_exec_runtime的值给管理起来,那么就会从下图看到打印出来的prev_sum_exec_runtime(即下图的prev_sum这个数值)是0或者其他值,并不是我们要的单次调度时间片开始时的sum_exec_runtime值:
上图是先insmod我们的监控驱动后,启动一个deadline调度类的线程,然后通过dmesg -w | grep deadline过滤dmesg得到的。
关于deadline线程的例程如下代码:
#include <stdio.h>
#include <stdlib.h>
#include <pthread.h>
#include <sched.h>
#include <unistd.h>
#include <time.h>
#include <string.h>
#include <linux/sched.h> // 包含 sched_attr 结构定义
#include <sys/syscall.h> // 包含 syscall 函数
struct sched_attr {
__u32 size;
__u32 sched_policy;
__u64 sched_flags;
/* SCHED_NORMAL, SCHED_BATCH */
__s32 sched_nice;
/* SCHED_FIFO, SCHED_RR */
__u32 sched_priority;
/* SCHED_DEADLINE */
__u64 sched_runtime;
__u64 sched_deadline;
__u64 sched_period;
/* Utilization hints */
__u32 sched_util_min;
__u32 sched_util_max;
};
void *task(void *arg) {
struct sched_attr attr;
pid_t pid = 0;
// 设置调度属性
memset(&attr, 0, sizeof(attr));
attr.size = sizeof(attr);
attr.sched_policy = SCHED_DEADLINE;
// 设置实时任务的参数
attr.sched_runtime = 100000000; // 100ms
attr.sched_period = 200000000; // 200ms
attr.sched_deadline = 150000000; // 150ms
// 设置线程的调度属性
long result = syscall(SYS_sched_setattr, pid, &attr, 0);
if (result != 0) {
perror("Failed to set scheduling attributes");
return EXIT_FAILURE;
}
while (1) {
// 模拟任务工作
//printf("Task is running...\n");
//nanosleep(&req, NULL); // 让出 CPU 控制权,避免占用过高的 CPU
}
return NULL;
}
int main() {
pthread_t thread;
// 创建线程
if (pthread_create(&thread, NULL, task, NULL) != 0) {
perror("Failed to create thread");
return EXIT_FAILURE;
}
// 等待线程结束
pthread_join(thread, NULL);
return EXIT_SUCCESS;
}
要注意,启动起来以后,如果通过top不带参数来看,看不到进程里的主线程以外的优先级,如下图左边框框只显示主线程的优先级:
这时候,需要top -H -p <pid>来看一个进程里各个线程的优先级:
回到刚才发现的deadline调度类的prev_sum_exec_runtime的值和预期不一致的问题,我们需要像rt调度类一样,做如下改动(kernel/sched/deadline.c里):
修改过后,我们可以如下图看到,打出来的prev_sum_exec_runtime值就是符合预期的:
2.2 一个疑似的监控问题及增加debug信息进行分析
这一节一方面是排除一个疑似的问题,另外一方面是通过分析该问题从而对内核调度系统的调度流程能有更细的认知。
在抓取的过程中发现,下图中policy=normal也就是cfs的任务线程,疑似的同一个时间片里多次上报的情况,且看到prev_sum也就是task_struct.se.prev_sum_exec_runtime的数值疑似在单次时间片里多次变化,这个和之前分析的cfs线程里的prev_sum_exec_runtime的数值的逻辑不一致:
所以,为了确认是否是同一个调度时间片,我们需要在sched_switch里做一个记录,分cpu记录这个per_cpu的上一次任务切换的信息,给抓到的时间片超过阈值事件同时打印该上下文切换的信息,来辅助分析。
这部分的核心代码如下:
struct testruntime_percpu_info {
struct timespec64 last_time;
int last_pid;
u64 last_prev_sum_exec_runtime;
u64 timens;
int last_prev_pid;
int last_next_pid;
};
#define TESTRUNTIME_PERCPU_INFO_INIT \
((struct testruntime_percpu_info){ \
.last_time = {0,0}, \
.last_pid = 0, \
.last_prev_sum_exec_runtime = 0, \
})
static DEFINE_PER_CPU(struct testruntime_percpu_info, _runtime_percpu_info) =
TESTRUNTIME_PERCPU_INFO_INIT;
static void cb_sched_switch(void *i_data, bool i_preempt,
struct task_struct *i_prev,
struct task_struct *i_next,
unsigned int i_prev_state)
{
u64 now = local_clock();
struct testruntime_percpu_info *info = this_cpu_ptr(&_runtime_percpu_info);
info->timens = now;
info->last_prev_pid = i_prev->pid;
info->last_next_pid = i_next->pid;
}
static inline u32 testruntime_check_time_diff(struct timespec64* i_pts)
{
struct timespec64 currtime;
ktime_get_real_ts64(&currtime);
if (timespec64_to_ns(&currtime) - timespec64_to_ns(i_pts) >
(s64)1000000000ull) {
return 1;
}
return 0;
}
static void cb_sched_stat_runtime(void *i_data, struct task_struct *i_curr,
u64 i_runtime, u64 i_vruntime)
{
u64 runtime;
runtime = i_curr->se.sum_exec_runtime - i_curr->se.prev_sum_exec_runtime;
if (runtime > 4000000ull) {
// we do not need to use get_cpu_var to disable preempt
struct testruntime_percpu_info *info = this_cpu_ptr(&_runtime_percpu_info);
u32 check_time = 0;
if (i_curr->pid != info->last_pid
|| i_curr->se.prev_sum_exec_runtime != info->last_prev_sum_exec_runtime
|| (check_time = testruntime_check_time_diff(&info->last_time))) {
printk("[cpu%d][in-runtime][runtime]pid=%d,last_pid=%d,comm=%s,policy=%s,runtime=%llu,sum=%llu,prev_sum=%llu,last_prev_sum=%llu,check_time[%u],lastswitchinfo[time:%llu,prev:%d,next:%d]",
smp_processor_id(), i_curr->pid, info->last_pid, i_curr->comm,
i_curr->policy == SCHED_NORMAL ? "normal" :
(i_curr->policy == SCHED_FIFO ? "fifo" : (i_curr->policy == SCHED_RR? "rr" : "NA")),
runtime, i_curr->se.sum_exec_runtime, i_curr->se.prev_sum_exec_runtime, info->last_prev_sum_exec_runtime, check_time,
info->timens, info->last_prev_pid, info->last_next_pid);
info->last_pid = i_curr->pid;
ktime_get_real_ts64(&info->last_time);
info->last_prev_sum_exec_runtime = i_curr->se.prev_sum_exec_runtime;
}
}
}
上面代码展示的大致意思就是在sched_switch时per-cpu方式记录下来切换的时间和切换的prev和next的pid:
在sched_stat_runtime时,在printk打印出调度时间超时的事件时也同时打印当前cpu上上一次的任务切换发生的时间和切换的prev和next的pid:
如此打印就可以发现之前发现的疑似是单个时间片内重复上报多次超时事件的现象,根据switch的信息,说明了这疑似重复上报的期间,任务切换一值在发生,只是由于切换到的别的线程再马上切换回来这个过程发生得非常快,频次很高,所以才有这个多次上报的错觉。如下图右边框框里的上下文切换时间是一值在变的。
每一次上下文切换,就会产生一个新的pcount的timeslice,关于pcount可以参考之前的博客 调度时延的观测_schedstat单位-CSDN博客 里的第四章。
2.3 单使用sched_stat_runtime无法监控stop调度类的线程
我们在通过sched_switch调度点里打印切换的信息时,把prev的prev_sum_exec_runtime打印出来时会发现,如下图migration线程(stop调度类,至于migration线程为什么是stop调度类,以后的博客里在讲调度负载均衡逻辑里会讲到)的prev_sum_exec_runtime的值也是不对的:
要注意,内核并没有给stop调度类的task_struct的policy变量里做区分,用的还是fifo,如上图,但是可以从task_struct的rt_priority来得到是stop调度类:
有同学可能会说,deadline调度类会不会rt_priority也是99,实时证明不是:
但是有问题是,如果你通过chrt -f 99来运行一个程序,得到的policy和rt_priority和调度类的情况是一样的:
所以,要真正完全确定的进行区分是stop调度类,可以参考 2.4.3 里讲的方法,在内核模块里先获取到stop_sched_class的指针地址,再进行比较,具体参考 2.4.3 里讲的方法。
回到这一节的主题里,我们先按照改rt的prev_sum_exec_runtime的一样的改发,先把stop调度类的prev_sum_exec_runtime也改成符合预期,改发如下(kernel/sched/stop_task.c),增加如下红框内容:
可以看到,修改过后,sched_switch时抓到的migration线程的prev_sum_exec_runtime值就符合预期了:
而毕竟sched_switch抓调度时间片超时的事件是比较置后的,但是发现进入sched_stat_runtime里并没有出现过stop调度类的线程。
2.3.1 尝试通过kprobe在update_curr_stop函数调用前打桩,发现从来不会走到
stop调度类的.update_curr实现是update_curr_stop函数:
先尝试通过kprobe进行update_curr_stop函数的调用前打桩。
使用kprobe进行打桩的核心代码:
struct kprobe _kp;
int kprobecb_update_curr_stop(struct kprobe* i_k, struct pt_regs* i_p)
{
printk("update_curr_stop enter");
return 0;
}
int kprobe_register_func_update_curr_stop(void)
{
int ret;
memset(&_kp, 0, sizeof(_kp));
_kp.symbol_name = "update_curr_stop";
_kp.pre_handler = kprobecb_update_curr_stop;
ret = register_kprobe(&_kp);
if (ret < 0) {
printk("register_kprobe fail!\n");
return -1;
}
return 0;
}
void kprobe_unregister_func_update_curr_stop(void)
{
unregister_kprobe(&_kp);
}
注册kprobe是成功的,但是并没有发现进入过:
而换成update_curr_fair就能进入:
然后,直接修改内核镜像里的update_curr_stop函数,直接增加printk打印(原来的update_curr_stop函数里是空的,如下图,增加了打印):
仍然在dmesg里并没有打印输出:
所以能确定这个stop调度类的.update_curr的实现update_curr_stop并不会走到:
而从理论上来分析,stop调度类是最最高优先级的调度类,所以stop调度类的任务不能被其他任何线程所抢占,所以也自然不需要进行.update_curr的处理(去更新线程执行时间等状态),因为在非上下文切换时去更新线程执行时间等状态的目的就是为了检查抢占(检查是否有更需要执行的线程需要抢占当前的执行线程)。
2.4 针对 2.3 的问题,可以采取的解决办法
2.3 的问题的其实就是stop调度类无法及时捕获调度时间片超时事件,针对 2.3 的问题,我们还是有“及时”捕获超时的解决办法的。
2.4.1 先通过sched_stat_runtime未及时“喂狗”来发现异常情况
既然stop调度类的线程走不到update_curr,那么我们就找别的办法来监控,所以stop调度类的时间片的超时监控就放到sched_switch里来滞后的监测,毕竟stop调度类一般所运行的逻辑也是内核里的基本上固化的逻辑,出问题的可能性比较小,另外,就算出问题,我们也可以通过别的监控,来辅助,因为stop调度类里走不到sched_stat_runtime函数,在之前的博客 硬中断关闭后的堆栈抓取方法_nmi ipi panic-CSDN博客 里 3.2.1 一节,我们就使用了sched_stat_runtime来进行喂狗逻辑,确定核的调度相关的情况正常,这样也就弥补了该stop调度类走不到sched_stat_runtime的监控盲区,因为某核上sched_stat_runtime走不进去,也就没有及时喂狗,也就如 硬中断关闭后的堆栈抓取方法_nmi ipi panic-CSDN博客 里第三章的方案实现里,可以去触发nmi的ipi中断到未喂狗的cpu上,进行未喂狗的cpu上的上下文环境检查,也就能拿到任务线程,来判断任务线程是否是stop调度类。
2.4.2 在发送到目标问题核上执行的nmi ipi的回调函数里
关于详细的喂狗逻辑及发送nmi ipi等细节,参考之前的 硬中断关闭后的堆栈抓取方法_nmi ipi panic-CSDN博客 博客。
这里讲在nmi ipi的目标核上的回调函数里如果要判断当前线程是否是stop调度类,要如何实现?
在内核里,可以通过task_struct里的sched_class指针是否是stop_sched_class的地址来判断任务的调度类是否是stop调度类,关于调度类等基础的介绍包括cfs的介绍,在之前的博客 CFS及RT调度整体介绍_cfs任务和rt任务-CSDN博客 里有。
由于stop_sched_class并不是一个export symbol,所以,在模块里无法直接引用。下面我们讲在模块里如何引出这个stop_sched_class的地址。
2.4.3 内核模块里获取stop_sched_class的地址的方法
在之前的博客
获取任意一个进程的共享内存的fd对应的资源,增加引用,实现数据的接管——包含非export的内核函数的模块内使用-CSDN博客
里 3.1 一节,讲到了通过kprobe来通过函数符号获取一个内核函数地址的办法,可以先这样获取kallsyms_lookup_name的函数地址,再通过该函数获取stop_sched_class的地址,核心代码如下:
void* _stop_sched_class = NULL;
typedef unsigned long (*kallsyms_lookup_name_func)(const char *name);
kallsyms_lookup_name_func _kallsyms_lookup_name_func;
void* get_func_by_symbol_name_kallsyms_lookup_name(void)
{
int ret;
void* pfunc = NULL;
struct kprobe kp;
memset(&kp, 0, sizeof(kp));
kp.symbol_name = "kallsyms_lookup_name";
kp.pre_handler = NULL;
kp.addr = NULL; // 作为强调,提示使用symbol_name
ret = register_kprobe(&kp);
if (ret < 0) {
printk("register_kprobe fail!\n");
return NULL;
}
printk("register_kprobe succeed!\n");
pfunc = (void*)kp.addr;
unregister_kprobe(&kp);
return pfunc;
}
static void cb_sched_switch(void *i_data, bool i_preempt,
struct task_struct *i_prev,
struct task_struct *i_next,
unsigned int i_prev_state)
{
u64 now = local_clock();
struct testruntime_percpu_info *info = this_cpu_ptr(&_runtime_percpu_info);
if (i_prev->sched_class == _stop_sched_class) {
printk("stop class %d %s", i_prev->pid, i_prev->comm);
}
}
static int __init testruntime_init(void)
{
...
_kallsyms_lookup_name_func = get_func_by_symbol_name_kallsyms_lookup_name();
_stop_sched_class = (void*)_kallsyms_lookup_name_func("stop_sched_class");
}
如下图,运行后,在cb_sched_switch里可以成功判断出是stop调度类:
三、不修改内核镜像使用内核模块进行“及时”的单次调度时间片的监控
在这一章里,我们去掉内核镜像里的改动,只使用sched_stat_runtime和sched_switch两个调度点进行监控逻辑的编写。其实想到没想到只是一念之差,实现起来并不复杂。但是要注意,这一章讲的方法并不解决 2.3 里讲的stop调度类线程无法通过sched_stat_runtime及时监控的问题,该问题是要通过 2.4 里讲的方法来解决的,这里第三章只是针对其他场景,也就是非stop调度类的情况,可以去掉内核镜像里的改动,使用内核模块来实现“及时”的监控,而对于stop调度类线程的调度时间片超时事件的“及时”监控,这一章里并没有具体去实现,关于 2.4 里说的方法如何具体实现,可以参考 硬中断关闭后的堆栈抓取方法_nmi ipi panic-CSDN博客 里 第三章 说的去实现。
3.1 实现原理及运行情况
3.1.1 实现原理
在第二章里讲到的内核部分的改动是在调用各个调度类的ops里的.set_next_task的实现里,参考cfs的.set_next_task的实现,进行sum_exec_runtime向prev_sum_exec_runtime的赋值,来记录下一个任务执行前的当前的总运行时间,从而可以在sched_stat_runtime时里做总运行时间和记录下来的调度时间片开始时的总运行时间之间算差值来得到这一次的调度时间片已经运行的时间。
而我们其实可以在监控模块里在sched_switch的tracepoint里去记录开始时间,在sched_stat_runtime里去减去在sched_switch的tracepoint里记录的开始时间来算当前这次调度时间片的时间。但是这里面是要注意一下,sched_stat_runtime并不一定是当前cpu上执行的线程,要做一个检查判断。
在这一章的代码里实现的方式,并没有采取这样的自己去获取开始时间的方式,而是还是借用了task_struct.se.sum_exec_runtime和task_struct.se.prev_sum_exec_runtime两个数值,只是在sched_switch时把第二章里在内核镜像里做的赋值动作改放在sched_switch的tracepoint里来做,也就是放在内核模块里来做,这样的方式来实现,相比刚才说的自己去记录开始时间和减出当前调度时间片的时间的做法相比,有两个方面的考虑:
1)各个调度类有这个准确的prev_sum_exec_runtime值可以未来再去做一些细颗粒度的功能开发和拓展,而你记录到监控模块的per-cpu变量里,有解耦的好处,但是在功能拓展上并不是很方便,因为prev_sum_exec_runtime在设计上它应该就是能表示单次调度时间片开始时的线程总运行时间。
2)sum_exec_runtime统计时间用的是rq_clock_task接口,而这个接口在之前的博客 与调度相关的内核时间接口的分析及实现介绍-CSDN博客 里的 3.7 一节里,也讲解过,它在打开CONFIG_IRQ_TIME_ACCOUNTING时,它是会去掉irq里的运行时间的,而自己去记录的开始时间和结束时间做差值时是没有扣除irq的时间的,要扣除irq时间你还得去另外去注册tracepoint加逻辑去统计
下面 3.2 里有完整的代码,这里先把核心代码贴出来说明一下。
下面截图里红色框框部分是刚才说的sum_exec_runtime向prev_sum_exec_runtime的赋值:
下面截图里红色框框部分是为了防止sched_stat_runtime“及时”上报方式时重复多次上报同一个时间片的debounce逻辑:
对应的sched_stat_runtime的debounce逻辑:
sched_stat_runtime里的计算当前调度时间片的时长逻辑:
3.1.2 运行情况
如下抓取到调度时间片超时事件的情况:
对于fair调度类:
对于rt调度类:
(下截图右边执行两个rt任务到核10上,下截图左边可以抓到超时事件,其实执行一个rt任务就可以抓到了,执行两个绑核的任务会让触发超时事件非常多)
对于deadline调度类:
对于stop调度类在sched_switch时会进行捕获,临时修改阈值到100ull来触发migration线程这个stop调度类的阈值超时事件看是否能抓取,如下图是可以抓取的:
3.2 完整的代码
#include <linux/module.h>
#include <linux/capability.h>
#include <linux/sched.h>
#include <linux/uaccess.h>
#include <linux/proc_fs.h>
#include <linux/ctype.h>
#include <linux/seq_file.h>
#include <linux/poll.h>
#include <linux/types.h>
#include <linux/ioctl.h>
#include <linux/errno.h>
#include <linux/stddef.h>
#include <linux/lockdep.h>
#include <linux/kthread.h>
#include <linux/sched.h>
#include <linux/delay.h>
#include <linux/wait.h>
#include <linux/init.h>
#include <asm/atomic.h>
#include <trace/events/workqueue.h>
#include <linux/sched/clock.h>
#include <linux/string.h>
#include <linux/mm.h>
#include <linux/interrupt.h>
#include <linux/tracepoint.h>
#include <trace/events/osmonitor.h>
#include <trace/events/sched.h>
#include <trace/events/irq.h>
#include <trace/events/kmem.h>
#include <linux/ptrace.h>
#include <linux/uaccess.h>
#include <asm/processor.h>
#include <linux/sched/task_stack.h>
#include <linux/nmi.h>
#include <asm/apic.h>
#include <linux/version.h>
#include <linux/sched/mm.h>
#include <asm/irq_regs.h>
#include <linux/kallsyms.h>
#include <linux/kprobes.h>
MODULE_LICENSE("GPL");
MODULE_AUTHOR("zhaoxin");
MODULE_DESCRIPTION("Module for debug runtime.");
MODULE_VERSION("1.0");
struct kern_tracepoint {
void *callback;
struct tracepoint *ptr;
bool bregister;
};
static void clear_kern_tracepoint(struct kern_tracepoint *tp)
{
if (tp->bregister) {
tracepoint_probe_unregister(tp->ptr, tp->callback, NULL);
}
}
#define INIT_KERN_TRACEPOINT(tracepoint_name) \
static struct kern_tracepoint mykern_##tracepoint_name = {.callback = NULL, .ptr = NULL, .bregister = false};
#define TRACEPOINT_CHECK_AND_SET(tracepoint_name) \
static void tracepoint_name##_tracepoint_check_and_set(struct tracepoint *tp, void *priv) \
{ \
if (!strcmp(#tracepoint_name, tp->name)) \
{ \
((struct kern_tracepoint *)priv)->ptr = tp; \
return; \
} \
}
INIT_KERN_TRACEPOINT(sched_switch)
TRACEPOINT_CHECK_AND_SET(sched_switch)
INIT_KERN_TRACEPOINT(sched_stat_runtime)
TRACEPOINT_CHECK_AND_SET(sched_stat_runtime)
struct testruntime_percpu_info {
struct timespec64 last_time;
int last_pid;
u64 last_prev_sum_exec_runtime;
u64 timens;
int last_prev_pid;
int last_next_pid;
};
#define TESTRUNTIME_PERCPU_INFO_INIT \
((struct testruntime_percpu_info){ \
.last_time = {0,0}, \
.last_pid = 0, \
.last_prev_sum_exec_runtime = 0, \
})
static DEFINE_PER_CPU(struct testruntime_percpu_info, _runtime_percpu_info) =
TESTRUNTIME_PERCPU_INFO_INIT;
void* _stop_sched_class = NULL;
static void cb_sched_switch(void *i_data, bool i_preempt,
struct task_struct *i_prev,
struct task_struct *i_next,
unsigned int i_prev_state)
{
u64 now = local_clock();
struct testruntime_percpu_info *info = this_cpu_ptr(&_runtime_percpu_info);
i_next->se.prev_sum_exec_runtime = i_next->se.sum_exec_runtime;
if (i_prev->se.sum_exec_runtime - i_prev->se.prev_sum_exec_runtime > 4000000ull)
{
printk("[cpu%d][in-switch][runtime]pid=%d,comm=%s,policy=%s,rt_prio=%u,runtime=%llu,sum=%llu,prev_sum=%llu",
smp_processor_id(), i_prev->pid, i_prev->comm,
i_prev->policy == SCHED_NORMAL ? "normal" :
(i_prev->policy == SCHED_FIFO ? "fifo" : (i_prev->policy == SCHED_RR? "rr" :
(i_prev->policy == SCHED_DEADLINE ? "deadline" :
(i_prev->policy == SCHED_IDLE ? "idle" : "NA")))), i_prev->rt_priority,
now - info->timens, i_prev->se.sum_exec_runtime, i_prev->se.prev_sum_exec_runtime);
}
info->timens = now;
info->last_prev_pid = i_prev->pid;
info->last_next_pid = i_next->pid;
}
typedef unsigned long (*kallsyms_lookup_name_func)(const char *name);
kallsyms_lookup_name_func _kallsyms_lookup_name_func;
void* get_func_by_symbol_name_kallsyms_lookup_name(void)
{
int ret;
void* pfunc = NULL;
struct kprobe kp;
memset(&kp, 0, sizeof(kp));
kp.symbol_name = "kallsyms_lookup_name";
kp.pre_handler = NULL;
kp.addr = NULL; // 作为强调,提示使用symbol_name
ret = register_kprobe(&kp);
if (ret < 0) {
printk("register_kprobe fail!\n");
return NULL;
}
printk("register_kprobe succeed!\n");
pfunc = (void*)kp.addr;
unregister_kprobe(&kp);
return pfunc;
}
static inline u32 testruntime_check_time_diff(struct timespec64* i_pts)
{
struct timespec64 currtime;
ktime_get_real_ts64(&currtime);
if (timespec64_to_ns(&currtime) - timespec64_to_ns(i_pts) >
(s64)1000000000ull) {
return 1;
}
return 0;
}
static void cb_sched_stat_runtime(void *i_data, struct task_struct *i_curr,
u64 i_runtime, u64 i_vruntime)
{
u64 runtime;
runtime = i_curr->se.sum_exec_runtime - i_curr->se.prev_sum_exec_runtime;
if (runtime > 4000000ull) {
// we do not need to use get_cpu_var to disable preempt
struct testruntime_percpu_info *info = this_cpu_ptr(&_runtime_percpu_info);
u32 check_time = 0;
if (i_curr->pid != info->last_pid
|| i_curr->se.prev_sum_exec_runtime != info->last_prev_sum_exec_runtime
|| (check_time = testruntime_check_time_diff(&info->last_time))) {
printk("[cpu%d][in-runtime][runtime]pid=%d,last_pid=%d,comm=%s,policy=%s,runtime=%llu,sum=%llu,prev_sum=%llu,last_prev_sum=%llu,check_time[%u],lastswitchinfo[time:%llu,prev:%d,next:%d]",
smp_processor_id(), i_curr->pid, info->last_pid, i_curr->comm,
i_curr->policy == SCHED_NORMAL ? "normal" :
(i_curr->policy == SCHED_FIFO ? "fifo" : (i_curr->policy == SCHED_RR? "rr" :
(i_curr->policy == SCHED_DEADLINE ? "deadline" :
(i_curr->policy == SCHED_IDLE ? "idle" : "NA")))),
runtime, i_curr->se.sum_exec_runtime, i_curr->se.prev_sum_exec_runtime, info->last_prev_sum_exec_runtime, check_time,
info->timens, info->last_prev_pid, info->last_next_pid);
info->last_pid = i_curr->pid;
ktime_get_real_ts64(&info->last_time);
info->last_prev_sum_exec_runtime = i_curr->se.prev_sum_exec_runtime;
}
}
}
static int __init testruntime_init(void)
{
mykern_sched_switch.callback = cb_sched_switch;
for_each_kernel_tracepoint(sched_switch_tracepoint_check_and_set, &mykern_sched_switch);
if (!mykern_sched_switch.ptr) {
printk(KERN_ERR "mykern_sched_switch register failed!\n");
return -1;
}
else {
printk(KERN_INFO "mykern_sched_switch register succeeded!\n");
}
tracepoint_probe_register(mykern_sched_switch.ptr, mykern_sched_switch.callback, NULL);
mykern_sched_switch.bregister = 1;
mykern_sched_stat_runtime.callback = cb_sched_stat_runtime;
for_each_kernel_tracepoint(sched_stat_runtime_tracepoint_check_and_set, &mykern_sched_stat_runtime);
if (!mykern_sched_stat_runtime.ptr) {
printk(KERN_ERR "mykern_sched_stat_runtime register failed!\n");
return 0;
}
else {
printk(KERN_INFO "mykern_sched_stat_runtime register succeeded!\n");
}
tracepoint_probe_register(mykern_sched_stat_runtime.ptr, mykern_sched_stat_runtime.callback, NULL);
mykern_sched_stat_runtime.bregister = 1;
_kallsyms_lookup_name_func = get_func_by_symbol_name_kallsyms_lookup_name();
_stop_sched_class = (void*)_kallsyms_lookup_name_func("stop_sched_class");
return 0;
}
static void __exit testruntime_exit(void)
{
clear_kern_tracepoint(&mykern_sched_switch);
clear_kern_tracepoint(&mykern_sched_stat_runtime);
tracepoint_synchronize_unregister();
}
module_init(testruntime_init);
module_exit(testruntime_exit);