Pourquoi un printk () imprimerait-il continuellement dans syslog lorsque la fonction du kernel dans laquelle il réside ne serait pas appelée (par trace)?

J’essaie d’imprimer des informations dans __generic_file_write_iter() partir de mm / filemap.c .

J’ai modifié la fonction comme suit:

 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 est une variable que j’ai définie via une entrée / proc (créée par mon module, intégré au kernel). Lorsque je bascule le commutateur et exécute dd (via dd if=/dev/urandom of=/tmp/gibberish bs=1M count=1 ), je reçois un stream de sortie continu vers /var/log/syslog , c’est-à-dire:

 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 

Pourtant, lorsque je lance ftrace (avec le traceur “function”), je ne vois jamais l’ __generic_file_write_iter() . Alors, pourquoi mon instruction printk() serait-elle appelée en continu sans que __generic_file_write_iter() apparaisse dans la sortie de ftrace?

La version du kernel est 4.5.5.

METTRE À JOUR

Auparavant, je ne pouvais pas associer le pid à un processus valide. Après avoir modifié mon code pour imprimer pid et tgid, j’ai pu associer tgid à un processus. Il semble que le syslog appelle mon printk() chaque fois qu’il écrit, ce qui provoque un stream continu de sortie. Cependant, ftrace ne montre toujours pas que __generic_file_write_iter() été appelé assez de fois pour refléter le nombre de fois que ma printk() est appelée. Donc, ma question demeure: si ftrace fonctionne comme prévu, j’imagine qu’il y ait un appel à __generic_file_write_iter() dans ftrace pour chaque printk() que je vois dans le journal système.

Pourtant, lorsque je lance ftrace (avec le traceur “function”), je ne vois jamais l’ __generic_file_write_iter() .

Très probablement, __generic_file_write_iter n’est pas répertorié dans /sys/kernel/debug/tracing/available_filter_functions ( les fonctions que ftrace peut suivre , voir ftrace – Traceur de fonctions ou Secrets du traceur de fonctions Ftrace ).