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

Message ID 87txtsitpt.fsf@deeprootsystems.com
State New, archived
Headers show

Commit Message

Kevin Hilman Oct. 17, 2012, 11:06 p.m. UTC
Felipe Balbi <balbi@ti.com> writes:

> On Wed, Oct 17, 2012 at 05:00:02PM +0300, Felipe Balbi wrote:
>> 
>> On Tue, Oct 16, 2012 at 02:39:50PM -0700, Kevin Hilman wrote:
>> > + peterz, tglx
>> > 
>> > Felipe Balbi <balbi@ti.com> writes:
>> > 
>> > [...]
>> > 
>> > > 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:
>> > 
>> > [...]
>> > 
>> > >> [   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]

Comments

Felipe Balbi Oct. 18, 2012, 5:51 a.m. UTC | #1
On Wed, Oct 17, 2012 at 04:06:54PM -0700, Kevin Hilman wrote:
> Felipe Balbi <balbi@ti.com> writes:
> 
> > On Wed, Oct 17, 2012 at 05:00:02PM +0300, Felipe Balbi wrote:
> >> 
> >> On Tue, Oct 16, 2012 at 02:39:50PM -0700, Kevin Hilman wrote:
> >> > + peterz, tglx
> >> > 
> >> > Felipe Balbi <balbi@ti.com> writes:
> >> > 
> >> > [...]
> >> > 
> >> > > 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:
> >> > 
> >> > [...]
> >> > 
> >> > >> [   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
Peter Zijlstra Oct. 19, 2012, 2 p.m. UTC | #2
On Thu, 2012-10-18 at 08:51 +0300, Felipe Balbi wrote:
> > 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?
Kevin Hilman Oct. 19, 2012, 11:28 p.m. UTC | #3
Peter Zijlstra <peterz@infradead.org> writes:

> On Thu, 2012-10-18 at 08:51 +0300, Felipe Balbi wrote:
>> > 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 :-)

No worries, thanks for the help.

> 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?

No, they do the right thing, but only if they're asked by the
SoC-specific code that registers a sched_clock.  Changing the SoC
specific code to use the 'needs_suspend' API gets things working
perfectly.

Thanks,

Kevin
Kevin Hilman Oct. 19, 2012, 11:54 p.m. UTC | #4
Peter Zijlstra <peterz@infradead.org> writes:

> On Thu, 2012-10-18 at 08:51 +0300, Felipe Balbi wrote:
>> > 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?

So I did the same thing for my ARM SoC, and it definitley stops the RT
throttling.  

However, it has the undesriable (IMO) side effect of making timed printk
output rather unhelpful for debugging suspend/resume since printk time
stays constant throughout suspend/resume no matter how long you
sleep. :(

So does that mean we have to choose between useful printk times during
suspend/resume or functioning IRQ threads during suspend/resume ?

Kevin
Peter Zijlstra Oct. 22, 2012, 9:52 a.m. UTC | #5
On Fri, 2012-10-19 at 16:54 -0700, Kevin Hilman wrote:

> So I did the same thing for my ARM SoC, and it definitley stops the RT
> throttling.  
> 
> However, it has the undesriable (IMO) side effect of making timed printk
> output rather unhelpful for debugging suspend/resume since printk time
> stays constant throughout suspend/resume no matter how long you
> sleep. :(
> 
> So does that mean we have to choose between useful printk times during
> suspend/resume or functioning IRQ threads during suspend/resume ?

Urgh.. this was not something I considered. This being primarily the
sched_clock infrastructure and such.

So what exactly is the problem with the suspend resume thing (its not
something I've ever debugged), is all you need a clean break between pre
and post suspend, or do you need the actual time the machine was gone?
Kevin Hilman Oct. 22, 2012, 4:47 p.m. UTC | #6
Peter Zijlstra <peterz@infradead.org> writes:

> On Fri, 2012-10-19 at 16:54 -0700, Kevin Hilman wrote:
>
>> So I did the same thing for my ARM SoC, and it definitley stops the RT
>> throttling.  
>> 
>> However, it has the undesriable (IMO) side effect of making timed printk
>> output rather unhelpful for debugging suspend/resume since printk time
>> stays constant throughout suspend/resume no matter how long you
>> sleep. :(
>> 
>> So does that mean we have to choose between useful printk times during
>> suspend/resume or functioning IRQ threads during suspend/resume ?
>
> Urgh.. this was not something I considered. This being primarily the
> sched_clock infrastructure and such.
>
> So what exactly is the problem with the suspend resume thing (its not
> something I've ever debugged), is all you need a clean break between pre
> and post suspend, or do you need the actual time the machine was gone?

I think it's more a question of what people are used to.  I think folks
used to debugging suspend/resume (at least on ARM) are used to having
the printk timestamps reflect the amount of time the machine was gone.

With a sched_clock() that counts during suspend, that feature doesn't
work anymore.  I'm not sure that this feature is a deal breaker, but it
has been convenient.  I see that on x86, it's already normal that
printk times don't reflect time spent in suspend, so I guess ARM needs
to adapt.  

Kevin
Russell King - ARM Linux Oct. 23, 2012, 9:19 a.m. UTC | #7
On Mon, Oct 22, 2012 at 09:47:06AM -0700, Kevin Hilman wrote:
> Peter Zijlstra <peterz@infradead.org> writes:
> 
> > On Fri, 2012-10-19 at 16:54 -0700, Kevin Hilman wrote:
> >
> >> So I did the same thing for my ARM SoC, and it definitley stops the RT
> >> throttling.  
> >> 
> >> However, it has the undesriable (IMO) side effect of making timed printk
> >> output rather unhelpful for debugging suspend/resume since printk time
> >> stays constant throughout suspend/resume no matter how long you
> >> sleep. :(
> >> 
> >> So does that mean we have to choose between useful printk times during
> >> suspend/resume or functioning IRQ threads during suspend/resume ?
> >
> > Urgh.. this was not something I considered. This being primarily the
> > sched_clock infrastructure and such.
> >
> > So what exactly is the problem with the suspend resume thing (its not
> > something I've ever debugged), is all you need a clean break between pre
> > and post suspend, or do you need the actual time the machine was gone?
> 
> I think it's more a question of what people are used to.  I think folks
> used to debugging suspend/resume (at least on ARM) are used to having
> the printk timestamps reflect the amount of time the machine was gone.
> 
> With a sched_clock() that counts during suspend, that feature doesn't
> work anymore.  I'm not sure that this feature is a deal breaker, but it
> has been convenient.

IMHO, this isn't a deal breaker, it's nothing more than cosmetic issue.
The big hint about the sched_clock() behaviour is partly in the name,
and the behaviour you get from the scheduler if you don't give it what
it wants.  The scheduler sets the requirements for sched_clock(), not
printk, so if we have to fix sched_clock() to get correct behaviour
from the scheduler, that's what we have to do irrespective of cosmetic
printk issues.

And there are many other ways to measure time off in suspend... we have
at least three other functions which return time, and which will return
updated time after a resume event.

Patch
diff mbox

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);
 		}
 	}