使用kretprobes來查找耗時長的中斷處理函數

在實時系統中，如果top half時間過長，會導緻實時任務得不到排程，産生比較高的延時。使用kretprobes可以檢視中斷處理的時間，代碼如下（參考kretprobe_sample.c做了一些改動）：

#include <linux/kernel.h>

#include <linux/module.h>

#include <linux/kprobes.h>

#include <linux/ktime.h>

#include <linux/limits.h>

#include <linux/sched.h>

#include <linux/irq.h>

#include <linux/interrupt.h>

#define PT_REGS_PARM1(x) ((x)->regs[0])

static char func_name[NAME_MAX] = "__handle_irq_event_percpu";

module_param_string(func, func_name, NAME_MAX, S_IRUGO);

MODULE_PARM_DESC(func, "Function to kretprobe; this module will report the"

            " function's execution time");

struct my_data {

    ktime_t entry_stamp;

    char func_name[NAME_MAX];

};

static int entry_handler(struct kretprobe_instance *ri, struct pt_regs *regs)

{

    struct my_data *data;

    struct irq_desc *desc;

    char *str;

    if (!current->mm)

        return 1;    

    data = (struct my_data *)ri->data;

    data->entry_stamp = ktime_get();

    str = data->func_name;

    desc = (struct irq_desc *)PT_REGS_PARM1(regs);

    str[0] = 0;

    if (desc->action)

        sprint_symbol_no_offset(str, (unsigned long)desc->action->handler);

    return 0;

}

static int ret_handler(struct kretprobe_instance *ri, struct pt_regs *regs)

{

    unsigned long retval = regs_return_value(regs);

    struct my_data *data = (struct my_data *)ri->data;

    s64 delta;

    ktime_t now;

    now = ktime_get();

    delta = ktime_to_ns(ktime_sub(now, data->entry_stamp));

    pr_info("%s returned %lu and took %lld ns to execute\n",

            data->func_name, retval, (long long)delta);

    return 0;

}

static struct kretprobe my_kretprobe = {

    .handler        = ret_handler,

    .entry_handler        = entry_handler,

    .data_size        = sizeof(struct my_data),

    .maxactive        = 20,

};

static int __init kretprobe_init(void)

{

    int ret;

    my_kretprobe.kp.symbol_name = func_name;

    ret = register_kretprobe(&my_kretprobe);

    if (ret < 0) {

        pr_err("register_kretprobe failed, returned %d\n", ret);

        return -1;

    }

    pr_info("Planted return probe at %s: %p\n",

            my_kretprobe.kp.symbol_name, my_kretprobe.kp.addr);

    return 0;

}

static void __exit kretprobe_exit(void)

{

    unregister_kretprobe(&my_kretprobe);

    pr_info("kretprobe at %p unregistered\n", my_kretprobe.kp.addr);

    pr_info("Missed probing %d instances of %s\n",

        my_kretprobe.nmissed, my_kretprobe.kp.symbol_name);

}

module_init(kretprobe_init)

module_exit(kretprobe_exit)

MODULE_LICENSE("GPL");

編譯後，運作：

insmod kretprobe.ko; cyclictest xxx;

得到結果如下：

[  272.418346] xhci_msi_irq returned 1 and took 146602 ns to execute

[  272.426034] ahci_single_level_irq_intr returned 1 and took 29161 ns to execute

[  272.426332] xhci_msi_irq returned 1 and took 135103 ns to execute

[  272.434361] xhci_msi_irq returned 1 and took 155142 ns to execute

[  272.442334] xhci_msi_irq returned 1 and took 138082 ns to execute

[  272.448333] xhci_msi_irq returned 1 and took 136542 ns to execute

[  272.456333] xhci_msi_irq returned 1 and took 134342 ns to execute

......

[  274.324755] ahci_single_level_irq_intr returned 1 and took 31560 ns to execute

[  274.330631] e1000_intr_msix_rx [e1000e] returned 1 and took 52401 ns to execute

[  274.347062] ahci_single_level_irq_intr returned 1 and took 29940 ns to execute

[  274.763850] ahci_single_level_irq_intr returned 1 and took 32041 ns to execute

[  274.796840] ahci_single_level_irq_intr returned 1 and took 29040 ns to execute

[  275.031541] ahci_single_level_irq_intr returned 1 and took 30261 ns to execute

[  275.040657] e1000_intr_msix_rx [e1000e] returned 1 and took 47541 ns to execute

[  275.232745] e1000_intr_msix_rx [e1000e] returned 1 and took 53941 ns to execute

[  275.233593] e1000_intr_msix_rx [e1000e] returned 1 and took 48321 ns to execute

[  275.377567] ahci_single_level_irq_intr returned 1 and took 30160 ns to execute

[  275.399842] e1000_intr_msix_rx [e1000e] returned 1 and took 50941 ns to execute

如果是preempt rt的實時系統，該代碼隻能得到irq_default_primary_handler，因為在preempt rt的方案中，所有的中斷處理函數都變成了threaded irq，irq_default_primary_handler被設定為預設的頂半部。