clinux-kernellinux-device-driverstack-traceperf

Linux kernel function call flow


Is there a way to get to know what kernel functions are called during a certain event.

For example, if I press any key on keyboard, I want to know what all kernel functions and device driver functions are getting called - before the character appears on the screen (the character corresponding to the key that I typed on keyboard).

I want to dump the complete flow somewhere and examine it later. I'm talking about kernel-space functions - NOT user-space functions.


Solution

  • I want to know what all kernel functions and device driver functions are getting called

    Obviously, the fullness of the trace depends on where it is started. And that's up to you.

    You can traсе what you want through the handy trace-cmd. E.g. you can obtain the function graph. Firstly you need to determine some entry point depending on your needs.
    If it is about keyboard pressing, you need to find its driver and some function related to it.

    Example:
    Classic AT and PS/2 keyboard driver atkbd has interrupt function atkbd_interrupt. Let's check if there is such a trace point:

    trace-cmd list -f | grep atkbd_int
    

    Then start the recording:

    trace-cmd record -p function_graph -g atkbd_interrupt &
    

    Press some keys and stop recording: fg then Ctrl+C. Now you can obtain the function graph:

    trace-cmd report | vim -
    

    It would be something like:

    CPU 1 is empty
    CPU 2 is empty
    CPU 3 is empty
    cpus=4
              <idle>-0     [000] 1095787.266859: funcgraph_entry:                   |  atkbd_interrupt() {
              <idle>-0     [000] 1095787.266863: funcgraph_entry:                   |    input_event() {
              <idle>-0     [000] 1095787.266864: funcgraph_entry:        0.215 us   |      _raw_spin_lock_irqsave();
              <idle>-0     [000] 1095787.266866: funcgraph_entry:        0.386 us   |      input_handle_event();
              <idle>-0     [000] 1095787.266867: funcgraph_entry:        0.163 us   |      _raw_spin_unlock_irqrestore();
              <idle>-0     [000] 1095787.266868: funcgraph_exit:         3.882 us   |    }
              <idle>-0     [000] 1095787.266869: funcgraph_entry:                   |    input_event() {
              <idle>-0     [000] 1095787.266869: funcgraph_entry:        0.123 us   |      _raw_spin_lock_irqsave();
              <idle>-0     [000] 1095787.266870: funcgraph_entry:                   |      input_handle_event() {
              <idle>-0     [000] 1095787.266871: funcgraph_entry:                   |        add_input_randomness() {
              <idle>-0     [000] 1095787.266871: funcgraph_entry:                   |          add_timer_randomness() {
              <idle>-0     [000] 1095787.266872: funcgraph_entry:                   |            mix_pool_bytes() {
              <idle>-0     [000] 1095787.266872: funcgraph_entry:        0.327 us   |              _raw_spin_lock_irqsave();
              <idle>-0     [000] 1095787.266873: funcgraph_entry:        0.877 us   |              _mix_pool_bytes();
              <idle>-0     [000] 1095787.266875: funcgraph_entry:        0.163 us   |              _raw_spin_unlock_irqrestore();
              <idle>-0     [000] 1095787.266876: funcgraph_exit:         3.628 us   |            }
              <idle>-0     [000] 1095787.266876: funcgraph_entry:                   |            credit_entropy_bits() {
              <idle>-0     [000] 1095787.266877: funcgraph_entry:                   |              __wake_up() {
              <idle>-0     [000] 1095787.266877: funcgraph_entry:        0.229 us   |                _raw_spin_lock_irqsave();
              <idle>-0     [000] 1095787.266878: funcgraph_entry:        0.120 us   |                __wake_up_common();
              <idle>-0     [000] 1095787.266879: funcgraph_entry:        0.135 us   |                _raw_spin_unlock_irqrestore();
              <idle>-0     [000] 1095787.266880: funcgraph_exit:         2.719 us   |              }
              <idle>-0     [000] 1095787.266880: funcgraph_entry:        0.108 us   |              kill_fasync();
              <idle>-0     [000] 1095787.266881: funcgraph_exit:         4.833 us   |            }
              <idle>-0     [000] 1095787.266882: funcgraph_exit:       + 10.249 us  |          }
              <idle>-0     [000] 1095787.266882: funcgraph_exit:       + 11.186 us  |        }
              <idle>-0     [000] 1095787.266883: funcgraph_entry:        0.237 us   |        atkbd_event();
              <idle>-0     [000] 1095787.266884: funcgraph_exit:       + 13.347 us  |      }
              <idle>-0     [000] 1095787.266884: funcgraph_entry:        0.138 us   |      _raw_spin_unlock_irqrestore();
              ........                                                         
    

    It's just a little piece of trace for example. I did it in my qemu VM.