使用Kretprobes 监控内涵函数运行时间和返回值.

一个简单的例子

文件名: myretprobe.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>

static char func_name[NAME_MAX] = "ksys_read";
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");

/* per-instance private data */
struct my_data {
    ktime_t entry_stamp;
};

/* Here we use the entry_hanlder to timestamp function entry */
static int entry_handler(struct kretprobe_instance *ri, struct pt_regs *regs)
{
    struct my_data *data;

    if (!current->mm)
        return 1;    /* Skip kernel threads */

    data = (struct my_data *)ri->data;
    data->entry_stamp = ktime_get();
    return 0;
}

/*
 * Return-probe handler: Log the return value and duration. Duration may turn
 * out to be zero consistently, depending upon the granularity of time
 * accounting on the platform.
 */
static int ret_handler(struct kretprobe_instance *ri, struct pt_regs *regs)
{
    int 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));
    printk(KERN_INFO "%s returned %d and took %lld ns to execute\n",
            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),
    /* Probe up to 20 instances concurrently. */
    .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) {
        printk(KERN_INFO "register_kretprobe failed, returned %d\n",
                ret);
        return -1;
    }
    printk(KERN_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);
    printk(KERN_INFO "kretprobe at %p unregistered\n",
            my_kretprobe.kp.addr);

    /* nmissed > 0 suggests that maxactive was set too low. */
    printk(KERN_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");

Makefile

obj-m += myretprobe.o

tag ?= `uname -r`
KDIR := /lib/modules/${tag}/build/

all:
    make -C $(KDIR) M=$(PWD) modules

clean:
    make -C $(KDIR) M=$(PWD) clean

运行并查看结果

$ make all
$ sudo insmod myretprobe.ko

$ sudo rmmod myretprobe
$ tail -n 10 /var/log/syslog
Jul 13 00:27:54 supra kernel: [ 2367.855060] ksys_read returned -32 and took 234 ns to execute
Jul 13 00:27:54 supra kernel: [ 2367.855063] ksys_read returned -32 and took 190 ns to execute
Jul 13 00:27:54 supra kernel: [ 2367.855066] ksys_read returned -32 and took 191 ns to execute
Jul 13 00:27:54 supra kernel: [ 2367.855068] ksys_read returned -32 and took 189 ns to execute

统计返回值 histogram 的例子

#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/init.h>

#define MY_ARRAY_SIZE 10
static uint my_array[MY_ARRAY_SIZE];

static char func_name[NAME_MAX] = "ksys_read";
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");

static int ret_handler(struct kretprobe_instance *ri, struct pt_regs *regs)
{
    int retval = regs_return_value(regs);
    if (retval < 0) {
        my_array[0]++;
    } else if (0 == retval) {
        my_array[1]++;
    } else if (retval < 20) {
        my_array[2]++;
    } else if (retval < 40) {
        my_array[3]++;
    } else if (retval < 80) {
        my_array[4]++;
    } else if (retval < 160) {
        my_array[5]++;
    } else if (retval < 320) {
        my_array[6]++;
    } else if (retval < 640) {
        my_array[7]++;
    } else if (retval < 1280) {
        my_array[8]++;
    } else {
        my_array[9]++;
    }
    //printk(KERN_INFO "%s returned %d \n", func_name, retval);
    return 0;
}

static struct kretprobe my_kretprobe = {
    .handler        = ret_handler,
    .maxactive        = 3,
};

static int __init kretprobe_init(void)
{
    int ret;

    memset(my_array, 0, sizeof(uint) * MY_ARRAY_SIZE);
    my_kretprobe.kp.symbol_name = func_name;
    ret = register_kretprobe(&my_kretprobe);
    if (ret < 0) {
        printk(KERN_INFO "register_kretprobe failed, returned %d\n",
                ret);
        return -1;
    }
    printk(KERN_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)
{
    int i;
    unregister_kretprobe(&my_kretprobe);
    printk(KERN_INFO "kretprobe at %p unregistered\n",
            my_kretprobe.kp.addr);

    printk(KERN_INFO "my_array values:\n");
    for (i = 0; i < MY_ARRAY_SIZE; i++) {
        printk(KERN_INFO "my_array[%d]: %u\n", i, my_array[i]);
    }

    /* nmissed > 0 suggests that maxactive was set too low. */
    printk(KERN_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");