public inbox for linux-kernel@vger.kernel.org
 help / color / mirror / Atom feed
From: Steven Rostedt <rostedt@goodmis.org>
To: linux-kernel@vger.kernel.org
Cc: Ingo Molnar <mingo@kernel.org>,
	Andrew Morton <akpm@linux-foundation.org>,
	Changbin Du <changbin.du@gmail.com>
Subject: [for-next][PATCH 06/29] tracing: Put a margin between flags and duration for wakeup tracers
Date: Wed, 20 Feb 2019 13:37:43 -0500	[thread overview]
Message-ID: <20190220183803.719429618@goodmis.org> (raw)
In-Reply-To: 20190220183737.034634614@goodmis.org

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



  parent reply	other threads:[~2019-02-20 18:39 UTC|newest]

Thread overview: 32+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2019-02-20 18:37 [for-next][PATCH 00/29] tracing: Updates for 5.1 Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 01/29] function_graph: Support displaying relative timestamp Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 02/29] tracing: Annotate implicit fall through in parse_probe_arg() Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 03/29] tracing: Annotate implicit fall through in predicate_parse() Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 04/29] tracing: Add comment to predicate_parse() about "&&" or "||" Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 05/29] tracing: Show more info for funcgraph wakeup tracers Steven Rostedt
2019-02-20 18:37 ` Steven Rostedt [this message]
2019-02-20 18:37 ` [for-next][PATCH 07/29] tracing/doc: Add latency tracer funcgraph example Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 08/29] tracing: Show stacktrace for wakeup tracers Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 09/29] ring-buffer: Remove unused function ring_buffer_page_len() Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 10/29] tracing: Change the function format to display function names by perf Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 11/29] ftrace: Allow enabling of filters via index of available_filter_functions Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 12/29] uprobes: convert uprobe.ref to refcount_t Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 13/29] tracing: No need to free iter->trace in fail path of tracing_open_pipe() Steven Rostedt
2019-02-20 18:46   ` Steven Rostedt
2019-02-20 18:50     ` Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 14/29] tracing: Refactor hist trigger action code Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 15/29] tracing: Make hist trigger Documentation better reflect actions/handlers Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 16/29] tracing: Split up onmatch action data Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 17/29] tracing: Generalize hist trigger onmax and save action Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 18/29] tracing: Add conditional snapshot Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 19/29] tracing: Add hist trigger snapshot() action Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 20/29] tracing: Add hist trigger snapshot() action Documentation Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 21/29] tracing: Add hist trigger onchange() handler Steven Rostedt
2019-02-20 18:37 ` [for-next][PATCH 22/29] tracing: Add hist trigger onchange() handler Documentation Steven Rostedt
2019-02-20 18:38 ` [for-next][PATCH 23/29] tracing: Add alternative synthetic event trace action syntax Steven Rostedt
2019-02-20 18:38 ` [for-next][PATCH 24/29] tracing: Add SPDX license GPL-2.0 license identifier to inter-event testcases Steven Rostedt
2019-02-20 18:38 ` [for-next][PATCH 25/29] tracing: Add hist trigger snapshot() action test case Steven Rostedt
2019-02-20 18:38 ` [for-next][PATCH 26/29] tracing: Add hist trigger onchange() handler " Steven Rostedt
2019-02-20 18:38 ` [for-next][PATCH 27/29] tracing: Add alternative synthetic event trace action " Steven Rostedt
2019-02-20 18:38 ` [for-next][PATCH 28/29] tracing: Add hist trigger action expected fail " Steven Rostedt
2019-02-20 18:38 ` [for-next][PATCH 29/29] tracing: Comment why cond_snapshot is checked outside of max_lock protection Steven Rostedt

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=20190220183803.719429618@goodmis.org \
    --to=rostedt@goodmis.org \
    --cc=akpm@linux-foundation.org \
    --cc=changbin.du@gmail.com \
    --cc=linux-kernel@vger.kernel.org \
    --cc=mingo@kernel.org \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox