Fixed
Created: Mar 4, 2015
Updated: Dec 3, 2018
Resolved Date: Mar 20, 2015
Found In Version: 6.0.0.16
Fix Version: 6.0.0.19
Severity: Standard
Applicable for: Wind River Linux 6
Component/s: Kernel
Request following patch be included in next RCPL:
commit 4373737360ac6aee8baffab874af175f7964e1ae
Author: Fredrik Markstrom <fredrik.markstrom@gmail.com>
Date: Tue Mar 3 14:09:40 2015 +0100
kernel: Fix for irqsoff tracer measuring time in idle/wfi
rcu_idle_enter() restarts critical timing since it's enabling/disabling interrupts. So in
order for the irqsoff tracer not to measure the time spent waiting for an interrupt in
armv7 idle we disable critical timing after the call to rcu_idle_enter() instead of before.
Signed-off-by: Fredrik Markstrom <fredrik.markstrom@gmail.com>
diff --git a/kernel/cpu/idle.c b/kernel/cpu/idle.c
index c261409..9de9d6e 100644
--- a/kernel/cpu/idle.c
+++ b/kernel/cpu/idle.c
@@ -93,8 +93,8 @@ static void cpu_idle_loop(void)
cpu_idle_poll();
} else {
if (!current_clr_polling_and_test()) {
- stop_critical_timings();
rcu_idle_enter();
+ stop_critical_timings();
arch_cpu_idle();
WARN_ON_ONCE(irqs_disabled());
rcu_idle_exit();
Before
root@axm5516:/sys/kernel/debug/tracing# echo irqsoff > current_tracer
root@axm5516:/sys/kernel/debug/tracing# echo 1 > tracing_on
root@axm5516:/sys/kernel/debug/tracing# cat trace
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 3.10.55-ltsi-rt55-10371-g6e096e0-dirty
# --------------------------------------------------------------------
# latency: 9979 us, #4/4, CPU#5 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:8)
# -----------------
# | task: swapper/5-0 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: rcu_idle_enter
# => ended at: arch_cpu_idle
#
#
# _--------=> CPU#
# / _-------=> irqs-off
# | / _------=> need-resched
# || / _-----=> need-resched_lazy
# ||| / _----=> hardirq/softirq
# |||| / _---=> preempt-depth
# ||||| / _--=> preempt-lazy-depth
# |||||| / _-=> migrate-disable
# ||||||| / delay
# cmd pid |||||||| time | caller
# \ / |||||||| \ | /
<idle>-0 5d...1.. 0us!: rcu_idle_enter <-rcu_idle_enter
<idle>-0 5d...1.. 9979us+: arch_cpu_idle <-arch_cpu_idle
<idle>-0 5d...1.. 9981us+: time_hardirqs_on <-arch_cpu_idle
<idle>-0 5d...1.. 9990us : <stack trace>
After
root@axm5516:/sys/kernel/debug/tracing# cat trace
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 3.10.55-ltsi-rt55-10371-g6e096e0-dirty
# --------------------------------------------------------------------
# latency: 583 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:8)
# -----------------
# | task: kworker/0:0-4 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: _raw_spin_lock_irqsave
# => ended at: _raw_spin_unlock_irqrestore
#
#
# _--------=> CPU#
# / _-------=> irqs-off
# | / _------=> need-resched
# || / _-----=> need-resched_lazy
# ||| / _----=> hardirq/softirq
# |||| / _---=> preempt-depth
# ||||| / _--=> preempt-lazy-depth
# |||||| / _-=> migrate-disable
# ||||||| / delay
# cmd pid |||||||| time | caller
# \ / |||||||| \ | /
kworker/-4 0d...113 0us!: _raw_spin_lock_irqsave <-_raw_spin_lock_irqsave
kworker/-4 0d...213 583us!: _raw_spin_unlock_irqrestore <-_raw_spin_unlock_irqrestore
kworker/-4 0d...213 728us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore
kworker/-4 0d...213 736us : <stack trace>
=> try_to_wake_up
=> wakeup_next_waiter
=> __rt_spin_lock_slowunlock
=> mod_timer
=> queue_delayed_work_on
=> process_one_work
=> worker_thread
=> kthread
=> ret_from_fork
