From afbab501c66bece057bc30656f71f856cd1b3baa Mon Sep 17 00:00:00 2001 From: Changbin Du Date: Tue, 1 Jan 2019 23:46:12 +0800 Subject: [PATCH] tracing: Put a margin between flags and duration for wakeup tracers 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) -0 | dNh5 | /* 0:120:R + [000] 11: 0:R migration/0 */ 2 us | 0) -0 | dNh5 0.000 us | (null)(); 4 us | 0) -0 | dNh4 | _raw_spin_unlock() { 4 us | 0) -0 | dNh4 0.304 us | preempt_count_sub(); 5 us | 0) -0 | dNh3 1.063 us | } 5 us | 0) -0 | dNh3 0.266 us | ttwu_stat(); 6 us | 0) -0 | dNh3 | _raw_spin_unlock_irqrestore() { 6 us | 0) -0 | dNh3 0.273 us | preempt_count_sub(); 6 us | 0) -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) -0 | dNs. | | /* 0:120:R + [000] 339:100:R kworker/0:1H */ 3 us | 0) -0 | dNs. | 0.000 us | (null)(); 67 us | 0) -0 | dNs. | 0.721 us | ttwu_stat(); 69 us | 0) -0 | dNs. | 0.607 us | _raw_spin_unlock_irqrestore(); 71 us | 0) -0 | .Ns. | 0.598 us | _raw_spin_lock_irq(); 72 us | 0) -0 | .Ns. | 0.584 us | _raw_spin_lock_irq(); 73 us | 0) -0 | dNs. | + 11.118 us | __next_timer_interrupt(); 75 us | 0) -0 | dNs. | | call_timer_fn() { 76 us | 0) -0 | dNs. | | delayed_work_timer_fn() { 76 us | 0) -0 | dNs. | | __queue_work() { ... Link: http://lkml.kernel.org/r/20190101154614.8887-4-changbin.du@gmail.com Signed-off-by: Changbin Du Signed-off-by: Steven Rostedt (VMware) --- 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");