Re: [PATCH 0/5] Improve the latency tracers

[Changbin Du]

Hi Steven, Have you checked this serias yet? :)

On Tue, Jan 01, 2019 at 11:46:09PM +0800, Changbin Du wrote:
> Happy new year!
> 
> This series make some improments for the kernel latency tracers, especilly
> for the wakeup tracers. The latency tracers will show us more useful
> information. With this series, the wakeup tracers look like this
> when display-graph is enabled:
> 
> # tracer: wakeup
> #
> # wakeup latency trace v1.1.5 on 4.20.0+
> # --------------------------------------------------------------------
> # latency: 593 us, #674/674, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
> #    -----------------
> #    | task: kworker/0:1H-339 (uid:0 nice:-20 policy:0 rt_prio:0)
> #    -----------------
> #
> #                                       _-----=> irqs-off        
> #                                      / _----=> need-resched    
> #                                     | / _---=> hardirq/softirq 
> #                                     || / _--=> preempt-depth   
> #                                     ||| /                      
> #   REL TIME      CPU  TASK/PID       ||||     DURATION                  FUNCTION CALLS
> #      |          |     |    |        ||||      |   |                     |   |   |   |
>         0 us |   0)    <idle>-0    |  dNs. |               |  /*      0:120:R   + [000]   339:100:R kworker/0:1H */
>         3 us |   0)    <idle>-0    |  dNs. |   0.000 us    |            (null)();
>   <idle>-0       0dNs.   66us : <stack trace>
>  => try_to_wake_up
>  => __queue_work
>  => queue_work_on
>  => call_timer_fn
>  => run_timer_softirq
>  => __do_softirq
>  => irq_exit
>  => smp_apic_timer_interrupt
>  => apic_timer_interrupt
>  => native_safe_halt
>  => default_idle
>  => default_idle_call
>  => do_idle
>  => cpu_startup_entry
>  => start_kernel
>  => secondary_startup_64
>        67 us |   0)    <idle>-0    |  dNs. |   0.721 us    |  ttwu_stat();
>        69 us |   0)    <idle>-0    |  dNs. |   0.607 us    |  _raw_spin_unlock_irqrestore();
>        71 us |   0)    <idle>-0    |  .Ns. |   0.598 us    |  _raw_spin_lock_irq();
>        72 us |   0)    <idle>-0    |  .Ns. |   0.584 us    |  _raw_spin_lock_irq();
>        73 us |   0)    <idle>-0    |  dNs. |   1.125 us    |  __next_timer_interrupt();
>        75 us |   0)    <idle>-0    |  dNs. |               |  call_timer_fn() {
>        76 us |   0)    <idle>-0    |  dNs. |               |    delayed_work_timer_fn() {
>       [...]
>       564 us |   0)   kworker-13   |  d... |               |      set_next_entity() {
>       565 us |   0)   kworker-13   |  d... |   0.524 us    |        __update_load_avg_se();
>       566 us |   0)   kworker-13   |  d... |   0.562 us    |        __update_load_avg_cfs_rq();
>       567 us |   0)   kworker-13   |  d... |   2.765 us    |      }
>       568 us |   0)   kworker-13   |  d... | + 10.077 us   |    }
>       569 us |   0)   kworker-13   |  d... |   0.000 us    |  __schedule();
> kworker/-13      0d...  593us : <stack trace>
>  => schedule
>  => worker_thread
>  => kthread
>  => ret_from_fork
>       593 us |   0)   kworker-13   |  d... |               |  /*     13:120:I ==> [000]   339:100:R kworker/0:1H */
> 
> Changbin Du (5):
>   function_graph: Support displaying relative timestamp
>   sched/tracing: Show more info for funcgraph wakeup tracers
>   sched/tracing: Put a margin between flags and duration for wakeup
>     tracers
>   sched/tracing: Show stacktrace for wakeup tracers
>   trace/doc: Add latency tracer funcgraph example
> 
>  Documentation/trace/ftrace.rst       | 51 ++++++++++++++++++++++++++++
>  kernel/trace/trace.h                 |  9 ++---
>  kernel/trace/trace_functions_graph.c | 30 ++++++++++++++--
>  kernel/trace/trace_irqsoff.c         |  2 +-
>  kernel/trace/trace_sched_wakeup.c    | 11 ++++--
>  5 files changed, 94 insertions(+), 9 deletions(-)
> 
> -- 
> 2.17.1
> 

-- 
Cheers,
Changbin Du