c - 当 printk() 驻留的内核函数未被调用(根据 ftrace)时，为什么 printk() 会在 syslog 内部连续打印？

Question

我正在尝试从 mm/filemap.c 中打印 __generic_file_write_iter() 中的一些信息.

我修改了函数如下:

struct file *file = iocb->ki_filp;
struct address_space * mapping = file->f_mapping;
struct inode    *inode = mapping->host;
ssize_t         written = 0;
ssize_t         err;
ssize_t         status;

/* We can write back this queue in page reclaim */
current->backing_dev_info = inode_to_bdi(inode);
err = file_remove_privs(file);
if (err)
        goto out;

err = file_update_time(file);
if (err)
        goto out;

/* This if() is all I have added */
if(io_tracing_on) {
        ssize_t write_size = iov_length(from->iov, from->nr_segs);
        printk(KERN_INFO "write size=%zu, pid=%d, inode=%lu\n", write_size, task_pid_nr(current), inode->i_ino);
}

if (iocb->ki_flags & IOCB_DIRECT) {
        loff_t pos, endbyte;
        ...

io_tracing_on 是我通过/proc 条目设置的变量(由我的模块创建，内置于内核中)。当我打开开关并运行 dd(通过 dd if=/dev/urandom of=/tmp/gibberish bs=1M count=1)时，我得到一个连续的输出流到 /var/log/syslog，即:

Jun 27 15:00:41 malka kernel: [  463.424155] write size=168, pid=715, inode=7864653
Jun 27 15:00:41 malka kernel: [  463.428064] write size=168, pid=715, inode=7864354
Jun 27 15:00:41 malka kernel: [  463.428126] write size=168, pid=715, inode=7864653
Jun 27 15:00:41 malka kernel: [  463.432061] write size=168, pid=715, inode=7864354
Jun 27 15:00:41 malka kernel: [  463.432121] write size=168, pid=715, inode=7864653
Jun 27 15:00:41 malka kernel: [  463.436075] write size=168, pid=715, inode=7864354
Jun 27 15:00:41 malka kernel: [  463.436133] write size=168, pid=715, inode=7864653
Jun 27 15:00:41 malka kernel: [  463.440060] write size=168, pid=715, inode=7864354
Jun 27 15:00:41 malka kernel: [  463.440121] write size=168, pid=715, inode=7864653
etc

然而，当我运行 ftrace(使用“函数”跟踪器)时，我从未看到 __generic_file_write_iter() 被调用。那么，为什么我的 printk() 语句会被连续调用而 __generic_file_write_iter() 不会出现在 ftrace 输出中？

内核版本为4.5.5。

更新

以前，我无法将 pid 与任何有效进程相关联。在更改我的代码以打印 pid 和 tgid 之后，我能够将 tgid 与进程相关联。似乎系统日志每次写入时都在调用我的 printk() ，导致连续输出流。但是，ftrace 仍然没有显示 __generic_file_write_iter() 被调用的次数足够多，无法反射(reflect)我的 printk() 被调用的次数。所以，我的问题仍然存在——如果 ftrace 像我预期的那样工作，我想我会在 ftrace 中为我调用的每个 printk() 调用一次 __generic_file_write_iter()在系统日志中查看。

Answer 1

Yet, when I run the ftrace (using the "function" tracer), I never see __generic_file_write_iter() get called.

__generic_file_write_iter 很可能没有列在 /sys/kernel/debug/tracing/available_filter_functions 中(ftrace可以追踪，参见ftrace - Function Tracer 或Secrets of the Ftrace function tracer )。