Skip to content
  • Steven Rostedt's avatar
    tracing: Add irq, preempt-count and need resched info to default trace output · 77271ce4
    Steven Rostedt authored
    
    
    People keep asking how to get the preempt count, irq, and need resched info
    and we keep telling them to enable the latency format. Some developers think
    that traces without this info is completely useless, and for a lot of tasks
    it is useless.
    
    The first option was to enable the latency trace as the default format, but
    the header for the latency format is pretty useless for most tracers and
    it also does the timestamp in straight microseconds from the time the trace
    started. This is sometimes more difficult to read as the default trace is
    seconds from the start of boot up.
    
    Latency format:
    
     # tracer: nop
     #
     # nop latency trace v1.1.5 on 3.2.0-rc1-test+
     # --------------------------------------------------------------------
     # latency: 0 us, #159771/64234230, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
     #    -----------------
     #    | task: -0 (uid:0 nice:0 policy:0 rt_prio:0)
     #    -----------------
     #
     #                  _------=> CPU#
     #                 / _-----=> irqs-off
     #                | / _----=> need-resched
     #                || / _---=> hardirq/softirq
     #                ||| / _--=> preempt-depth
     #                |||| /     delay
     #  cmd     pid   ||||| time  |   caller
     #     \   /      |||||  \    |   /
     migratio-6       0...2 41778231us+: rcu_note_context_switch <-__schedule
     migratio-6       0...2 41778233us : trace_rcu_utilization <-rcu_note_context_switch
     migratio-6       0...2 41778235us+: rcu_sched_qs <-rcu_note_context_switch
     migratio-6       0d..2 41778236us+: rcu_preempt_qs <-rcu_note_context_switch
     migratio-6       0...2 41778238us : trace_rcu_utilization <-rcu_note_context_switch
     migratio-6       0...2 41778239us+: debug_lockdep_rcu_enabled <-__schedule
    
    default format:
    
     # tracer: nop
     #
     #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
     #              | |       |          |         |
          migration/0-6     [000]    50.025810: rcu_note_context_switch <-__schedule
          migration/0-6     [000]    50.025812: trace_rcu_utilization <-rcu_note_context_switch
          migration/0-6     [000]    50.025813: rcu_sched_qs <-rcu_note_context_switch
          migration/0-6     [000]    50.025815: rcu_preempt_qs <-rcu_note_context_switch
          migration/0-6     [000]    50.025817: trace_rcu_utilization <-rcu_note_context_switch
          migration/0-6     [000]    50.025818: debug_lockdep_rcu_enabled <-__schedule
          migration/0-6     [000]    50.025820: debug_lockdep_rcu_enabled <-__schedule
    
    The latency format header has latency information that is pretty meaningless
    for most tracers. Although some of the header is useful, and we can add that
    later to the default format as well.
    
    What is really useful with the latency format is the irqs-off, need-resched
    hard/softirq context and the preempt count.
    
    This commit adds the option irq-info which is on by default that adds this
    information:
    
     # tracer: nop
     #
     #                              _-----=> irqs-off
     #                             / _----=> need-resched
     #                            | / _---=> hardirq/softirq
     #                            || / _--=> preempt-depth
     #                            ||| /     delay
     #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
     #              | |       |   ||||       |         |
               <idle>-0     [000] d..2    49.309305: cpuidle_get_driver <-cpuidle_idle_call
               <idle>-0     [000] d..2    49.309307: mwait_idle <-cpu_idle
               <idle>-0     [000] d..2    49.309309: need_resched <-mwait_idle
               <idle>-0     [000] d..2    49.309310: test_ti_thread_flag <-need_resched
               <idle>-0     [000] d..2    49.309312: trace_power_start.constprop.13 <-mwait_idle
               <idle>-0     [000] d..2    49.309313: trace_cpu_idle <-mwait_idle
               <idle>-0     [000] d..2    49.309315: need_resched <-mwait_idle
    
    If a user wants the old format, they can disable the 'irq-info' option:
    
     # tracer: nop
     #
     #           TASK-PID   CPU#      TIMESTAMP  FUNCTION
     #              | |       |          |         |
               <idle>-0     [000]     49.309305: cpuidle_get_driver <-cpuidle_idle_call
               <idle>-0     [000]     49.309307: mwait_idle <-cpu_idle
               <idle>-0     [000]     49.309309: need_resched <-mwait_idle
               <idle>-0     [000]     49.309310: test_ti_thread_flag <-need_resched
               <idle>-0     [000]     49.309312: trace_power_start.constprop.13 <-mwait_idle
               <idle>-0     [000]     49.309313: trace_cpu_idle <-mwait_idle
               <idle>-0     [000]     49.309315: need_resched <-mwait_idle
    
    Requested-by: default avatarThomas Gleixner <tglx@linutronix.de>
    Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
    77271ce4