调度器37—关中断/关抢占DebugQcom Hello

基于Qcom-Linux-5.10

一、背景

1. 音频卡音，从trace上看有较多音频相关RT线程runnable 5-20ms。怀疑关抢占或关中断(perfetto trace上看不到irqs信息)导致的调度延迟。

二、Trace原理

追踪关中断、关抢占的trace hook 主要在 kernel/trace/trace_preemptirq.c 中，Google 在里面预留了用于 debug 的 Hook, 我们将代码插入进去即可。

1. 关中断Hook —— trace_android_rvh_irqs_disable

(1) 调用路径

enter_from_user_mode //kernel/entry/common.c
    irqentry_enter //kernel/entry/common.c
    irqentry_nmi_enter //kernel/entry/common.c
        trace_hardirqs_off_finish //trace_preemptirq.c 需要使能 CONFIG_TRACE_IRQFLAGS，否则是个空函数
            trace_android_rvh_irqs_disable(CALLER_ADDR0, CALLER_ADDR1);

//注：kernel/entry/common.c 应该是虚拟化相关文件。

    local_irq_disable //irqflags.h 需要使能 CONFIG_TRACE_IRQFLAGS 才会调用
    local_irq_save //irqflags.h 需要使能 CONFIG_TRACE_IRQFLAGS 才会调用
        trace_hardirqs_off //trace_preemptirq.c
            trace_android_rvh_irqs_disable(CALLER_ADDR0, CALLER_ADDR1);

关中断是只关闭了local的！

2. 开中断Hook —— trace_android_rvh_irqs_enable

(1) 调用路径

    default_idle_call //idle.c
    exit_to_user_mode //kernel/entry/common.c
    irqentry_exit //kernel/entry/common.c
    irqentry_nmi_exit //kernel/entry/common.c
        trace_hardirqs_on_prepare //trace_preemptirq.c
    local_irq_enable //irqflags.h 需要使能 CONFIG_TRACE_IRQFLAGS
    local_irq_restore //irqflags.h 需要使能 CONFIG_TRACE_IRQFLAGS
    safe_halt //irqflags.h 需要使能 CONFIG_TRACE_IRQFLAGS
    irqentry_exit //kernel/entry/common.c
        trace_hardirqs_on //trace_preemptirq.c
            trace_android_rvh_irqs_enable(CALLER_ADDR0, CALLER_ADDR1);
        trace_hardirqs_on_caller //trace_preemptirq.c 没有调用位置
        trace_hardirqs_off_caller //trace_preemptirq.c 没有调用位置
            trace_android_rvh_irqs_enable(CALLER_ADDR0, caller_addr);

3. 关抢占Hook —— trace_android_rvh_preempt_disable

(1) 调用路径

    __raw_spin_lock_bh //spinlock_api_smp.h
    __raw_spin_trylock_bh //spinlock_api_smp.h
    local_bh_disable //bottom_half.h
    __raw_read_lock_bh //rwlock_api_smp.h
    __raw_write_lock_bh //rwlock_api_smp.h
        __local_bh_disable_ip //softirq.c
            trace_preempt_off(CALLER_ADDR0, get_lock_parent_ip()); //trace_preemptirq.c
                trace_android_rvh_preempt_disable(a0, a1);

    preempt_count_add //core.c
    preempt_schedule_common //core.c
    preempt_schedule_notrace //core.c
        preempt_latency_start //core.c
            trace_preempt_off(CALLER_ADDR0, ip);
                trace_android_rvh_preempt_disable(a0, a1);

可见关抢占主要集中在两个位置，一个是 kernel/softirq.c 软中断实现中，另一个是在 kernel/sched/core.c 调度策略中。

4. 开抢占Hook —— trace_android_rvh_preempt_enable

