为什么一个的printk（）连续系统日志内打印时，它驻留在（每ftrace）不会被调用内核函数？ [英] Why would a printk() continuously print inside of syslog when the kernel function it resides in does not get called (per ftrace)?

问题描述

我想从的里面的一些信息__ generic_file_write_iter（） /filemap.c?v=4.5#L2696相对=nofollow>毫米/ filemap.c 。

我已经修改的功能如下：

 结构文件*文件= iocb-＆GT; ki_filp;
结构address_space *映射文件 -  =＆GT; f_mapping;
结构的inode的inode * = mapping-＆GT;主机;
ssiz​​e_t供书面= 0;
ssiz​​e_t供走错了路。
ssiz​​e_t供状态;/ *我们可以写回这个队列页面回收* /
电流 - ＆GT; backing_dev_info = inode_to_bdi（i节点）;
ERR = file_remove_privs（文件）;
如果（ERR）
        转到出来;ERR = file_update_time（文件）;
如果（ERR）
        转到出来;/ *如果这个（）是我已经添加* /
如果（io_tracing_on）{
        ssiz​​e_t供write_size = iov_length（从 - ＆GT; IOV，从 - ＆GT; nr_segs）;
        printk的（KERN_INFO写入大小=％祖，PID =％d个，索引节点=％lu个\\ N，write_size，task_pid_nr（电流），inode-＆GT; i_ino）;
}如果（iocb-＆GT; ki_flags＆安培; IOCB_DIRECT）{
        参数loff_t POS，endbyte;
        ...
 

io_tracing_on是，我通过/ proc入口（由我的模块，该模块内置在内核中创建）设置一个变量。当我翻转上的开关和运行DD（通过 DD如果=的/ dev / urandom的= / tmp目录/胡言乱语BS = 1M计算= 1 ），我得到一个连续的数据流输出的的/ var / log / syslog的，即：

  6月27日15时00分41秒马尔卡内核：[463.424155]写大小= 168，PID = 715，索引节点= 7864653
6月27日15时00分41秒马尔卡内核：[463.428064]写大小= 168，PID = 715，索引节点= 7864354
6月27日15时00分41秒马尔卡内核：[463.428126]写大小= 168，PID = 715，索引节点= 7864653
6月27日15时00分41秒马尔卡内核：[463.432061]写大小= 168，PID = 715，索引节点= 7864354
6月27日15时00分41秒马尔卡内核：[463.432121]写大小= 168，PID = 715，索引节点= 7864653
6月27日15时00分41秒马尔卡内核：[463.436075]写大小= 168，PID = 715，索引节点= 7864354
6月27日15时00分41秒马尔卡内核：[463.436133]写大小= 168，PID = 715，索引节点= 7864653
6月27日15时00分41秒马尔卡内核：[463.440060]写大小= 168，PID = 715，索引节点= 7864354
6月27日15时00分41秒马尔卡内核：[463.440121]写大小= 168，PID = 715，索引节点= 7864653
等等
 

然而，当我运行ftrace（使用功能示踪剂），我从来没有看到 __ generic_file_write_iter（）被调用。那么，为什么我的的printk（）语句不断得到所谓无 __ generic_file_write_iter（）显示在ftrace输出高达<？ / p>

该内核版本是4.5.5。

更新

previously，我没能到PID任何有效的过程联系起来。改变我的code打印PID和TGID之后，我能够与进程相关联TGID。看来，系统日志呼唤我的的printk（）每次写入，导致产量的连续流的时间。然而，ftrace仍然没有显示 __ generic_file_write_iter（）被称为近足够的时间，以反映倍量我的的printk（）被调用。所以，我的问题是 - 如果ftrace正在工作，我希望，我会想象那里是一个调用 __ generic_file_write_iter（）在ftrace每 printk的（）我在syslog看到的。

解决方案

  

然而，当我运行ftrace（使用功能示踪剂），我从来没有看到
   __ generic_file_write_iter（）被调用。

最可能的是， __ generic_file_write_iter 未在上市/ SYS /内核/调试/跟踪/ available_filter_functions （了<功能STRONG> ftrace 可以跟踪的，看的 ftrace - 功能示踪或的href=\"https://lwn.net/Articles/370423/\" rel=\"nofollow\">秘密）

I am trying to print some information inside of __generic_file_write_iter() from within mm/filemap.c.

I have modified the function as follows:

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 is a variable that I set via a /proc entry (created by my module, which is built in to the kernel). When I flip the switch on and run dd (via dd if=/dev/urandom of=/tmp/gibberish bs=1M count=1), I get a continuous stream of output to /var/log/syslog, i.e.:

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

Yet, when I run the ftrace (using the "function" tracer), I never see __generic_file_write_iter() get called. So, why would my printk() statement get called continuously without __generic_file_write_iter() showing up in the ftrace output?

The kernel version is 4.5.5.

UPDATE

Previously, I was not able to associate the pid with any valid process. After changing my code to print pid and tgid, I was able to associate tgid with a process. It seems that the syslog is calling my printk() every time it writes, causing the continuous stream of output. However, ftrace still does not show __generic_file_write_iter() being called near enough times to reflect the amount of times my printk() is called. So, my question remains -- if ftrace is working as I expect, I would imagine there to be one call to __generic_file_write_iter() in ftrace for every printk() that I see in the syslog.

解决方案

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

Most probably, __generic_file_write_iter is not listed in /sys/kernel/debug/tracing/available_filter_functions (the functions that ftrace can trace, see ftrace - Function Tracer or Secrets of the Ftrace function tracer).

这篇关于为什么一个的printk（）连续系统日志内打印时，它驻留在（每ftrace）不会被调用内核函数？的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！