lkml.org 
[lkml]   [2019]   [Feb]   [20]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    Patch in this message
    /
    Date
    From
    Subject[for-next][PATCH 06/29] tracing: Put a margin between flags and duration for wakeup tracers
    From: Changbin Du <changbin.du@gmail.com>

    Don't mix context flags with function duration info.

    Instead of this:

    # tracer: wakeup_rt
    #
    # wakeup_rt latency trace v1.1.5 on 5.0.0-rc1-test+
    # --------------------------------------------------------------------
    # latency: 177 us, #545/545, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:8)
    # -----------------
    # | task: migration/0-11 (uid:0 nice:0 policy:1 rt_prio:99)
    # -----------------
    #
    # _-----=> irqs-off
    # / _----=> need-resched
    # | / _---=> hardirq/softirq
    # || / _--=> preempt-depth
    # ||| /
    # REL TIME CPU TASK/PID |||| DURATION FUNCTION CALLS
    # | | | | |||| | | | | | |
    0 us | 0) <idle>-0 | dNh5 | /* 0:120:R + [000] 11: 0:R migration/0 */
    2 us | 0) <idle>-0 | dNh5 0.000 us | (null)();
    4 us | 0) <idle>-0 | dNh4 | _raw_spin_unlock() {
    4 us | 0) <idle>-0 | dNh4 0.304 us | preempt_count_sub();
    5 us | 0) <idle>-0 | dNh3 1.063 us | }
    5 us | 0) <idle>-0 | dNh3 0.266 us | ttwu_stat();
    6 us | 0) <idle>-0 | dNh3 | _raw_spin_unlock_irqrestore() {
    6 us | 0) <idle>-0 | dNh3 0.273 us | preempt_count_sub();
    6 us | 0) <idle>-0 | dNh2 0.818 us | }

    Show this:

    # 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)();
    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. | + 11.118 us | __next_timer_interrupt();
    75 us | 0) <idle>-0 | dNs. | | call_timer_fn() {
    76 us | 0) <idle>-0 | dNs. | | delayed_work_timer_fn() {
    76 us | 0) <idle>-0 | dNs. | | __queue_work() {
    ...

    Link: http://lkml.kernel.org/r/20190101154614.8887-4-changbin.du@gmail.com

    Signed-off-by: Changbin Du <changbin.du@gmail.com>
    Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
    ---
    kernel/trace/trace_functions_graph.c | 5 +++--
    1 file changed, 3 insertions(+), 2 deletions(-)

    diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
    index 16ebbdd7b22e..69ebf3c2f1b5 100644
    --- a/kernel/trace/trace_functions_graph.c
    +++ b/kernel/trace/trace_functions_graph.c
    @@ -380,6 +380,7 @@ static void print_graph_lat_fmt(struct trace_seq *s, struct trace_entry *entry)
    {
    trace_seq_putc(s, ' ');
    trace_print_lat_fmt(s, entry);
    + trace_seq_puts(s, " | ");
    }

    /* If the pid changed since the last trace, output this event */
    @@ -1153,7 +1154,7 @@ static void __print_graph_headers_flags(struct trace_array *tr,
    if (flags & TRACE_GRAPH_PRINT_PROC)
    seq_puts(s, " TASK/PID ");
    if (lat)
    - seq_puts(s, "||||");
    + seq_puts(s, "|||| ");
    if (flags & TRACE_GRAPH_PRINT_DURATION)
    seq_puts(s, " DURATION ");
    seq_puts(s, " FUNCTION CALLS\n");
    @@ -1169,7 +1170,7 @@ static void __print_graph_headers_flags(struct trace_array *tr,
    if (flags & TRACE_GRAPH_PRINT_PROC)
    seq_puts(s, " | | ");
    if (lat)
    - seq_puts(s, "||||");
    + seq_puts(s, "|||| ");
    if (flags & TRACE_GRAPH_PRINT_DURATION)
    seq_puts(s, " | | ");
    seq_puts(s, " | | | |\n");
    --
    2.20.1

    \
     
     \ /
      Last update: 2019-02-20 19:40    [W:4.225 / U:0.940 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site