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
