From: Stephen Boyd <sboyd@codeaurora.org>
To: Steven Rostedt <rostedt@goodmis.org>,
Frederic Weisbecker <fweisbec@gmail.com>,
Ingo Molnar <mingo@redhat.com>
Cc: linux-kernel@vger.kernel.org
Subject: [PATCH] tracing: Don't account for cpu idle time with irqsoff tracers
Date: Mon, 19 May 2014 12:30:47 -0700 [thread overview]
Message-ID: <1400527847-28359-1-git-send-email-sboyd@codeaurora.org> (raw)
The idle loop calls stop_critical_timings() in an attempt to stop
the irqsoff tracer from tracing a cpu's idle time. Unfortunately,
stop_critical_timings() doesn't do much besides stop the tracer
until the point that another irqsoff event happens. This typically
happens right after in rcu_idle_enter() or later on in the cpuidle
driver when we take a spinlock to notify the clockevent framework
about timers that lose state during deep idle (FEAT_C3_STOP).
This leads to worthless irqsoff traces that show a large amount
of time spent in idle:
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 3.15.0-rc4-00002-geffda86cfdaa-dirty
# --------------------------------------------------------------------
# latency: 3997988 us, #88/88, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: swapper/1-0 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: rcu_idle_enter
# => ended at: cpuidle_enter_state
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
<idle>-0 1d..1 2us+: trace_hardirqs_off <-rcu_idle_enter
<idle>-0 1d..2 7us+: rcu_eqs_enter_common.isra.48 <-rcu_idle_enter
<idle>-0 1d..2 12us+: cpuidle_enabled <-cpu_startup_entry
<idle>-0 1d..2 17us+: cpuidle_select <-cpu_startup_entry
<idle>-0 1d..2 21us+: menu_select <-cpuidle_select
<idle>-0 1d..2 26us+: pm_qos_request <-menu_select
<idle>-0 1d..2 30us+: tick_nohz_get_sleep_length <-menu_select
<idle>-0 1d..2 34us+: ns_to_timespec <-menu_select
<idle>-0 1d..2 39us+: nr_iowait_cpu <-menu_select
<idle>-0 1d..2 46us+: this_cpu_load <-menu_select
<idle>-0 1d..2 50us+: nr_iowait_cpu <-menu_select
<idle>-0 1d..2 55us+: clockevents_notify <-cpu_startup_entry
<idle>-0 1d..2 59us+: _raw_spin_lock_irqsave <-clockevents_notify
<idle>-0 1d..2 64us+: preempt_count_add <-_raw_spin_lock_irqsave
<idle>-0 1d..3 69us+: do_raw_spin_lock <-_raw_spin_lock_irqsave
<idle>-0 1d..3 74us+: tick_broadcast_oneshot_control <-clockevents_notify
<idle>-0 1d..3 78us+: _raw_spin_lock_irqsave <-tick_broadcast_oneshot_control
<idle>-0 1d..3 83us+: preempt_count_add <-_raw_spin_lock_irqsave
<idle>-0 1d..4 88us+: do_raw_spin_lock <-_raw_spin_lock_irqsave
<idle>-0 1d..4 93us+: clockevents_set_mode <-tick_broadcast_oneshot_control
<idle>-0 1d..4 97us+: arch_timer_set_mode_virt <-clockevents_set_mode
<idle>-0 1d..4 102us+: broadcast_needs_cpu <-tick_broadcast_oneshot_control
<idle>-0 1d..4 106us+: _raw_spin_unlock_irqrestore <-tick_broadcast_oneshot_control
<idle>-0 1d..4 110us+: do_raw_spin_unlock <-_raw_spin_unlock_irqrestore
<idle>-0 1d..4 115us+: preempt_count_sub <-_raw_spin_unlock_irqrestore
<idle>-0 1d..3 120us+: _raw_spin_unlock_irqrestore <-clockevents_notify
<idle>-0 1d..3 124us+: do_raw_spin_unlock <-_raw_spin_unlock_irqrestore
<idle>-0 1d..3 129us+: preempt_count_sub <-_raw_spin_unlock_irqrestore
<idle>-0 1d..2 133us+: cpuidle_enter <-cpu_startup_entry
<idle>-0 1d..2 137us+: cpuidle_enter_state <-cpuidle_enter
<idle>-0 1d..2 141us+: ktime_get <-cpuidle_enter_state
<idle>-0 1d..2 148us+: arch_counter_read <-ktime_get
<idle>-0 1d..2 153us+: cpu_enter_idle <-cpuidle_enter_state
<idle>-0 1d..2 157us+: cpu_pm_enter <-cpu_enter_idle
<idle>-0 1d..2 161us+: _raw_read_lock <-cpu_pm_enter
<idle>-0 1d..2 165us+: preempt_count_add <-_raw_read_lock
<idle>-0 1d..3 170us+: do_raw_read_lock <-_raw_read_lock
<idle>-0 1d..3 175us+: cpu_pm_notify <-cpu_pm_enter
<idle>-0 1d..3 179us+: __raw_notifier_call_chain <-cpu_pm_notify
<idle>-0 1d..3 183us+: notifier_call_chain <-__raw_notifier_call_chain
<idle>-0 1d..3 187us+: gic_notifier <-notifier_call_chain
<idle>-0 1d..3 192us+: arch_timer_cpu_pm_notify <-notifier_call_chain
<idle>-0 1d..3 197us+: vfp_cpu_pm_notifier <-notifier_call_chain
<idle>-0 1d..3 201us+: dbg_cpu_pm_notify <-notifier_call_chain
<idle>-0 1d..3 206us+: _raw_read_unlock <-cpu_pm_enter
<idle>-0 1d..3 210us+: do_raw_read_unlock <-_raw_read_unlock
<idle>-0 1d..3 214us!: preempt_count_sub <-_raw_read_unlock
<idle>-0 1d..2 3997820us+: cpu_pm_exit <-cpu_enter_idle
<idle>-0 1d..2 3997824us+: _raw_read_lock <-cpu_pm_exit
<idle>-0 1d..2 3997828us+: preempt_count_add <-_raw_read_lock
<idle>-0 1d..3 3997833us+: do_raw_read_lock <-_raw_read_lock
<idle>-0 1d..3 3997838us+: cpu_pm_notify <-cpu_pm_exit
<idle>-0 1d..3 3997842us+: __raw_notifier_call_chain <-cpu_pm_notify
<idle>-0 1d..3 3997846us+: notifier_call_chain <-__raw_notifier_call_chain
<idle>-0 1d..3 3997850us+: gic_notifier <-notifier_call_chain
<idle>-0 1d..3 3997856us+: arch_timer_cpu_pm_notify <-notifier_call_chain
<idle>-0 1d..3 3997860us+: vfp_cpu_pm_notifier <-notifier_call_chain
<idle>-0 1d..3 3997865us+: vfp_enable <-vfp_cpu_pm_notifier
<idle>-0 1d..3 3997869us+: dbg_cpu_pm_notify <-notifier_call_chain
<idle>-0 1d..3 3997873us+: reset_ctrl_regs <-dbg_cpu_pm_notify
<idle>-0 1d..3 3997877us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997882us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997886us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997890us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997894us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997898us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997902us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997906us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997910us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997915us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997919us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997923us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997927us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997931us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997936us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997940us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997944us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997948us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997952us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997956us+: write_wb_reg <-reset_ctrl_regs
<idle>-0 1d..3 3997960us+: _raw_read_unlock <-cpu_pm_exit
<idle>-0 1d..3 3997965us+: do_raw_read_unlock <-_raw_read_unlock
<idle>-0 1d..3 3997969us+: preempt_count_sub <-_raw_read_unlock
<idle>-0 1d..2 3997973us+: ktime_get <-cpuidle_enter_state
<idle>-0 1d..2 3997980us+: arch_counter_read <-ktime_get
<idle>-0 1d..1 3997985us+: trace_hardirqs_on <-cpuidle_enter_state
<idle>-0 1d..1 3997994us+: time_hardirqs_on <-cpuidle_enter_state
<idle>-0 1d..1 3998053us : <stack trace>
=> time_hardirqs_on
=> trace_hardirqs_on_caller
=> trace_hardirqs_on
=> cpuidle_enter_state
=> cpuidle_enter
=> cpu_startup_entry
=> secondary_start_kernel
Let's make stop_critical_timings() actually stop the tracer until
start_critical_timings() is called. This way we don't have to
worry about adding more stop_critical_timings() calls deep down
in cpuidle drivers or later on in the idle loop.
Signed-off-by: Stephen Boyd <sboyd@codeaurora.org>
---
kernel/trace/trace_irqsoff.c | 20 ++++++++++++++------
1 file changed, 14 insertions(+), 6 deletions(-)
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 8ff02cbb892f..ea5f5d484150 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -367,6 +367,8 @@ out:
__trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc);
}
+static DEFINE_PER_CPU(bool, timings_stopped);
+
static inline void
start_critical_timing(unsigned long ip, unsigned long parent_ip)
{
@@ -375,11 +377,12 @@ start_critical_timing(unsigned long ip, unsigned long parent_ip)
struct trace_array_cpu *data;
unsigned long flags;
- if (!tracer_enabled || !tracing_is_enabled())
- return;
-
cpu = raw_smp_processor_id();
+ if (!tracer_enabled || !tracing_is_enabled() ||
+ per_cpu(timings_stopped, cpu))
+ return;
+
if (per_cpu(tracing_cpu, cpu))
return;
@@ -418,7 +421,8 @@ stop_critical_timing(unsigned long ip, unsigned long parent_ip)
else
return;
- if (!tracer_enabled || !tracing_is_enabled())
+ if (!tracer_enabled || !tracing_is_enabled() ||
+ per_cpu(timings_stopped, cpu))
return;
data = per_cpu_ptr(tr->trace_buffer.data, cpu);
@@ -439,15 +443,19 @@ stop_critical_timing(unsigned long ip, unsigned long parent_ip)
/* start and stop critical timings used to for stoppage (in idle) */
void start_critical_timings(void)
{
- if (preempt_trace() || irq_trace())
+ if (preempt_trace() || irq_trace()) {
+ per_cpu(timings_stopped, raw_smp_processor_id()) = false;
start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
+ }
}
EXPORT_SYMBOL_GPL(start_critical_timings);
void stop_critical_timings(void)
{
- if (preempt_trace() || irq_trace())
+ if (preempt_trace() || irq_trace()) {
stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
+ per_cpu(timings_stopped, raw_smp_processor_id()) = true;
+ }
}
EXPORT_SYMBOL_GPL(stop_critical_timings);
--
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
hosted by The Linux Foundation
next reply other threads:[~2014-05-19 19:30 UTC|newest]
Thread overview: 5+ messages / expand[flat|nested] mbox.gz Atom feed top
2014-05-19 19:30 Stephen Boyd [this message]
2014-05-27 18:05 ` [PATCH] tracing: Don't account for cpu idle time with irqsoff tracers Stephen Boyd
2014-05-27 18:23 ` Steven Rostedt
2014-05-27 19:13 ` Steven Rostedt
2014-05-27 19:26 ` Stephen Boyd
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=1400527847-28359-1-git-send-email-sboyd@codeaurora.org \
--to=sboyd@codeaurora.org \
--cc=fweisbec@gmail.com \
--cc=linux-kernel@vger.kernel.org \
--cc=mingo@redhat.com \
--cc=rostedt@goodmis.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 an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.