(1) 调用路径

        irq_exit_rcu //softirq.c
        irq_exit //softirq.c
            __irq_exit_rcu //softirq.c 不在中断中，且没有软中断pending才调用
                invoke_softirq //softirq.c 需要使能 CONFIG_HAVE_IRQ_EXIT_ON_IRQ_STACK 才会调用，默认没使能
    spawn_ksoftirqd //softirq.c  __init 函数，初始化时注册为per-cpu的线程
        smpboot_register_percpu_thread(&softirq_threads) //softirq.c
            softirq_threads.thread_fn //softirq.c
                run_ksoftirqd //softirq.c
                    __do_softirq //softirq.c
                    _local_bh_enable //softirq.c
                        __local_bh_enable //softirq.c
                            trace_preempt_on(CALLER_ADDR0, get_lock_parent_ip()); //trace_preemptirq.c
                                trace_android_rvh_preempt_enable(a0, a1);

        __local_bh_enable_ip //softirq.c
        __irq_exit_rcu //softirq.c 传参 HARDIRQ_OFFSET
            preempt_count_sub //core.c
        preempt_schedule //core.c 若此时是关抢占的或是关中断的就调度一下
        _cond_resched //core.c 若没有定义 CONFIG_PREEMPTION 才调用，默认是使能的
    cond_resched_lock //include/linux/sched.h 调用位置众多
        __cond_resched_lock //core.c
            preempt_schedule_common //core.c
            preempt_schedule_notrace //core.c
                preempt_latency_stop //core.c CONFIG_DEBUG_PREEMPT 和 CONFIG_TRACE_PREEMPT_TOGGLE 若是没使能的话就是空函数，默认不使能，只要有一个使能就是使能的
                    trace_preempt_on(CALLER_ADDR0, get_lock_parent_ip()); //trace_preemptirq.c
                        trace_android_rvh_preempt_enable(a0, a1);

开抢占和关抢占一样，主要集中在两个位置，一个是 kernel/softirq.c 软中断实现中，另一个是在 kernel/sched/core.c 调度策略中。

 

三、方案修改

1. 原生内核 arch/arm64/configs/gki_defconfig 中使能 CONFIG_GKI_HACKS_FOR_CONSOLIDATE=y。

其配置位置：

$ cat init/Kconfig.gki-debug
config GKI_HIDDEN_RCUTORTURE
        bool
        select TASKS_RUDE_RCU

config GKI_HACKS_FOR_CONSOLIDATE
        bool "GKI Dummy config options for consolidate"
        select TRACE_PREEMPT_TOGGLE //它在 kernel/trace/Kconfig 中定义，没有再 select 别的
        select TRACE_IRQFLAGS //它在 lib/Kconfig.debug 中定义，依赖的 TRACE_IRQFLAGS_SUPPORT 默认是使能的，也没有select其它的东西
        select GKI_HIDDEN_RCUTORTURE //只在上面这个debug文件中定义

trace_preemptirq.c 文件的编译依赖 CONFIG_PREEMPTIRQ_TRACEPOINTS 配置项，而其只在 arch/arm64/configs/consolidate.fragment: CONFIG_PREEMPTIRQ_TRACEPOINTS=y 唯一配置使能。

2. build.config.msm.gki 中将 "GKI_BUILD_CONFIG=${GKI_KERNEL_DIR}/build.config.gki.aarch64" 改为 "GKI_BUILD_CONFIG=${GKI_KERNEL_DIR}/build.config.gki-debug.aarch64" 选debug的配置。它应该是根据 -debug 这个后缀来选择 lib/Kconfig.debug 的吧。

3. 内核中选中 CONFIG_SCHED_WALT_DEBUG=m 选中debug补丁编译成模块，内核根目录下的 modules.list.msm.XXX 要将需要添加上需要insmod的debug ko。

(1) Kconfig 中选中依赖的模块，而不是直接在 deconfig 中配置，select 应该可以自动处理下级依赖。

kernel/sched/walt$ cat Makefile 
...
obj-$(CONFIG_SCHED_WALT_DEBUG) += sched-walt-debug.o
sched-walt-debug-$(CONFIG_SCHED_WALT_DEBUG) := walt_debug.o preemptirq_long.o

kernel/sched/walt$ cat Kconfig 
    ...
    config SCHED_WALT_DEBUG
        tristate "WALT debug module"
        depends on SCHED_WALT
        select TRACE_PREEMPT_TOGGLE
        select TRACE_IRQFLAGS
        help
          provides debugging long preempt and irq disable code method. 
          also used to crash the system to catch issues in scenarios like
          RT throttling and sleeping while in atomic context etc.

(2) 编写trace统计代码

preemptirq_long.c：统计，超出阈值就打印一条调用路径的trace。

#include <linux/ftrace.h>
#include <linux/sched.h>
#include <linux/sysctl.h>
#include <linux/printk.h>
#include <linux/sched.h>
#include <linux/sched/clock.h>
#include <trace/hooks/preemptirq.h>
#define CREATE_TRACE_POINTS
#include "preemptirq_long.h"

#define IRQSOFF_SENTINEL 0x0fffDEAD

