How to use ftrace to analyze latency of the kernel module function

Posted on Edited on In , Views:

In this example, we study the latency of the function “nfsd_vfs_write” from kernel module “nfsd”.

ftrace configuration

The following ftrace options are used in this example. There are 8 nfsd processes to be traced.

  • current_tracer: function_graph
  • pids: 3591 3592 3593 3594 3595 3596 3597 3598
  • filters: nfsd_vfs_write [nfsd]

ftrace result

From the following trace result, it helps understand the call time of the function “nfsd_vfs_write”. This can be very helpful if we need to analyze the function latency in the kernel module.

$ cat ftrace.out | grep nfsd_vfs_write | grep "nfsd_vfs_write \[nfsd\]();" | head -5
  1)  ! 185.011 us  |  nfsd_vfs_write [nfsd]();
  2)  ! 161.237 us  |  nfsd_vfs_write [nfsd]();
  3)  ! 200.954 us  |  nfsd_vfs_write [nfsd]();
  4)  ! 255.285 us  |  nfsd_vfs_write [nfsd]();
  5)  ! 171.537 us  |  nfsd_vfs_write [nfsd]();

Reference