Skip to content
  • Frederic Weisbecker's avatar
    tracing/function-return-tracer: set a more human readable output · 287b6e68
    Frederic Weisbecker authored
    
    
    Impact: feature
    
    This patch sets a C-like output for the function graph tracing.
    For this aim, we now call two handler for each function: one on the entry
    and one other on return. This way we can draw a well-ordered call stack.
    
    The pid of the previous trace is loosely stored to be compared against
    the one of the current trace to see if there were a context switch.
    
    Without this little feature, the call tree would seem broken at
    some locations.
    We could use the sched_tracer to capture these sched_events but this
    way of processing is much more simpler.
    
    2 spaces have been chosen for indentation to fit the screen while deep
    calls. The time of execution in nanosecs is printed just after closed
    braces, it seems more easy this way to find the corresponding function.
    If the time was printed as a first column, it would be not so easy to
    find the corresponding function if it is called on a deep depth.
    
    I plan to output the return value but on 32 bits CPU, the return value
    can be 32 or 64, and its difficult to guess on which case we are.
    I don't know what would be the better solution on X86-32: only print
    eax (low-part) or even edx (high-part).
    
    Actually it's thee same problem when a function return a 8 bits value, the
    high part of eax could contain junk values...
    
    Here is an example of trace:
    
    sys_read() {
      fget_light() {
      } 526
      vfs_read() {
        rw_verify_area() {
          security_file_permission() {
            cap_file_permission() {
            } 519
          } 1564
        } 2640
        do_sync_read() {
          pipe_read() {
            __might_sleep() {
            } 511
            pipe_wait() {
              prepare_to_wait() {
              } 760
              deactivate_task() {
                dequeue_task() {
                  dequeue_task_fair() {
                    dequeue_entity() {
                      update_curr() {
                        update_min_vruntime() {
                        } 504
                      } 1587
                      clear_buddies() {
                      } 512
                      add_cfs_task_weight() {
                      } 519
                      update_min_vruntime() {
                      } 511
                    } 5602
                    dequeue_entity() {
                      update_curr() {
                        update_min_vruntime() {
                        } 496
                      } 1631
                      clear_buddies() {
                      } 496
                      update_min_vruntime() {
                      } 527
                    } 4580
                    hrtick_update() {
                      hrtick_start_fair() {
                      } 488
                    } 1489
                  } 13700
                } 14949
              } 16016
              msecs_to_jiffies() {
              } 496
              put_prev_task_fair() {
              } 504
              pick_next_task_fair() {
              } 489
              pick_next_task_rt() {
              } 496
              pick_next_task_fair() {
              } 489
              pick_next_task_idle() {
              } 489
    
    ------------8<---------- thread 4 ------------8<----------
    
    finish_task_switch() {
    } 1203
    do_softirq() {
      __do_softirq() {
        __local_bh_disable() {
        } 669
        rcu_process_callbacks() {
          __rcu_process_callbacks() {
            cpu_quiet() {
              rcu_start_batch() {
              } 503
            } 1647
          } 3128
          __rcu_process_callbacks() {
          } 542
        } 5362
        _local_bh_enable() {
        } 587
      } 8880
    } 9986
    kthread_should_stop() {
    } 669
    deactivate_task() {
      dequeue_task() {
        dequeue_task_fair() {
          dequeue_entity() {
            update_curr() {
              calc_delta_mine() {
              } 511
              update_min_vruntime() {
              } 511
            } 2813
    
    Signed-off-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
    Acked-by: default avatarSteven Rostedt <rostedt@goodmis.org>
    Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
    287b6e68