static unsigned int sysctl_preemptoff_tracing_threshold_ns = 1000000; //1ms 要改为5ms，达到1ms阈值的太多
static unsigned int sysctl_irqsoff_tracing_threshold_ns = 5000000; //5ms
static unsigned int sysctl_irqsoff_dmesg_output_enabled;
static unsigned int sysctl_irqsoff_crash_sentinel_value;
static unsigned int sysctl_irqsoff_crash_threshold_ns = 10000000;  //10ms

static unsigned int half_million = 500000;
static unsigned int one_hundred_million = 100000000;
static unsigned int one_million = 1000000;

//用于记录下irq被disable的时间戳
static DEFINE_PER_CPU(u64, irq_disabled_ts);

/*
 * preemption disable tracking require additional context
 * to rule out false positives(排除误报). see the comment in
 * test_preempt_disable_long() for more details.
 */
struct preempt_store {
    u64        ts;
    int        pid;
    unsigned long    ncsw;
};


static DEFINE_PER_CPU(struct preempt_store, the_ps);

static void note_irq_disable(void *u1, unsigned long u2, unsigned long u3)
{
    if (is_idle_task(current))
        return;

    /* 我们只需要在此处记下时间戳即可。使用堆栈跟踪触发功能来打印堆栈跟踪。*/
    this_cpu_write(irq_disabled_ts, sched_clock());
}

/* enable irq 时调用 */
static void test_irq_disable_long(void *u1, unsigned long ip, unsigned long parent_ip)
{
    u64 ts = this_cpu_read(irq_disabled_ts);

    if (!ts)
        return;

    this_cpu_write(irq_disabled_ts, 0);
    //时间差值
    ts = sched_clock() - ts;

    //默认5ms
    if (ts > sysctl_irqsoff_tracing_threshold_ns) {
        trace_irq_disable_long(ts, ip, parent_ip, CALLER_ADDR4, CALLER_ADDR5);

        //默认是0，就是打印几个函数地址。
        if (sysctl_irqsoff_dmesg_output_enabled == IRQSOFF_SENTINEL)
            printk_deferred("irqs off exceeds thresh delta=%llu C:(%ps<-%ps<-%ps<-%ps)\n",
                    ts, (void *)CALLER_ADDR2,
                    (void *)CALLER_ADDR3,
                    (void *)CALLER_ADDR4,
                    (void *)CALLER_ADDR5);
    }

    //0x0fffDEAD, 10ms。前者默认是0，即使后者超过10ms也不会crash.
    //实测，echo 0x0fffDEAD > irqsoff_crash_sentinel_value 后，立即就死机了。
    if (sysctl_irqsoff_crash_sentinel_value == IRQSOFF_SENTINEL && ts > sysctl_irqsoff_crash_threshold_ns) {
        printk_deferred("delta=%llu(ns) > crash_threshold=%u(ns) Task=%s\n", ts, sysctl_irqsoff_crash_threshold_ns, current->comm);
        BUG_ON(1);
    }
}

static void note_preempt_disable(void *u1, unsigned long u2, unsigned long u3)
{
    struct preempt_store *ps = &per_cpu(the_ps, raw_smp_processor_id());

    ps->ts = sched_clock();
    ps->pid = current->pid;
    /*
     * 和为nr_switches，表示切换的次数，nvcsw 表示非抢占任务被切走的次数，
     * nivcsw 表示发生抢占任务被切走的次数。
     */
    ps->ncsw = current->nvcsw + current->nivcsw;
}

/* enable preempt 时调用 */
static void test_preempt_disable_long(void *u1, unsigned long ip, unsigned long parent_ip)
{
    struct preempt_store *ps = &per_cpu(the_ps, raw_smp_processor_id());
    u64 delta = 0;

    if (!ps->ts)
        return;

    /*
     * schedule() 在禁用抢占的情况下调用 __schedule()。 如果我们现在进入空闲并退出空闲，
     * 我们认为抢占一直被禁用。 通过检查是否在同一任务中禁用抢占来检测这一点。 有可能在
     * 空闲后安排相同的任务。 要排除这种可能性，还要比较上下文切换计数。
     *
     * 关抢占的是当前任务，且当前任务的切换次数没有变 ==> 当前任务一次执行中关/开抢占
     */
    if (ps->pid == current->pid && (ps->ncsw == current->nvcsw + current->nivcsw))
        delta = sched_clock() - ps->ts; //关抢占时间差值

    ps->ts = 0;
    /*关抢占时间超过门限，默认是1ms，就会打印trace*/
    if (delta > sysctl_preemptoff_tracing_threshold_ns)
        trace_preempt_disable_long(delta, ip, parent_ip, CALLER_ADDR4, CALLER_ADDR5);
}

