RT throttling and suspend/resume (was Re: [PATCH] i2c: omap: revert "i2c: omap: switch to threaded IRQ support")

Felipe Balbi [off-list ref] writes:

On Wed, Oct 17, 2012 at 05:00:02PM +0300, Felipe Balbi wrote:

quoted

On Tue, Oct 16, 2012 at 02:39:50PM -0700, Kevin Hilman wrote:

quoted

+ peterz, tglx

Felipe Balbi [off-list ref] writes:

[...]

quoted

The problem I see is that even though we properly return IRQ_WAKE_THREAD
and wake_up_process() manages to wakeup the IRQ thread (it returns 1),
the thread is never scheduled. To make things even worse, ouw irq thread
runs once, but doesn't run on a consecutive call. Here's some (rather
nasty) debug prints showing the problem:

[...]

quoted

quoted

[   88.721923] try_to_wake_up 1411
[   88.725189] ===> irq_wake_thread 139: IRQ 72 wake_up_process 0
[   88.731292] [sched_delayed] sched: RT throttling activated

This throttling message is the key one.

With RT throttling activated, the IRQ thread will not be run (it
eventually will be allowed much later on, but by then, the I2C xfers
have timed out.)

As a quick hack, the throttling can be disabled by seeting the
sched_rt_runtime to RUNTIME_INF:

        # sysctl -w kernel.sched_rt_runtime_us=-1

and a quick test shows that things go back to working as expected.  But
we still need to figure out why the throttling is hapenning...

So I started digging into why the RT runtime was so high, and noticed
that time spent in suspend was being counted as RT runtime!

So spending time in suspend anywhere near sched_rt_runtime (0.95s) will
cause the RT throttling to always be triggered, and thus prevent IRQ
threads from running in the resume path.  Ouch.

I think I'm already in over my head in the RT runtime stuff, but
counting the time spent in suspend as RT runtime smells like a bug to
me. no?

Peter? Thomas?

it looks like removing console output completely (echo 0 >
/proc/sysrq-trigger) I don't see the issue anymore. Let me just run for
a few more iterations to make sure what I'm saying is correct.

Yeah, really looks like removing console output makes the problem go
away. Ran a few iterations and it always worked fine. Full logs attached

Removing console output during resume is going to significantly change
the timing of what is happening during suspend/resume, so I suspect that
combined with all your other debug prints is somehow masking the
problem.  How log are you letting the system stay in suspend?

That being said, I can still easily reproduce the problem, even with
console output disabled.

With vanilla v3.7-rc1 + the debug patch below[1], with and without
console output, I see RT throttling kicking in on resume, and the RT
runtime on resume corresponds to the time spent in suspend.  Here's an
example of debug output of my patch below after ~3 sec in suspend:

[   43.198028] sched_rt_runtime_exceeded: rt_time 2671752930 > runtime 950000000
[   43.198028] update_curr_rt: RT runtime exceeded: irq/72-omap_i2c
[   43.198059] update_curr_rt: RT runtime exceeded: irq/72-omap_i2c
[   43.203704] [sched_delayed] sched: RT throttling activated

I see this rather consistently, and the rt_time value is always roughly the
time I spent in suspend.

So the primary question remains: is RT runtime supposed to include the
time spent suspended?  I suspect not. 

Kevin

[1]

diff --git a/kernel/sched/rt.c b/kernel/sched/rt.c
index 418feb0..39de750 100644
--- a/kernel/sched/rt.c
+++ b/kernel/sched/rt.c

