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 01/29] function_graph: Support displaying relative timestamp
Date: Wed, 20 Feb 2019 13:37:38 -0500 [thread overview]
Message-ID: <20190220183802.911843633@goodmis.org> (raw)
In-Reply-To: 20190220183737.034634614@goodmis.org
From: Changbin Du <changbin.du@gmail.com>
When function_graph is used for latency tracers, relative timestamp
is more straightforward than absolute timestamp as function trace
does. This change adds relative timestamp support to function_graph
and applies to latency tracers (wakeup and irqsoff).
Instead of:
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 5.0.0-rc1-test
# --------------------------------------------------------------------
# latency: 521 us, #1125/1125, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:8)
# -----------------
# | task: swapper/2-0 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: __schedule
# => ended at: _raw_spin_unlock_irq
#
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| /
# TIME CPU TASK/PID |||| DURATION FUNCTION CALLS
# | | | | |||| | | | | | |
124.974306 | 2) systemd-693 | d..1 0.000 us | __schedule();
124.974307 | 2) systemd-693 | d..1 | rcu_note_context_switch() {
124.974308 | 2) systemd-693 | d..1 0.487 us | rcu_preempt_deferred_qs();
124.974309 | 2) systemd-693 | d..1 0.451 us | rcu_qs();
124.974310 | 2) systemd-693 | d..1 2.301 us | }
[..]
124.974826 | 2) <idle>-0 | d..2 | finish_task_switch() {
124.974826 | 2) <idle>-0 | d..2 | _raw_spin_unlock_irq() {
124.974827 | 2) <idle>-0 | d..2 0.000 us | _raw_spin_unlock_irq();
124.974828 | 2) <idle>-0 | d..2 0.000 us | tracer_hardirqs_on();
<idle>-0 2d..2 552us : <stack trace>
=> __schedule
=> schedule_idle
=> do_idle
=> cpu_startup_entry
=> start_secondary
=> secondary_startup_64
Show:
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 5.0.0-rc1-test+
# --------------------------------------------------------------------
# latency: 511 us, #1053/1053, CPU#7 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:8)
# -----------------
# | task: swapper/7-0 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: __schedule
# => ended at: _raw_spin_unlock_irq
#
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| /
# REL TIME CPU TASK/PID |||| DURATION FUNCTION CALLS
# | | | | |||| | | | | | |
0 us | 7) sshd-1704 | d..1 0.000 us | __schedule();
1 us | 7) sshd-1704 | d..1 | rcu_note_context_switch() {
1 us | 7) sshd-1704 | d..1 0.611 us | rcu_preempt_deferred_qs();
2 us | 7) sshd-1704 | d..1 0.484 us | rcu_qs();
3 us | 7) sshd-1704 | d..1 2.599 us | }
[..]
509 us | 7) <idle>-0 | d..2 | finish_task_switch() {
510 us | 7) <idle>-0 | d..2 | _raw_spin_unlock_irq() {
510 us | 7) <idle>-0 | d..2 0.000 us | _raw_spin_unlock_irq();
512 us | 7) <idle>-0 | d..2 0.000 us | tracer_hardirqs_on();
<idle>-0 7d..2 543us : <stack trace>
=> __schedule
=> schedule_idle
=> do_idle
=> cpu_startup_entry
=> start_secondary
=> secondary_startup_64
Link: http://lkml.kernel.org/r/20190101154614.8887-2-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.h | 9 +++++----
kernel/trace/trace_functions_graph.c | 25 +++++++++++++++++++++++++
kernel/trace/trace_irqsoff.c | 2 +-
kernel/trace/trace_sched_wakeup.c | 2 +-
4 files changed, 32 insertions(+), 6 deletions(-)
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 08900828d282..a34fa5e76abb 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -855,10 +855,11 @@ static __always_inline bool ftrace_hash_empty(struct ftrace_hash *hash)
#define TRACE_GRAPH_PRINT_PROC 0x8
#define TRACE_GRAPH_PRINT_DURATION 0x10
#define TRACE_GRAPH_PRINT_ABS_TIME 0x20
-#define TRACE_GRAPH_PRINT_IRQS 0x40
-#define TRACE_GRAPH_PRINT_TAIL 0x80
-#define TRACE_GRAPH_SLEEP_TIME 0x100
-#define TRACE_GRAPH_GRAPH_TIME 0x200
+#define TRACE_GRAPH_PRINT_REL_TIME 0x40
+#define TRACE_GRAPH_PRINT_IRQS 0x80
+#define TRACE_GRAPH_PRINT_TAIL 0x100
+#define TRACE_GRAPH_SLEEP_TIME 0x200
+#define TRACE_GRAPH_GRAPH_TIME 0x400
#define TRACE_GRAPH_PRINT_FILL_SHIFT 28
#define TRACE_GRAPH_PRINT_FILL_MASK (0x3 << TRACE_GRAPH_PRINT_FILL_SHIFT)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index c2af1560e856..16ebbdd7b22e 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -500,6 +500,17 @@ static void print_graph_abs_time(u64 t, struct trace_seq *s)
(unsigned long)t, usecs_rem);
}
+static void
+print_graph_rel_time(struct trace_iterator *iter, struct trace_seq *s)
+{
+ unsigned long long usecs;
+
+ usecs = iter->ts - iter->trace_buffer->time_start;
+ do_div(usecs, NSEC_PER_USEC);
+
+ trace_seq_printf(s, "%9llu us | ", usecs);
+}
+
static void
print_graph_irq(struct trace_iterator *iter, unsigned long addr,
enum trace_type type, int cpu, pid_t pid, u32 flags)
@@ -517,6 +528,10 @@ print_graph_irq(struct trace_iterator *iter, unsigned long addr,
if (flags & TRACE_GRAPH_PRINT_ABS_TIME)
print_graph_abs_time(iter->ts, s);
+ /* Relative time */
+ if (flags & TRACE_GRAPH_PRINT_REL_TIME)
+ print_graph_rel_time(iter, s);
+
/* Cpu */
if (flags & TRACE_GRAPH_PRINT_CPU)
print_graph_cpu(s, cpu);
@@ -725,6 +740,10 @@ print_graph_prologue(struct trace_iterator *iter, struct trace_seq *s,
if (flags & TRACE_GRAPH_PRINT_ABS_TIME)
print_graph_abs_time(iter->ts, s);
+ /* Relative time */
+ if (flags & TRACE_GRAPH_PRINT_REL_TIME)
+ print_graph_rel_time(iter, s);
+
/* Cpu */
if (flags & TRACE_GRAPH_PRINT_CPU)
print_graph_cpu(s, cpu);
@@ -1101,6 +1120,8 @@ static void print_lat_header(struct seq_file *s, u32 flags)
if (flags & TRACE_GRAPH_PRINT_ABS_TIME)
size += 16;
+ if (flags & TRACE_GRAPH_PRINT_REL_TIME)
+ size += 16;
if (flags & TRACE_GRAPH_PRINT_CPU)
size += 4;
if (flags & TRACE_GRAPH_PRINT_PROC)
@@ -1125,6 +1146,8 @@ static void __print_graph_headers_flags(struct trace_array *tr,
seq_putc(s, '#');
if (flags & TRACE_GRAPH_PRINT_ABS_TIME)
seq_puts(s, " TIME ");
+ if (flags & TRACE_GRAPH_PRINT_REL_TIME)
+ seq_puts(s, " REL TIME ");
if (flags & TRACE_GRAPH_PRINT_CPU)
seq_puts(s, " CPU");
if (flags & TRACE_GRAPH_PRINT_PROC)
@@ -1139,6 +1162,8 @@ static void __print_graph_headers_flags(struct trace_array *tr,
seq_putc(s, '#');
if (flags & TRACE_GRAPH_PRINT_ABS_TIME)
seq_puts(s, " | ");
+ if (flags & TRACE_GRAPH_PRINT_REL_TIME)
+ seq_puts(s, " | ");
if (flags & TRACE_GRAPH_PRINT_CPU)
seq_puts(s, " | ");
if (flags & TRACE_GRAPH_PRINT_PROC)
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index d3294721f119..e6a62e7c6b69 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -238,7 +238,7 @@ static void irqsoff_trace_close(struct trace_iterator *iter)
#define GRAPH_TRACER_FLAGS (TRACE_GRAPH_PRINT_CPU | \
TRACE_GRAPH_PRINT_PROC | \
- TRACE_GRAPH_PRINT_ABS_TIME | \
+ TRACE_GRAPH_PRINT_REL_TIME | \
TRACE_GRAPH_PRINT_DURATION)
static enum print_line_t irqsoff_print_line(struct trace_iterator *iter)
diff --git a/kernel/trace/trace_sched_wakeup.c b/kernel/trace/trace_sched_wakeup.c
index 4ea7e6845efb..b6c5fa10347e 100644
--- a/kernel/trace/trace_sched_wakeup.c
+++ b/kernel/trace/trace_sched_wakeup.c
@@ -180,7 +180,7 @@ static void wakeup_trace_close(struct trace_iterator *iter)
}
#define GRAPH_TRACER_FLAGS (TRACE_GRAPH_PRINT_PROC | \
- TRACE_GRAPH_PRINT_ABS_TIME | \
+ TRACE_GRAPH_PRINT_REL_TIME | \
TRACE_GRAPH_PRINT_DURATION)
static enum print_line_t wakeup_print_line(struct trace_iterator *iter)
--
2.20.1
next prev parent reply other threads:[~2019-02-20 18:40 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 ` Steven Rostedt [this message]
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 ` [for-next][PATCH 06/29] tracing: Put a margin between flags and duration for " Steven Rostedt
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=20190220183802.911843633@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