static struct ctl_table preemptirq_long_table[] = {
    {
        .procname    = "preemptoff_tracing_threshold_ns",
        .data        = &sysctl_preemptoff_tracing_threshold_ns, //默认1ms
        .maxlen        = sizeof(unsigned int),
        .mode        = 0644,
        .proc_handler    = proc_dointvec,
    },
    {
        .procname    = "irqsoff_tracing_threshold_ns",
        .data        = &sysctl_irqsoff_tracing_threshold_ns, //默认5ms
        .maxlen        = sizeof(unsigned int),
        .mode        = 0644,
        .proc_handler    = proc_douintvec_minmax,
        .extra1        = &half_million,
        .extra2        = &one_hundred_million,
    },
    {
        .procname    = "irqsoff_dmesg_output_enabled",
        .data        = &sysctl_irqsoff_dmesg_output_enabled, //默认为0，不使能
        .maxlen        = sizeof(unsigned int),
        .mode        = 0644,
        .proc_handler    = proc_dointvec,
    },
    {
        .procname    = "irqsoff_crash_sentinel_value",
        .data        = &sysctl_irqsoff_crash_sentinel_value, //默认为0，不使能
        .maxlen        = sizeof(unsigned int),
        .mode        = 0644,
        .proc_handler    = proc_dointvec,
    },
    {
        .procname    = "irqsoff_crash_threshold_ns",
        .data        = &sysctl_irqsoff_crash_threshold_ns, //默认为10ms
        .maxlen        = sizeof(unsigned int),
        .mode        = 0644,
        .proc_handler    = proc_douintvec_minmax,
        .extra1        = &one_million,
        .extra2        = &one_hundred_million,
    },
    { }
};

int preemptirq_long_init(void)
{
    if (!register_sysctl("preemptirq", preemptirq_long_table)) {
        pr_err("Fail to register sysctl table\n");
        return -EPERM;
    }

    /*
    hook位置：
    ./kernel/trace/trace_preemptirq.c:    trace_hardirqs_off_finish --> trace_android_rvh_irqs_disable(CALLER_ADDR0,
    ./kernel/trace/trace_preemptirq.c:    trace_hardirqs_off --> trace_android_rvh_irqs_disable(CALLER_ADDR0,
    */
    register_trace_android_rvh_irqs_disable(note_irq_disable, NULL);
    /*
    hook位置：
    ./trace_preemptirq.c:    trace_hardirqs_on_prepare --> trace_android_rvh_irqs_enable(CALLER_ADDR0,
    ./trace_preemptirq.c:    trace_hardirqs_on --> trace_android_rvh_irqs_enable(CALLER_ADDR0,
    ./trace_preemptirq.c:    trace_hardirqs_on_caller --> trace_android_rvh_irqs_enable(CALLER_ADDR0,
    ./trace_preemptirq.c:    trace_hardirqs_off_caller --> trace_android_rvh_irqs_enable(CALLER_ADDR0,
    */
    register_trace_android_rvh_irqs_enable(test_irq_disable_long, NULL);
    /*
    hook位置：
    ./trace_preemptirq.c:    trace_preempt_off --> trace_android_rvh_preempt_disable(a0, a1);
    */
    register_trace_android_rvh_preempt_disable(note_preempt_disable, NULL);
    /*
    hook位置：
    ./trace_preemptirq.c:    trace_preempt_on --> trace_android_rvh_preempt_enable(a0, a1);
    */
    register_trace_android_rvh_preempt_enable(test_preempt_disable_long, NULL);

    return 0;
}

preemptirq_long.h：trace打印格式，支持4层调用栈。

#undef TRACE_SYSTEM
/* 可在 tracing/events 下创建 preemptirq_long 目录 */
#define TRACE_SYSTEM preemptirq_long

#undef TRACE_INCLUDE_PATH
#define TRACE_INCLUDE_PATH .

#if !defined(_TRACE_PREEMPTIRQ_LONG_H) || defined(TRACE_HEADER_MULTI_READ)
#define _TRACE_PREEMPTIRQ_LONG_H

#include <linux/tracepoint.h>

