Re: RT throttling and suspend/resume (was Re: [PATCH] i2c: omap: revert i2c: omap: switch to threaded IRQ support)
On Mon, Oct 22, 2012 at 09:47:06AM -0700, Kevin Hilman wrote: Peter Zijlstra pet...@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. -- To unsubscribe from this list: send the line unsubscribe linux-omap in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: RT throttling and suspend/resume (was Re: [PATCH] i2c: omap: revert i2c: omap: switch to threaded IRQ support)
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? -- To unsubscribe from this list: send the line unsubscribe linux-omap in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: RT throttling and suspend/resume (was Re: [PATCH] i2c: omap: revert i2c: omap: switch to threaded IRQ support)
Peter Zijlstra pet...@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 -- To unsubscribe from this list: send the line unsubscribe linux-omap in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: RT throttling and suspend/resume (was Re: [PATCH] i2c: omap: revert i2c: omap: switch to threaded IRQ support)
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? -- To unsubscribe from this list: send the line unsubscribe linux-omap in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: RT throttling and suspend/resume (was Re: [PATCH] i2c: omap: revert i2c: omap: switch to threaded IRQ support)
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: 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 signature.asc Description: Digital signature
Re: RT throttling and suspend/resume (was Re: [PATCH] i2c: omap: revert i2c: omap: switch to threaded IRQ support)
Peter Zijlstra pet...@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 -- To unsubscribe from this list: send the line unsubscribe linux-omap in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: RT throttling and suspend/resume (was Re: [PATCH] i2c: omap: revert i2c: omap: switch to threaded IRQ support)
Peter Zijlstra pet...@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 -- To unsubscribe from this list: send the line unsubscribe linux-omap in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: RT throttling and suspend/resume (was Re: [PATCH] i2c: omap: revert i2c: omap: switch to threaded IRQ support)
Hi, On Tue, Oct 16, 2012 at 02:39:50PM -0700, Kevin Hilman wrote: + peterz, tglx Felipe Balbi ba...@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. -- balbi signature.asc Description: Digital signature
Re: RT throttling and suspend/resume (was Re: [PATCH] i2c: omap: revert i2c: omap: switch to threaded IRQ support)
Felipe Balbi ba...@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 ba...@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 95000
[ 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);
}
}
--
To unsubscribe from this list: send the line unsubscribe linux-omap in
the body of a message to majord...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: RT throttling and suspend/resume (was Re: [PATCH] i2c: omap: revert i2c: omap: switch to threaded IRQ support)
On Wed, Oct 17, 2012 at 04:06:54PM -0700, Kevin Hilman wrote: Felipe Balbi ba...@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 ba...@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 95000 [ 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 signature.asc Description: Digital signature
Re: [PATCH] i2c: omap: revert i2c: omap: switch to threaded IRQ support
On Mon, Oct 15, 2012 at 7:21 AM, Paul Walmsley p...@pwsan.com wrote: Commit 3b2f8f82dad7d1f79cdc8fc05bd1c94baf109bde (i2c: omap: switch to threaded IRQ support) causes communication with I2C devices to fail after system suspend/resume on all OMAP3 devices: Could you tell me which omap3 platform On Beagle Xm after mount /dev/mmcblk /mmcfs # mount /dev/mmcblk0p2 /mmcfs/ [ 412.480041] kjournald starting. Commit interval 5 seconds [ 412.490020] EXT3-fs (mmcblk0p2): using internal journal [ 412.495605] EXT3-fs (mmcblk0p2): mounted filesystem with ordered data mode # # cd /mmcfs/ # # # ls bin omap3_usb_prcm.sh usb_prcm.sh dev omap3_usbhs_off.shusb_uhh_show.sh etc omap3_usbhs_on.sh usb_uhh_tll.sh init proc usbhs_clk_disable.sh lib readmem.dat usbhs_clk_enable.sh lost+foundroot usbhs_set_sm.sh mnt sbin usbhs_show.sh modules sys usr msc tmp var omap3_ehcidump.sh usb_omap3.sh # # # echo mem /sys/power/state [ 464.785461] PM: Syncing filesystems ... done. [ 464.791442] PM: Preparing system for mem sleep [ 464.798034] Freezing user space processes ... (elapsed 0.02 seconds) done. [ 464.827301] Freezing remaining freezable tasks ... (elapsed 0.02 seconds) done. [ 464.858703] PM: Entering mem sleep [ 464.862304] Suspending console(s) (use no_console_suspend to debug) [ 464.994415] PM: suspend of devices complete after 121.002 msecs [ 464.998107] PM: late suspend of devices complete after 3.662 msecs [ 465.003173] PM: noirq suspend of devices complete after 5.004 msecs [ 465.003173] Disabling non-boot CPUs ... [ 466.225585] Successfully put all powerdomains to target state [ 466.228942] PM: noirq resume of devices complete after 3.051 msecs [ 466.232421] PM: early resume of devices complete after 2.349 msecs [ 467.492645] PM: resume of devices complete after 1260.131 msecs [ 467.546936] PM: Finishing wakeup. [ 467.550415] Restarting tasks ... done. # # # cat /debug/pm_debug/count | grep per_pwrdm per_pwrdm (ON),OFF:7,RET:0,INA:0,ON:8,RET-LOGIC-OFF:0,RET-MEMBANK1-OFF:0 per_clkdm-per_pwrdm (17) # echo mem /sys/power/state [ 1492.225311] PM: Syncing filesystems ... done. [ 1492.232177] PM: Preparing system for mem sleep [ 1492.238830] Freezing user space processes ... (elapsed 0.02 seconds) done. [ 1492.268188] Freezing remaining freezable tasks ... (elapsed 0.02 seconds) done. [ 1492.299804] PM: Entering mem sleep [ 1492.303375] Suspending console(s) (use no_console_suspend to debug) [ 1492.435333] PM: suspend of devices complete after 120.880 msecs [ 1492.439025] PM: late suspend of devices complete after 3.692 msecs [ 1492.444091] PM: noirq suspend of devices complete after 5.004 msecs [ 1492.444091] Disabling non-boot CPUs ... [ 1493.745544] Successfully put all powerdomains to target state [ 1493.748901] PM: noirq resume of devices complete after 3.051 msecs [ 1493.752319] PM: early resume of devices complete after 2.319 msecs [ 1494.794067] PM: resume of devices complete after 1041.625 msecs [ 1494.848388] PM: Finishing wakeup. [ 1494.851867] Restarting tasks ... done. # # # cat /debug/pm_debug/count | grep per_pwrdm per_pwrdm (ON),OFF:8,RET:0,INA:0,ON:9,RET-LOGIC-OFF:0,RET-MEMBANK1-OFF:0 per_clkdm-per_pwrdm (17) # Anyways will retry with fs on mmc. -- To unsubscribe from this list: send the line unsubscribe linux-omap in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: [PATCH] i2c: omap: revert i2c: omap: switch to threaded IRQ support
Hi, + Thomas Gleixner On Tue, Oct 16, 2012 at 06:28:13PM +0530, Shubhrajyoti Datta wrote: On Mon, Oct 15, 2012 at 7:21 AM, Paul Walmsley p...@pwsan.com wrote: Commit 3b2f8f82dad7d1f79cdc8fc05bd1c94baf109bde (i2c: omap: switch to threaded IRQ support) causes communication with I2C devices to fail after system suspend/resume on all OMAP3 devices: Could you tell me which omap3 platform On Beagle Xm after mount /dev/mmcblk /mmcfs # mount /dev/mmcblk0p2 /mmcfs/ [ 412.480041] kjournald starting. Commit interval 5 seconds [ 412.490020] EXT3-fs (mmcblk0p2): using internal journal [ 412.495605] EXT3-fs (mmcblk0p2): mounted filesystem with ordered data mode # # cd /mmcfs/ # # # ls bin omap3_usb_prcm.sh usb_prcm.sh dev omap3_usbhs_off.shusb_uhh_show.sh etc omap3_usbhs_on.sh usb_uhh_tll.sh init proc usbhs_clk_disable.sh lib readmem.dat usbhs_clk_enable.sh lost+foundroot usbhs_set_sm.sh mnt sbin usbhs_show.sh modules sys usr msc tmp var omap3_ehcidump.sh usb_omap3.sh # # # echo mem /sys/power/state [ 464.785461] PM: Syncing filesystems ... done. [ 464.791442] PM: Preparing system for mem sleep [ 464.798034] Freezing user space processes ... (elapsed 0.02 seconds) done. [ 464.827301] Freezing remaining freezable tasks ... (elapsed 0.02 seconds) done. [ 464.858703] PM: Entering mem sleep [ 464.862304] Suspending console(s) (use no_console_suspend to debug) [ 464.994415] PM: suspend of devices complete after 121.002 msecs [ 464.998107] PM: late suspend of devices complete after 3.662 msecs [ 465.003173] PM: noirq suspend of devices complete after 5.004 msecs [ 465.003173] Disabling non-boot CPUs ... [ 466.225585] Successfully put all powerdomains to target state [ 466.228942] PM: noirq resume of devices complete after 3.051 msecs [ 466.232421] PM: early resume of devices complete after 2.349 msecs [ 467.492645] PM: resume of devices complete after 1260.131 msecs [ 467.546936] PM: Finishing wakeup. [ 467.550415] Restarting tasks ... done. # # # cat /debug/pm_debug/count | grep per_pwrdm per_pwrdm (ON),OFF:7,RET:0,INA:0,ON:8,RET-LOGIC-OFF:0,RET-MEMBANK1-OFF:0 per_clkdm-per_pwrdm (17) # echo mem /sys/power/state [ 1492.225311] PM: Syncing filesystems ... done. [ 1492.232177] PM: Preparing system for mem sleep [ 1492.238830] Freezing user space processes ... (elapsed 0.02 seconds) done. [ 1492.268188] Freezing remaining freezable tasks ... (elapsed 0.02 seconds) done. [ 1492.299804] PM: Entering mem sleep [ 1492.303375] Suspending console(s) (use no_console_suspend to debug) [ 1492.435333] PM: suspend of devices complete after 120.880 msecs [ 1492.439025] PM: late suspend of devices complete after 3.692 msecs [ 1492.444091] PM: noirq suspend of devices complete after 5.004 msecs [ 1492.444091] Disabling non-boot CPUs ... [ 1493.745544] Successfully put all powerdomains to target state [ 1493.748901] PM: noirq resume of devices complete after 3.051 msecs [ 1493.752319] PM: early resume of devices complete after 2.319 msecs [ 1494.794067] PM: resume of devices complete after 1041.625 msecs [ 1494.848388] PM: Finishing wakeup. [ 1494.851867] Restarting tasks ... done. # # # cat /debug/pm_debug/count | grep per_pwrdm per_pwrdm (ON),OFF:8,RET:0,INA:0,ON:9,RET-LOGIC-OFF:0,RET-MEMBANK1-OFF:0 per_clkdm-per_pwrdm (17) # Anyways will retry with fs on mmc. rootfs has to be on MMC to trigger this. The problem happens because omap_hsmmc calls enable_irq() on its resume method. That IRQ line is actually a GPIO from TWL4030, so twl4030-irq.c::twl4030_sih_bus_sync_unlock() will be called, which will trigger an I2C transfer. 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: [ 78.709381] omap_i2c omap_i2c.1: omap_i2c_isr_thread 913 [ 78.715026] omap_i2c omap_i2c.1: omap_i2c_isr_thread 1038 [ 78.720733] omap_i2c omap_i2c.1: omap_i2c_xfer 655 [ 78.725769] omap_i2c omap_i2c.1: omap_i2c_xfer 659 [ 78.730804] omap_i2c omap_i2c.1: omap_i2c_xfer 663 [ 78.735870] omap_i2c omap_i2c.1: omap_i2c_xfer 668 [ 78.850708] PM: suspend of devices complete after 1287.841 msecs [ 78.860870] PM: late suspend of devices complete after 3.753 msecs [ 78.872283] try_to_wake_up 1411 [ 78.875701] try_to_wake_up 1411 [ 78.879028] try_to_wake_up 1411 [ 78.882537] omap_i2c omap_i2c.1: omap_i2c_runtime_suspend 1359 [ 78.888763] omap_i2c omap_i2c.1: omap_i2c_low_level_suspend 1261
Re: [PATCH] i2c: omap: revert i2c: omap: switch to threaded IRQ support
Hi again, On Tue, Oct 16, 2012 at 04:33:56PM +0300, Felipe Balbi wrote: Hi, + Thomas Gleixner On Tue, Oct 16, 2012 at 06:28:13PM +0530, Shubhrajyoti Datta wrote: On Mon, Oct 15, 2012 at 7:21 AM, Paul Walmsley p...@pwsan.com wrote: Commit 3b2f8f82dad7d1f79cdc8fc05bd1c94baf109bde (i2c: omap: switch to threaded IRQ support) causes communication with I2C devices to fail after system suspend/resume on all OMAP3 devices: Could you tell me which omap3 platform On Beagle Xm after mount /dev/mmcblk /mmcfs # mount /dev/mmcblk0p2 /mmcfs/ [ 412.480041] kjournald starting. Commit interval 5 seconds [ 412.490020] EXT3-fs (mmcblk0p2): using internal journal [ 412.495605] EXT3-fs (mmcblk0p2): mounted filesystem with ordered data mode # # cd /mmcfs/ # # # ls bin omap3_usb_prcm.sh usb_prcm.sh dev omap3_usbhs_off.shusb_uhh_show.sh etc omap3_usbhs_on.sh usb_uhh_tll.sh init proc usbhs_clk_disable.sh lib readmem.dat usbhs_clk_enable.sh lost+foundroot usbhs_set_sm.sh mnt sbin usbhs_show.sh modules sys usr msc tmp var omap3_ehcidump.sh usb_omap3.sh # # # echo mem /sys/power/state [ 464.785461] PM: Syncing filesystems ... done. [ 464.791442] PM: Preparing system for mem sleep [ 464.798034] Freezing user space processes ... (elapsed 0.02 seconds) done. [ 464.827301] Freezing remaining freezable tasks ... (elapsed 0.02 seconds) done. [ 464.858703] PM: Entering mem sleep [ 464.862304] Suspending console(s) (use no_console_suspend to debug) [ 464.994415] PM: suspend of devices complete after 121.002 msecs [ 464.998107] PM: late suspend of devices complete after 3.662 msecs [ 465.003173] PM: noirq suspend of devices complete after 5.004 msecs [ 465.003173] Disabling non-boot CPUs ... [ 466.225585] Successfully put all powerdomains to target state [ 466.228942] PM: noirq resume of devices complete after 3.051 msecs [ 466.232421] PM: early resume of devices complete after 2.349 msecs [ 467.492645] PM: resume of devices complete after 1260.131 msecs [ 467.546936] PM: Finishing wakeup. [ 467.550415] Restarting tasks ... done. # # # cat /debug/pm_debug/count | grep per_pwrdm per_pwrdm (ON),OFF:7,RET:0,INA:0,ON:8,RET-LOGIC-OFF:0,RET-MEMBANK1-OFF:0 per_clkdm-per_pwrdm (17) # echo mem /sys/power/state [ 1492.225311] PM: Syncing filesystems ... done. [ 1492.232177] PM: Preparing system for mem sleep [ 1492.238830] Freezing user space processes ... (elapsed 0.02 seconds) done. [ 1492.268188] Freezing remaining freezable tasks ... (elapsed 0.02 seconds) done. [ 1492.299804] PM: Entering mem sleep [ 1492.303375] Suspending console(s) (use no_console_suspend to debug) [ 1492.435333] PM: suspend of devices complete after 120.880 msecs [ 1492.439025] PM: late suspend of devices complete after 3.692 msecs [ 1492.444091] PM: noirq suspend of devices complete after 5.004 msecs [ 1492.444091] Disabling non-boot CPUs ... [ 1493.745544] Successfully put all powerdomains to target state [ 1493.748901] PM: noirq resume of devices complete after 3.051 msecs [ 1493.752319] PM: early resume of devices complete after 2.319 msecs [ 1494.794067] PM: resume of devices complete after 1041.625 msecs [ 1494.848388] PM: Finishing wakeup. [ 1494.851867] Restarting tasks ... done. # # # cat /debug/pm_debug/count | grep per_pwrdm per_pwrdm (ON),OFF:8,RET:0,INA:0,ON:9,RET-LOGIC-OFF:0,RET-MEMBANK1-OFF:0 per_clkdm-per_pwrdm (17) # Anyways will retry with fs on mmc. rootfs has to be on MMC to trigger this. The problem happens because omap_hsmmc calls enable_irq() on its resume method. That IRQ line is actually a GPIO from TWL4030, so twl4030-irq.c::twl4030_sih_bus_sync_unlock() will be called, which will trigger an I2C transfer. 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 another detail here: if I drop the disable_irq()/enable_irq() from omap_hsmmc driver, everything ends up being fine, so I'm wondering if we have a race between omap_hsmmc, twl4030 card detect GPIO and I2C, but I'm not sure yet. nasty) debug prints showing the problem: [ 78.709381] omap_i2c omap_i2c.1: omap_i2c_isr_thread 913 [ 78.715026] omap_i2c omap_i2c.1: omap_i2c_isr_thread 1038 [ 78.720733] omap_i2c omap_i2c.1: omap_i2c_xfer 655 [ 78.725769] omap_i2c omap_i2c.1: omap_i2c_xfer 659 [ 78.730804] omap_i2c omap_i2c.1: omap_i2c_xfer 663 [ 78.735870]
Re: [PATCH] i2c: omap: revert i2c: omap: switch to threaded IRQ support
Hi,
On Mon, Oct 15, 2012 at 01:51:08AM +, Paul Walmsley wrote:
Commit 3b2f8f82dad7d1f79cdc8fc05bd1c94baf109bde (i2c: omap: switch to
threaded IRQ support) causes communication with I2C devices to fail
after system suspend/resume on all OMAP3 devices:
...
[ 40.228576] PM: noirq resume of devices complete after 3.723 msecs
[ 40.233184] PM: early resume of devices complete after 3.173 msecs
[ 40.242736] [sched_delayed] sched: RT throttling activated
[ 41.235046] omap_i2c omap_i2c.1: controller timed out
instead of just reverting the patch, I'd rather try to figure out why
controller times out in that situation.
It should make no difference if you're running an IRQ thread or not.
Do you have any extra debugging information which might help figuring
out what the issue really is ?
If the thread is actually at fault, then we need to add IRQF_NO_THREAD
to the IRQ flags, otherwise same issue will appear if we boot with
threadirqs kernel parameter.
[ 41.235351] twl: i2c_read failed to transfer all messages
[ 41.235382] omap_hsmmc omap_hsmmc.0: could not set regulator OCR (-110)
[ 41.396453] mmc0: error -110 during resume (card was removed?)
[ 42.391754] omap_i2c omap_i2c.1: controller timed out
[ 42.391876] twl: i2c_write failed to transfer all messages
[ 42.391906] twl_rtc: Could not write TWLregister F - error -110
[ 43.391326] omap_i2c omap_i2c.1: controller timed out
[ 43.391479] twl: i2c_read failed to transfer all messages
[ 43.391510] twl_rtc: Could not read TWLregister D - error -110
[ 43.391540] twl_rtc twl_rtc: twl_rtc_read_time: reading CTRL_REG, error
-110
[ 43.392364] PM: resume of devices complete after 3158.935 msecs
When the root filesystem is on MMC, as in the above example, the
card's voltage regulator is not re-enabled and the filesystem becomes
inaccessible after resume.
but it fails because I2C times out and I'd like to understand why,
before just reverting the patch.
Fix by reverting the conversion to a threaded IRQ handler.
Signed-off-by: Paul Walmsley p...@pwsan.com
Cc: Felipe Balbi ba...@ti.com
Cc: Shubhrajyoti D shubhrajy...@ti.com
Cc: Wolfram Sang w.s...@pengutronix.de
Cc: Ben Dooks ben-li...@fluff.org
---
drivers/i2c/busses/i2c-omap.c | 44
+++--
1 file changed, 7 insertions(+), 37 deletions(-)
diff --git a/drivers/i2c/busses/i2c-omap.c b/drivers/i2c/busses/i2c-omap.c
index db31eae..e001c2a 100644
--- a/drivers/i2c/busses/i2c-omap.c
+++ b/drivers/i2c/busses/i2c-omap.c
@@ -180,7 +180,6 @@ enum {
#define I2C_OMAP_ERRATA_I462 (1 1)
struct omap_i2c_dev {
- spinlock_t lock; /* IRQ synchronization */
struct device *dev;
void __iomem*base; /* virtual */
int irq;
@@ -865,35 +864,13 @@ static int omap_i2c_transmit_data(struct omap_i2c_dev
*dev, u8 num_bytes,
}
static irqreturn_t
-omap_i2c_isr(int irq, void *dev_id)
+omap_i2c_isr(int this_irq, void *dev_id)
{
struct omap_i2c_dev *dev = dev_id;
- irqreturn_t ret = IRQ_HANDLED;
- u16 mask;
- u16 stat;
-
- spin_lock(dev-lock);
- mask = omap_i2c_read_reg(dev, OMAP_I2C_IE_REG);
- stat = omap_i2c_read_reg(dev, OMAP_I2C_STAT_REG);
-
- if (stat mask)
- ret = IRQ_WAKE_THREAD;
-
- spin_unlock(dev-lock);
-
- return ret;
-}
-
-static irqreturn_t
-omap_i2c_isr_thread(int this_irq, void *dev_id)
-{
- struct omap_i2c_dev *dev = dev_id;
- unsigned long flags;
u16 bits;
u16 stat;
int err = 0, count = 0;
- spin_lock_irqsave(dev-lock, flags);
do {
bits = omap_i2c_read_reg(dev, OMAP_I2C_IE_REG);
stat = omap_i2c_read_reg(dev, OMAP_I2C_STAT_REG);
@@ -907,7 +884,7 @@ omap_i2c_isr_thread(int this_irq, void *dev_id)
if (!stat) {
/* my work here is done */
- goto out;
+ return IRQ_HANDLED;
}
dev_dbg(dev-dev, IRQ (ISR = 0x%04x)\n, stat);
@@ -1016,8 +993,6 @@ omap_i2c_isr_thread(int this_irq, void *dev_id)
omap_i2c_complete_cmd(dev, err);
out:
- spin_unlock_irqrestore(dev-lock, flags);
-
return IRQ_HANDLED;
}
@@ -1062,6 +1037,7 @@ omap_i2c_probe(struct platform_device *pdev)
pdev-dev.platform_data;
struct device_node *node = pdev-dev.of_node;
const struct of_device_id *match;
+ irq_handler_t isr;
int irq;
int r;
@@ -1110,8 +1086,6 @@ omap_i2c_probe(struct platform_device *pdev)
dev-dev = pdev-dev;
dev-irq = irq;
- spin_lock_init(dev-lock);
-
platform_set_drvdata(pdev, dev);
init_completion(dev-cmd_complete);
@@ -1166,14 +1140,10 @@ omap_i2c_probe(struct platform_device *pdev)
/* reset ASAP, clearing any IRQs */
Re: [PATCH] i2c: omap: revert i2c: omap: switch to threaded IRQ support
Hi On Mon, 15 Oct 2012, Felipe Balbi wrote: On Mon, Oct 15, 2012 at 01:51:08AM +, Paul Walmsley wrote: Commit 3b2f8f82dad7d1f79cdc8fc05bd1c94baf109bde (i2c: omap: switch to threaded IRQ support) causes communication with I2C devices to fail after system suspend/resume on all OMAP3 devices: ... [ 40.228576] PM: noirq resume of devices complete after 3.723 msecs [ 40.233184] PM: early resume of devices complete after 3.173 msecs [ 40.242736] [sched_delayed] sched: RT throttling activated [ 41.235046] omap_i2c omap_i2c.1: controller timed out instead of just reverting the patch, I'd rather try to figure out why controller times out in that situation. It should make no difference if you're running an IRQ thread or not. Do you have any extra debugging information which might help figuring out what the issue really is ? As mentioned, the problem can be easily reproduced on OMAP3 is test by running echo mem /sys/power/state in userspace when rootfs is on MMC. Then wake up out of suspend, for example, by hitting ENTER on the serial console. This needs to be part of the testing before any OMAP patches are posted to the lists -- if for no other reason than because Android kernels enter and exit system suspend frequently as part of their standard usage model. If the thread is actually at fault, then we need to add IRQF_NO_THREAD to the IRQ flags, otherwise same issue will appear if we boot with threadirqs kernel parameter. ... but it fails because I2C times out and I'd like to understand why, before just reverting the patch. It doesn't matter to me how it's fixed as long as it's fixed quickly during the early 3.7-rcs. - Paul -- To unsubscribe from this list: send the line unsubscribe linux-omap in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
[PATCH] i2c: omap: revert i2c: omap: switch to threaded IRQ support
Commit 3b2f8f82dad7d1f79cdc8fc05bd1c94baf109bde (i2c: omap: switch to
threaded IRQ support) causes communication with I2C devices to fail
after system suspend/resume on all OMAP3 devices:
...
[ 40.228576] PM: noirq resume of devices complete after 3.723 msecs
[ 40.233184] PM: early resume of devices complete after 3.173 msecs
[ 40.242736] [sched_delayed] sched: RT throttling activated
[ 41.235046] omap_i2c omap_i2c.1: controller timed out
[ 41.235351] twl: i2c_read failed to transfer all messages
[ 41.235382] omap_hsmmc omap_hsmmc.0: could not set regulator OCR (-110)
[ 41.396453] mmc0: error -110 during resume (card was removed?)
[ 42.391754] omap_i2c omap_i2c.1: controller timed out
[ 42.391876] twl: i2c_write failed to transfer all messages
[ 42.391906] twl_rtc: Could not write TWLregister F - error -110
[ 43.391326] omap_i2c omap_i2c.1: controller timed out
[ 43.391479] twl: i2c_read failed to transfer all messages
[ 43.391510] twl_rtc: Could not read TWLregister D - error -110
[ 43.391540] twl_rtc twl_rtc: twl_rtc_read_time: reading CTRL_REG, error -110
[ 43.392364] PM: resume of devices complete after 3158.935 msecs
When the root filesystem is on MMC, as in the above example, the
card's voltage regulator is not re-enabled and the filesystem becomes
inaccessible after resume.
Fix by reverting the conversion to a threaded IRQ handler.
Signed-off-by: Paul Walmsley p...@pwsan.com
Cc: Felipe Balbi ba...@ti.com
Cc: Shubhrajyoti D shubhrajy...@ti.com
Cc: Wolfram Sang w.s...@pengutronix.de
Cc: Ben Dooks ben-li...@fluff.org
---
drivers/i2c/busses/i2c-omap.c | 44 +++--
1 file changed, 7 insertions(+), 37 deletions(-)
diff --git a/drivers/i2c/busses/i2c-omap.c b/drivers/i2c/busses/i2c-omap.c
index db31eae..e001c2a 100644
--- a/drivers/i2c/busses/i2c-omap.c
+++ b/drivers/i2c/busses/i2c-omap.c
@@ -180,7 +180,6 @@ enum {
#define I2C_OMAP_ERRATA_I462 (1 1)
struct omap_i2c_dev {
- spinlock_t lock; /* IRQ synchronization */
struct device *dev;
void __iomem*base; /* virtual */
int irq;
@@ -865,35 +864,13 @@ static int omap_i2c_transmit_data(struct omap_i2c_dev
*dev, u8 num_bytes,
}
static irqreturn_t
-omap_i2c_isr(int irq, void *dev_id)
+omap_i2c_isr(int this_irq, void *dev_id)
{
struct omap_i2c_dev *dev = dev_id;
- irqreturn_t ret = IRQ_HANDLED;
- u16 mask;
- u16 stat;
-
- spin_lock(dev-lock);
- mask = omap_i2c_read_reg(dev, OMAP_I2C_IE_REG);
- stat = omap_i2c_read_reg(dev, OMAP_I2C_STAT_REG);
-
- if (stat mask)
- ret = IRQ_WAKE_THREAD;
-
- spin_unlock(dev-lock);
-
- return ret;
-}
-
-static irqreturn_t
-omap_i2c_isr_thread(int this_irq, void *dev_id)
-{
- struct omap_i2c_dev *dev = dev_id;
- unsigned long flags;
u16 bits;
u16 stat;
int err = 0, count = 0;
- spin_lock_irqsave(dev-lock, flags);
do {
bits = omap_i2c_read_reg(dev, OMAP_I2C_IE_REG);
stat = omap_i2c_read_reg(dev, OMAP_I2C_STAT_REG);
@@ -907,7 +884,7 @@ omap_i2c_isr_thread(int this_irq, void *dev_id)
if (!stat) {
/* my work here is done */
- goto out;
+ return IRQ_HANDLED;
}
dev_dbg(dev-dev, IRQ (ISR = 0x%04x)\n, stat);
@@ -1016,8 +993,6 @@ omap_i2c_isr_thread(int this_irq, void *dev_id)
omap_i2c_complete_cmd(dev, err);
out:
- spin_unlock_irqrestore(dev-lock, flags);
-
return IRQ_HANDLED;
}
@@ -1062,6 +1037,7 @@ omap_i2c_probe(struct platform_device *pdev)
pdev-dev.platform_data;
struct device_node *node = pdev-dev.of_node;
const struct of_device_id *match;
+ irq_handler_t isr;
int irq;
int r;
@@ -1110,8 +1086,6 @@ omap_i2c_probe(struct platform_device *pdev)
dev-dev = pdev-dev;
dev-irq = irq;
- spin_lock_init(dev-lock);
-
platform_set_drvdata(pdev, dev);
init_completion(dev-cmd_complete);
@@ -1166,14 +1140,10 @@ omap_i2c_probe(struct platform_device *pdev)
/* reset ASAP, clearing any IRQs */
omap_i2c_init(dev);
- if (dev-rev OMAP_I2C_OMAP1_REV_2)
- r = devm_request_irq(pdev-dev, dev-irq, omap_i2c_omap1_isr,
- IRQF_NO_SUSPEND, pdev-name, dev);
- else
- r = devm_request_threaded_irq(pdev-dev, dev-irq,
- omap_i2c_isr, omap_i2c_isr_thread,
- IRQF_NO_SUSPEND | IRQF_ONESHOT,
- pdev-name, dev);
+ isr = (dev-rev OMAP_I2C_OMAP1_REV_2) ? omap_i2c_omap1_isr :
+ omap_i2c_isr;
+ r = devm_request_irq(pdev-dev,
