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.