/* reference preemptirq_template */
DECLARE_EVENT_CLASS(preemptirq_long_template,

    TP_PROTO(u64 delta, unsigned long ip, unsigned long parent_ip,
        unsigned long pparent_ip, unsigned long ppparent_ip),

    TP_ARGS(delta, ip, parent_ip, pparent_ip, ppparent_ip),

    TP_STRUCT__entry(
        __field(u64, delta)
        __field(unsigned long, caller_offs)
        __field(unsigned long, parent_offs)
        __field(unsigned long, pparent_offs)
        __field(unsigned long, ppparent_offs)
    ),

    TP_fast_assign(
        __entry->delta = delta;
        __entry->caller_offs = ip;
        __entry->parent_offs = parent_ip;
        __entry->pparent_offs = pparent_ip;
        __entry->ppparent_offs = ppparent_ip;
    ),

    TP_printk("delta=%llu(ns) caller=%ps <- %ps <- %ps <- %ps",
        __entry->delta, __entry->caller_offs,
        __entry->parent_offs,  __entry->pparent_offs,  __entry->ppparent_offs)
);

DEFINE_EVENT(preemptirq_long_template, irq_disable_long,
         TP_PROTO(u64 delta, unsigned long ip, unsigned long parent_ip,
              unsigned long pparent_ip, unsigned long ppparent_ip),
         TP_ARGS(delta, ip, parent_ip, pparent_ip, ppparent_ip));

DEFINE_EVENT(preemptirq_long_template, preempt_disable_long,
         TP_PROTO(u64 delta, unsigned long ip, unsigned long parent_ip,
              unsigned long pparent_ip, unsigned long ppparent_ip),
         TP_ARGS(delta, ip, parent_ip, pparent_ip, ppparent_ip));

#endif /* _TRACE_PREEMPTIRQ_LONG_H */

/* This part must be outside protection */
#include <trace/define_trace.h>

四、验证测试

1. 验证代码，测试关中断和关抢占，disable_irq_preempt_debug.c：

#define pr_fmt(fmt) "preempt_irq_debug: " fmt

#include <linux/module.h>
#include <linux/init.h>
#include <linux/fs.h>
#include <linux/sched.h>
#include <linux/proc_fs.h>
#include <linux/seq_file.h>
#include <linux/string.h>
#include <linux/delay.h>
#include <linux/printk.h>
#include <linux/plist.h>
#include <linux/workqueue.h>
#include <linux/preempt.h>
#include <linux/irqflags.h>
#include <linux/spinlock.h>
#include <linux/sched/clock.h>

enum {
    SET_TYPE = 0,
    SET_VAL,
    SET_MAX = 2,
};

enum {
    TEST_PREEMPT_DISABLE = 1,
    TEST_IRQ_DISABLE = 2,
    TEST_PREEMPT_IRQ_DISABLE = 4,
    TEST_SET_NUMBER = 8,
};

static int mdelay_time = 2;
static spinlock_t slock;


static int preempt_irq_debug_show(struct seq_file *m, void *v)
{
    seq_printf(m, "g_loop_times=%lu\n", mdelay_time);

    return 0;
}

static int preempt_irq_debug_open(struct inode *inode, struct file *file)
{
    return single_open(file, preempt_irq_debug_show, NULL);
}

static void busy_loop_delay(unsigned long num)
{
    unsigned long ts,  delta_t;

    ts = local_clock();
    mdelay(num);
    delta_t = sched_clock() - ts;
    pr_info("busy delay time=%ld.%ld ms\n", delta_t/1000000, (delta_t/1000)%1000);
}