@@ -891,6 +891,8 @@ static int sched_rt_runtime_exceeded(struct rt_rq *rt_rq)
 			if (!once) {
 				once = true;
 				printk_sched("sched: RT throttling activated\n");
+				pr_warn("%s: rt_time %llu > runtime %llu\n",
+					__func__, rt_rq->rt_time, runtime);
 			}
 		} else {
 			/*

@@ -948,8 +950,11 @@ static void update_curr_rt(struct rq *rq)
 		if (sched_rt_runtime(rt_rq) != RUNTIME_INF) {
 			raw_spin_lock(&rt_rq->rt_runtime_lock);
 			rt_rq->rt_time += delta_exec;
-			if (sched_rt_runtime_exceeded(rt_rq))
+			if (sched_rt_runtime_exceeded(rt_rq)) {
+				pr_warn("%s: RT runtime exceeded: %s\n",
+					__func__, curr->comm);
 				resched_task(curr);
+			}
 			raw_spin_unlock(&rt_rq->rt_runtime_lock);
 		}
 	}

On Wed, Oct 17, 2012 at 04:06:54PM -0700, Kevin Hilman wrote:

Felipe Balbi [off-list ref] writes:

quoted

On Wed, Oct 17, 2012 at 05:00:02PM +0300, Felipe Balbi wrote:

quoted

On Tue, Oct 16, 2012 at 02:39:50PM -0700, Kevin Hilman wrote:

quoted

+ peterz, tglx

Felipe Balbi [off-list ref] writes:

[...]

quoted

The problem I see is that even though we properly return IRQ_WAKE_THREAD
and wake_up_process() manages to wakeup the IRQ thread (it returns 1),
the thread is never scheduled. To make things even worse, ouw irq thread
runs once, but doesn't run on a consecutive call. Here's some (rather
nasty) debug prints showing the problem:

[...]

quoted

quoted

[   88.721923] try_to_wake_up 1411
[   88.725189] ===> irq_wake_thread 139: IRQ 72 wake_up_process 0
[   88.731292] [sched_delayed] sched: RT throttling activated

This throttling message is the key one.

With RT throttling activated, the IRQ thread will not be run (it
eventually will be allowed much later on, but by then, the I2C xfers
have timed out.)

As a quick hack, the throttling can be disabled by seeting the
sched_rt_runtime to RUNTIME_INF:

        # sysctl -w kernel.sched_rt_runtime_us=-1

and a quick test shows that things go back to working as expected.  But
we still need to figure out why the throttling is hapenning...

So I started digging into why the RT runtime was so high, and noticed
that time spent in suspend was being counted as RT runtime!

So spending time in suspend anywhere near sched_rt_runtime (0.95s) will
cause the RT throttling to always be triggered, and thus prevent IRQ
threads from running in the resume path.  Ouch.

I think I'm already in over my head in the RT runtime stuff, but
counting the time spent in suspend as RT runtime smells like a bug to
me. no?

Peter? Thomas?

it looks like removing console output completely (echo 0 >
/proc/sysrq-trigger) I don't see the issue anymore. Let me just run for
a few more iterations to make sure what I'm saying is correct.

Yeah, really looks like removing console output makes the problem go
away. Ran a few iterations and it always worked fine. Full logs attached

Removing console output during resume is going to significantly change
the timing of what is happening during suspend/resume, so I suspect that
combined with all your other debug prints is somehow masking the
problem.  How log are you letting the system stay in suspend?

about 2 minutes

That being said, I can still easily reproduce the problem, even with
console output disabled.

With vanilla v3.7-rc1 + the debug patch below[1], with and without
console output, I see RT throttling kicking in on resume, and the RT
runtime on resume corresponds to the time spent in suspend.  Here's an
example of debug output of my patch below after ~3 sec in suspend:

[   43.198028] sched_rt_runtime_exceeded: rt_time 2671752930 > runtime 950000000
[   43.198028] update_curr_rt: RT runtime exceeded: irq/72-omap_i2c
[   43.198059] update_curr_rt: RT runtime exceeded: irq/72-omap_i2c
[   43.203704] [sched_delayed] sched: RT throttling activated

I see this rather consistently, and the rt_time value is always roughly the
time I spent in suspend.

So the primary question remains: is RT runtime supposed to include the
time spent suspended?  I suspect not. 

you might be right there, though we need Thomas or Peter to answer :-s

-- 
balbi
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 836 bytes
Desc: Digital signature
URL: <http://lists.infradead.org/pipermail/linux-arm-kernel/attachments/20121018/033fbaef/attachment.sig>

On Thu, 2012-10-18 at 08:51 +0300, Felipe Balbi wrote:

quoted

So the primary question remains: is RT runtime supposed to include the
time spent suspended?  I suspect not. 

you might be right there, though we need Thomas or Peter to answer :-s 

re, sorry both tglx and I have been traveling, he still is, I'm trying
to play catch-up :-)

Anyway, yeah I'm somewhat surprised the clock is 'running' when the
machine isn't. From what I could gather, this is !x86 hardware, right?

x86 explicitly makes sure our clocks are 'stopped' during suspend, see
commit cd7240c0b900eb6d690ccee088a6c9b46dae815a.

Can you do something similar for ARM? A quick look at
arch/arm/kernel/sched_clock.c shows there's already suspend/resume
hooks, do they do the wrong thing?

Hi,

On Fri, Oct 19, 2012 at 04:00:27PM +0200, Peter Zijlstra wrote:

On Thu, 2012-10-18 at 08:51 +0300, Felipe Balbi wrote:

quoted

quoted

So the primary question remains: is RT runtime supposed to include the
time spent suspended?  I suspect not. 

you might be right there, though we need Thomas or Peter to answer :-s 

re, sorry both tglx and I have been traveling, he still is, I'm trying
to play catch-up :-)

Anyway, yeah I'm somewhat surprised the clock is 'running' when the
machine isn't. From what I could gather, this is !x86 hardware, right?

x86 explicitly makes sure our clocks are 'stopped' during suspend, see
commit cd7240c0b900eb6d690ccee088a6c9b46dae815a.

Can you do something similar for ARM? A quick look at
arch/arm/kernel/sched_clock.c shows there's already suspend/resume
hooks, do they do the wrong thing?

if I understand correctly, then below should be enough. I did't test it
though:

diff --git a/arch/arm/plat-omap/counter_32k.c b/arch/arm/plat-omap/counter_32k.c
index 87ba8dd..c9260e6 100644
--- a/arch/arm/plat-omap/counter_32k.c
+++ b/arch/arm/plat-omap/counter_32k.c

@@ -116,7 +116,7 @@ int __init omap_init_clocksource_32k(void __iomem *vbase)
 		return ret;
 	}
 
-	setup_sched_clock(omap_32k_read_sched_clock, 32, 32768);
+	setup_sched_clock_needs_suspend(omap_32k_read_sched_clock, 32, 32768);
 	register_persistent_clock(NULL, omap_read_persistent_clock);
 	pr_info("OMAP clocksource: 32k_counter at 32768 Hz\n");
 

Russell, would you have any comments here ? Should we make sure all ARMs
call setup_sched_clock_needs_suspend() and 'stop' counting during
suspend ?

I will test the above diff tomorrow, unless you have any other (better)
idea on how to deal with the problem.

cheers

-- 
balbi
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 836 bytes
Desc: Digital signature
URL: <http://lists.infradead.org/pipermail/linux-arm-kernel/attachments/20121019/df3b447e/attachment.sig>