/*
 * echo 1 关抢占
 * echo 2 关中断
 * echo 4 关中断，关抢占
 * echo 8 <num> 设置循环次数
*/
static ssize_t preempt_irq_debug_write(struct file *file, const char __user *buf, size_t count, loff_t *ppos)
{

    int ret, cnt = 0, cmd_type;
    unsigned int cmd_val;
    char *str, *token;
    char buffer[128] = {0};
    //8 char, max set num is 4000000 which 7 charactors.
    char opt_str[SET_MAX][16];

    if (count >= sizeof(buffer)) {
        count = sizeof(buffer) - 1;
    }
    if (copy_from_user(buffer, buf, count)) {
        pr_info("copy_from_user failed\n");
        return -EFAULT;
    }
    pr_info("user buffer=%s\n", buffer);

    buffer[count] = '\0';
    str = strstrip(buffer);
    while ((token = strsep(&str, " ")) && *token && cnt < SET_MAX) {
        strlcpy(opt_str[cnt], token, sizeof(opt_str[cnt]));
        pr_info("cmd%d = %s\n", cnt, opt_str[cnt]);
        cnt++;
    }

    ret = kstrtoint(strstrip(opt_str[SET_TYPE]), 10, &cmd_type);
    if (ret)
        return ret;

    if (cmd_type & TEST_PREEMPT_DISABLE) {
        pr_info("test preempt disable\n");
        preempt_disable();
        busy_loop_delay(mdelay_time);
        preempt_enable();
    }

    if (cmd_type & TEST_IRQ_DISABLE) {
        pr_info("test irq disable\n");
        local_irq_disable();
        busy_loop_delay(mdelay_time);
        local_irq_enable();
    }

    if (cmd_type & TEST_PREEMPT_IRQ_DISABLE) {
        pr_info("test preempt irq disable\n");
        spin_lock_irq(&slock);
        busy_loop_delay(mdelay_time);
        spin_unlock_irq(&slock);
    }

    /*TODO: 添加 spin_lock */
    

    if (cmd_type & TEST_SET_NUMBER) {
        ret = kstrtouint(strstrip(opt_str[SET_VAL]), 10, &cmd_val);
        if (ret)
            return ret;
        mdelay_time = cmd_val;
        pr_info("set g_loop_times %lu\n", cmd_val);
    }

    return count;
}

//Linux5.10 change file_operations to proc_ops
static const struct proc_ops preempt_irq_debug_fops = {
    .proc_open    = preempt_irq_debug_open,
    .proc_read    = seq_read,
    .proc_write   = preempt_irq_debug_write,
    .proc_lseek  = seq_lseek,
    .proc_release = single_release,
};


static int __init preempt_irq_debug_init(void)
{
    spin_lock_init(&slock);

    proc_create("preempt_irq_debug", S_IRUGO | S_IWUGO, NULL, &preempt_irq_debug_fops);

    pr_info("preempt_irq_debug probed!\n");

    return 0;
}

static void __exit preempt_irq_debug_exit(void)
{
    remove_proc_entry("preempt_irq_debug", NULL);

    pr_info("preempt_irq_debug exit!\n");
}

module_init(preempt_irq_debug_init);
module_exit(preempt_irq_debug_exit);


MODULE_DESCRIPTION("Preempt Irq Debug");
MODULE_LICENSE("GPL v2");

2. 验证Trace

(1) 验证编码没问题

/proc # echo 2 > preempt_irq_debug
/proc # dmesg -c | grep preempt_irq_debug
[  459.975452] preempt_irq_debug: user buffer=2\x0a
[  459.975496] preempt_irq_debug: cmd0 = 2
[  459.975518] preempt_irq_debug: test irq disable
[  459.977542] preempt_irq_debug: busy delay time=2.1 ms

(2) 验证Trace追踪没问题

/ # cat /proc/preempt_irq_debug
g_loop_times=6
/ # echo 1 > /proc/preempt_irq_debug
/ # echo 2 > /proc/preempt_irq_debug
/ # echo 4 > /proc/preempt_irq_debug


/ # echo 5000000 > /proc/sys/preemptirq/preemptoff_tracing_threshold_ns
/ # P=/sys/kernel/tracing; echo preemptirq_long > $P/set_event; echo notrace_printk > $P/trace_options; echo nomarkers > $P/trace_options; > $P/trace; echo 1 > $P/tracing_on; cat $P/trace_pipe

  sh-3860    [003] ...1 16069.435369: preempt_disable_long: delta=6105833(ns) caller=preempt_irq_debug_write [disable_irq_preempt_debug] <- preempt_irq_debug_write [disable_irq_preempt_debug] <- ksys_write <- __arm64_sys_write

  sh-3860    [000] dn.. 16078.972178: irq_disable_long: delta=6021511(ns) caller=preempt_irq_debug_write [disable_irq_preempt_debug] <- vfs_write <- ksys_write <- __arm64_sys_write

  sh-3860    [003] d..1 16083.483985: irq_disable_long: delta=6017969(ns) caller=_raw_spin_unlock_irq <- proc_reg_write <- vfs_write <- ksys_write
  sh-3860    [003] ...1 16083.484690: preempt_disable_long: delta=6726719(ns) caller=_raw_spin_unlock_irq <- proc_reg_write <- vfs_write <- ksys_write

四、总结

1. 注意 printk() 打印，若是要打印到串口，它就是关着 local 中断，然后以 poll 的方式进行打印的，打印一条稍长的 log 需要关中断十几个毫秒！若是只打印到内存，则不会有关中断时间长的问题。若是没有开串口，在抓log时也是打印在内存中的。