omap_hsmmc noisy/broken for suspend resume

DISCUSSION Kevin Hilman 4 participants 5 messages Nov 3, 2011 – Nov 21, 2011 MMC, SD and SDIO

Share & tools

Girish K S

2011-11-04 04:21 UTC #1 lore raw

Quoted 18 lines · Kevin Hilman

Hello,
Using Linus' master branch, I was testing PM functionality on OMAP3/4 and noticed that the MMC driver is now rather noisy during suspend on OMAP3[1], but seems to work.
On OMAP4, MMC seems to prevent suspend/resume all together. I haven't found the root cause, but know that by not buidling the MMC driver, I have working suspend/resume again on OMAP4.
Venkat, can you investigate this?
For OMAP4, please use my for_3.2/omap4-pm branch which has the OMAP4 MPUSS retention support from Santosh.
Kevin

Quoted 16 lines

[1]
/ # echo mem > /sys/power/state
[ 811.145507] PM: Syncing filesystems ... done.
[ 811.150268] PM: Preparing system for mem sleep
[ 811.155059] Freezing user space processes ... (elapsed 0.01 seconds) done.
[ 811.179992] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
[ 811.203460] PM: Entering mem sleep
[ 811.207489] Suspending console(s) (use no_console_suspend to debug)
a[ 811.225860] ------------[ cut here ]------------
[ 811.225891] WARNING: at /work/kernel/omap/pm/drivers/mmc/core/core.c:453 mmc_wait_for_cmd+0x78/0x84() [ 811.225921] Modules linked in:
[ 811.225952] [<c001a810>] (unwind_backtrace+0x0/0xf0) from [<c00525d0>] (warn_slowpath_common+0x4c/0x64) [ 811.225982] [<c00525d0>] (warn_slowpath_common+0x4c/0x64) from [<c0052604>] (warn_slowpath_null+0x1c/0x24) [ 811.226013] [<c0052604>] (warn_slowpath_null+0x1c/0x24) from [<c033a494>] (mmc_wait_for_cmd+0x78/0x84) [ 811.226043] [<c033a494>] (mmc_wait_for_cmd+0x78/0x84) from [<c033e7b8>] (mmc_switch+0x74/0x118) [ 811.226074] [<c033e7b8>] (mmc_switch+0x74/0x118) from [<c033b034>] (mmc_power_off+0xd8/0x108)

The problem is caused by the card->poweroff_notify_state = MMC_POWERED_ON; statement in the mmc_card_init function it is set for the non eMMC4.5 devices. I will rectify this and soon send a patch for the same.

Quoted 56 lines

[ 811.226104] [<c033b034>] (mmc_power_off+0xd8/0x108) from [<c033b3a4>] (mmc_suspend_host+0xe4/0x1b8) [ 811.226135] [<c033b3a4>] (mmc_suspend_host+0xe4/0x1b8) from [<c034a77c>] (omap_hsmmc_suspend+0x74/0xfc) [ 811.226165] [<c034a77c>] (omap_hsmmc_suspend+0x74/0xfc) from [<c028df74>] (platform_pm_suspend+0x2c/0x5c) [ 811.226196] [<c028df74>] (platform_pm_suspend+0x2c/0x5c) from [<c0291a60>] (pm_op.clone.4+0x70/0xb8) [ 811.226226] [<c0291a60>] (pm_op.clone.4+0x70/0xb8) from [<c0291b70>] (__device_suspend+0xc8/0x1f0) [ 811.226257] [<c0291b70>] (__device_suspend+0xc8/0x1f0) from [<c02929d0>] (dpm_suspend+0x5c/0x218) [ 811.226287] [<c02929d0>] (dpm_suspend+0x5c/0x218) from [<c00970c8>] (suspend_devices_and_enter+0x8c/0x18c) [ 811.226318] [<c00970c8>] (suspend_devices_and_enter+0x8c/0x18c) from [<c0097308>] (enter_state+0x140/0x180) [ 811.226318] [<c0097308>] (enter_state+0x140/0x180) from [<c00961d4>] (state_store+0xb8/0x104) [ 811.226348] [<c00961d4>] (state_store+0xb8/0x104) from [<c022f7b8>] (kobj_attr_store+0x14/0x20) [ 811.226379] [<c022f7b8>] (kobj_attr_store+0x14/0x20) from [<c01542a8>] (sysfs_write_file+0x100/0x184) [ 811.226409] [<c01542a8>] (sysfs_write_file+0x100/0x184) from [<c00f8d88>] (vfs_write+0xb4/0x148) [ 811.226440] [<c00f8d88>] (vfs_write+0xb4/0x148) from [<c00f9010>] (sys_write+0x40/0x70)
[ 811.226470] [<c00f9010>] (sys_write+0x40/0x70) from [<c00132a0>] (ret_fast_syscall+0x0/0x3c) [ 811.226501] ---[ end trace 870223ea4a1b1518 ]---
[ 811.226501] ------------[ cut here ]------------
[ 811.226531] WARNING: at /work/kernel/omap/pm/drivers/mmc/core/core.c:210 mmc_start_request+0xd4/0xdc() [ 811.226531] Modules linked in:
[ 811.226562] [<c001a810>] (unwind_backtrace+0x0/0xf0) from [<c00525d0>] (warn_slowpath_common+0x4c/0x64) [ 811.226593] [<c00525d0>] (warn_slowpath_common+0x4c/0x64) from [<c0052604>] (warn_slowpath_null+0x1c/0x24) [ 811.226623] [<c0052604>] (warn_slowpath_null+0x1c/0x24) from [<c0339da8>] (mmc_start_request+0xd4/0xdc) [ 811.226654] [<c0339da8>] (mmc_start_request+0xd4/0xdc) from [<c033a404>] (mmc_wait_for_req+0x34/0x4c) [ 811.226684] [<c033a404>] (mmc_wait_for_req+0x34/0x4c) from [<c033a47c>] (mmc_wait_for_cmd+0x60/0x84) [ 811.226715] [<c033a47c>] (mmc_wait_for_cmd+0x60/0x84) from [<c033e7b8>] (mmc_switch+0x74/0x118) [ 811.226715] [<c033e7b8>] (mmc_switch+0x74/0x118) from [<c033b034>] (mmc_power_off+0xd8/0x108) [ 811.226745] [<c033b034>] (mmc_power_off+0xd8/0x108) from [<c033b3a4>] (mmc_suspend_host+0xe4/0x1b8) [ 811.226776] [<c033b3a4>] (mmc_suspend_host+0xe4/0x1b8) from [<c034a77c>] (omap_hsmmc_suspend+0x74/0xfc) [ 811.226806] [<c034a77c>] (omap_hsmmc_suspend+0x74/0xfc) from [<c028df74>] (platform_pm_suspend+0x2c/0x5c) [ 811.226837] [<c028df74>] (platform_pm_suspend+0x2c/0x5c) from [<c0291a60>] (pm_op.clone.4+0x70/0xb8) [ 811.226867] [<c0291a60>] (pm_op.clone.4+0x70/0xb8) from [<c0291b70>] (__device_suspend+0xc8/0x1f0) [ 811.226867] [<c0291b70>] (__device_suspend+0xc8/0x1f0) from [<c02929d0>] (dpm_suspend+0x5c/0x218) [ 811.226898] [<c02929d0>] (dpm_suspend+0x5c/0x218) from [<c00970c8>] (suspend_devices_and_enter+0x8c/0x18c) [ 811.226928] [<c00970c8>] (suspend_devices_and_enter+0x8c/0x18c) from [<c0097308>] (enter_state+0x140/0x180) [ 811.226959] [<c0097308>] (enter_state+0x140/0x180) from [<c00961d4>] (state_store+0xb8/0x104) [ 811.226989] [<c00961d4>] (state_store+0xb8/0x104) from [<c022f7b8>] (kobj_attr_store+0x14/0x20) [ 811.227020] [<c022f7b8>] (kobj_attr_store+0x14/0x20) from [<c01542a8>] (sysfs_write_file+0x100/0x184) [ 811.227020] [<c01542a8>] (sysfs_write_file+0x100/0x184) from [<c00f8d88>] (vfs_write+0xb4/0x148) [ 811.227050] [<c00f8d88>] (vfs_write+0xb4/0x148) from [<c00f9010>] (sys_write+0x40/0x70)
[ 811.227081] [<c00f9010>] (sys_write+0x40/0x70) from [<c00132a0>] (ret_fast_syscall+0x0/0x3c) [ 811.227111] ---[ end trace 870223ea4a1b1519 ]---
[ 811.227294] Device failed to respond within 0 poweroff time. Forcefully powering down the device [ 811.336791] PM: suspend of devices complete after 119.435 msecs
[ 811.340118] PM: late suspend of devices complete after 3.328 msecs
[ 811.340148] Disabling non-boot CPUs ...
[ 811.340393] PM: Resume timer in 4.000 secs (131072 ticks at 32768 ticks/sec.)
[ 812.226165] Successfully put all powerdomains to target state
[ 812.228851] PM: early resume of devices complete after 2.229 msecs
[ 812.994049] PM: resume of devices complete after 763.887 msecs
[ 813.452484] PM: Finishing wakeup.
[ 813.455871] Restarting tasks ... done.
/ # a
--
To unsubscribe from this list: send the line "unsubscribe linux-mmc" in
the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Kevin Hilman

Tested-by

2011-11-18 19:43 UTC #2 lore raw

Hello Girish,

Quoted 7 lines · Girish K S

Quoted 6 lines · Kevin Hilman
Hello,
Using Linus' master branch, I was testing PM functionality on OMAP3/4 and noticed that the MMC driver is now rather noisy during suspend on OMAP3[1], but seems to work.

[...]

Quoted 16 lines

Quoted 15 lines

/ # echo mem > /sys/power/state

[  811.145507] PM: Syncing filesystems ... done.
[  811.150268] PM: Preparing system for mem sleep
[  811.155059] Freezing user space processes ... (elapsed 0.01 seconds) done.
[  811.179992] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
[  811.203460] PM: Entering mem sleep
[  811.207489] Suspending console(s) (use no_console_suspend to debug)
a[  811.225860] ------------[ cut here ]------------
[  811.225891] WARNING: at /work/kernel/omap/pm/drivers/mmc/core/core.c:453 mmc_wait_for_cmd+0x78/0x84()
[  811.225921] Modules linked in:
[  811.225952] [<c001a810>] (unwind_backtrace+0x0/0xf0) from [<c00525d0>] (warn_slowpath_common+0x4c/0x64)
[  811.225982] [<c00525d0>] (warn_slowpath_common+0x4c/0x64) from [<c0052604>] (warn_slowpath_null+0x1c/0x24)
[  811.226013] [<c0052604>] (warn_slowpath_null+0x1c/0x24) from [<c033a494>] (mmc_wait_for_cmd+0x78/0x84)
[  811.226043] [<c033a494>] (mmc_wait_for_cmd+0x78/0x84) from [<c033e7b8>] (mmc_switch+0x74/0x118)
[  811.226074] [<c033e7b8>] (mmc_switch+0x74/0x118) from [<c033b034>] (mmc_power_off+0xd8/0x108)

Quoted 4 lines

The problem is caused by the card->poweroff_notify_state = MMC_POWERED_ON; statement in the mmc_card_init function it is set for the non eMMC4.5 devices. I will rectify this and soon send a patch for the same.

Is this the patch that fixes this issue:

	http://article.gmane.org/gmane.linux.kernel.mmc/10961

I found this by digging (since I'm not subscribed to linux-mmc), but it would've been much more efficient if you Cc the original lists where the issue was reported, and especially the person reporting the bug so it can be tested by those reporting the problem.

I tested the above patch and verified it gets rid of all the noise in the OMAP HS-MMC driver.

Chris, I see this is already in mmc-next. Feel free to add:

Tested-by Kevin Hilman <[email protected]>

If you like.

Thanks,

Kevin

Girish K S

2011-11-21 03:32 UTC #3 lore raw

Quoted 56 lines · Kevin Hilman

Hello Girish,
Quoted 7 lines · Girish K S
Quoted 6 lines · Kevin Hilman
Hello,
Using Linus' master branch, I was testing PM functionality on OMAP3/4 and noticed that the MMC driver is now rather noisy during suspend on OMAP3[1], but seems to work.
[...]
Quoted 16 lines
Quoted 7 lines
/ # echo mem > /sys/power/state
[ 811.145507] PM: Syncing filesystems ... done.
[ 811.150268] PM: Preparing system for mem sleep
[ 811.155059] Freezing user space processes ... (elapsed 0.01 seconds) done. [ 811.179992] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done. [ 811.203460] PM: Entering mem sleep
[ 811.207489] Suspending console(s) (use no_console_suspend to debug)
Quoted 8 lines
a[ 811.225860] ------------[ cut here ]------------
[ 811.225891] WARNING: at /work/kernel/omap/pm/drivers/mmc/core/core.c:453 mmc_wait_for_cmd+0x78/0x84() [ 811.225921] Modules linked in:
[ 811.225952] [<c001a810>] (unwind_backtrace+0x0/0xf0) from [<c00525d0>] (warn_slowpath_common+0x4c/0x64) [ 811.225982] [<c00525d0>] (warn_slowpath_common+0x4c/0x64) from [<c0052604>] (warn_slowpath_null+0x1c/0x24) [ 811.226013] [<c0052604>] (warn_slowpath_null+0x1c/0x24) from [<c033a494>] (mmc_wait_for_cmd+0x78/0x84) [ 811.226043] [<c033a494>] (mmc_wait_for_cmd+0x78/0x84) from [<c033e7b8>] (mmc_switch+0x74/0x118) [ 811.226074] [<c033e7b8>] (mmc_switch+0x74/0x118) from [<c033b034>] (mmc_power_off+0xd8/0x108)
Quoted 4 lines
The problem is caused by the card->poweroff_notify_state = MMC_POWERED_ON; statement in the mmc_card_init function it is set for the non eMMC4.5 devices. I will rectify this and soon send a patch for the same.
Is this the patch that fixes this issue:
http://article.gmane.org/gmane.linux.kernel.mmc/10961
I found this by digging (since I'm not subscribed to linux-mmc), but it would've been much more efficient if you Cc the original lists where the issue was reported, and especially the person reporting the bug so it can be tested by those reporting the problem.
Did you mention in your first mail? "You are not subscribed in the list." I tested the above patch and verified it gets rid of all the noise in the OMAP HS-MMC driver.
Chris, I see this is already in mmc-next. Feel free to add:
Tested-by Kevin Hilman <[email protected]>
If you like.
Thanks,
Kevin

T Krishnamoorthy, Balaji

2011-11-04 11:59 UTC #4 lore raw

In reply to Kevin Hilman

Quoted 7 lines · Kevin Hilman

Hello,
Using Linus' master branch, I was testing PM functionality on OMAP3/4 and noticed that the MMC driver is now rather noisy during suspend on OMAP3[1], but seems to work.

Quoted 9 lines

On OMAP4, MMC seems to prevent suspend/resume all together. I haven't found the root cause, but know that by not buidling the MMC driver, I have working suspend/resume again on OMAP4.
Venkat, can you investigate this?
For OMAP4, please use my for_3.2/omap4-pm branch which has the OMAP4 MPUSS retention support from Santosh.

With 4430SDP I observed abort on accessing I2C registers probably i2c clock is not turned ON?

echo mem > /sys/power/state

[   41.971649] PM: Preparing system for mem sleep
[   41.976440] Freezing user space processes ... (elapsed 0.02 seconds) done.
[   42.002838] Freezing remaining freezable tasks ... (elapsed 0.02
seconds) done.
[   42.033172] PM: Entering mem sleep
[   42.043212] omap_hsmmc omap_hsmmc.4: context was not lost
[   42.043212] omap_hsmmc omap_hsmmc.4: enabled
[   42.043212] mmc2: clock 0Hz busmode 1 powermode 0 cs 0 Vdd 0 width 0 timing 0
[   42.060852] omap_hsmmc omap_hsmmc.4: Set clock to 0Hz
[   42.066192] omap_device: omap_hsmmc.0: new worst case activate
latency 0: 5310058
[   42.074035] omap_hsmmc omap_hsmmc.0: context was not lost
[   42.074035] omap_hsmmc omap_hsmmc.0: enabled
[   42.074035] mmc1: starting CMD7 arg 00000000 flags 00000000
[   42.090026] omap_hsmmc omap_hsmmc.0: mmc1: CMD7, argument 0x00000000
[   42.096679] omap_hsmmc omap_hsmmc.0: IRQ Status is 1
[   42.096710] mmc1: req done (CMD7): 0: 00000000 00000000 00000000 00000000
[   42.109008] mmc1: clock 0Hz busmode 1 powermode 0 cs 0 Vdd 0 width 0 timing 0
[   42.116668] omap_hsmmc omap_hsmmc.0: Set clock to 0Hz
[   42.122009] omap_hsmmc omap_hsmmc.1: context was not lost
[   42.127655] omap_hsmmc omap_hsmmc.1: enabled
[   42.132171] mmc0: starting CMD7 arg 00000000 flags 00000000
[   42.138000] omap_hsmmc omap_hsmmc.1: mmc0: CMD7, argument 0x00000000
[   42.144653] omap_hsmmc omap_hsmmc.1: IRQ Status is 1
[   42.144653] mmc0: req done (CMD7): 0: 00000000 00000000 00000000 00000000
[   42.159301] mmc0: starting CMD5 arg 00018000 flags 0000001d
[   42.165130] omap_hsmmc omap_hsmmc.1: mmc0: CMD5, argument 0x00018000
[   42.171783] omap_hsmmc omap_hsmmc.1: IRQ Status is 1
[   42.176971] omap_hsmmc omap_hsmmc.1: IRQ Status is 2
[   42.176971] mmc0: req done (CMD5): 0: 00000600 00000000 00000000 00000000
[   42.189270] mmc0: clock 0Hz busmode 1 powermode 0 cs 0 Vdd 0 width 0 timing 0
[   42.196929] TWL6030 IRQ 0x0 0x8 0x0
[   42.203765] omap_hsmmc omap_hsmmc.1: Set clock to 0Hz
[   42.203765] PM: suspend of devices complete after 166.717 msecs
[   42.216003] omap_hsmmc omap_hsmmc.4: disabled
[   42.221801] omap_hsmmc omap_hsmmc.0: disabled
[   42.226379] omap_hsmmc omap_hsmmc.1: disabled
[   42.230926] PM: late suspend of devices complete after 14.923 msecs
[   42.237609] Disabling non-boot CPUs ...
[   42.241790] Unhandled fault: imprecise external abort (0x1406) at 0x4005a000
[   42.241851] Internal error: : 1406 [#1] SMP
[   42.253509] Modules linked in:
[   42.256713] CPU: 0    Not tainted  (3.1.0-00165-g97d4c96-dirty #12)
[   42.256713] PC is at omap_i2c_wait_for_bb+0x88/0xa8
[   42.268341] LR is at omap_i2c_wait_for_bb+0x10/0xa8
[   42.273437] pc : [<c0351d84>]    lr : [<c0351d0c>]    psr: 40000013
[   42.273437] sp : ef9dfee8  ip : ffff7e58  fp : ef8f2c00
[   42.273437] r10: ffff7e58  r9 : c035249c  r8 : 00000001
[   42.285430] r7 : c0c0c43c  r6 : c063e080  r5 : c063e080  r4 : ef8f2c00
[   42.285430] r3 : 00000000  r2 : 00000028  r1 : 00000028  r0 : 00000080
[   42.304504] Flags: nZcv  IRQs on  FIQs on  Mode SVC_32  ISA ARM
Segment kernel
[   42.304504] Control: 10c53c7d  Table: af10404a  DAC: 00000017
[   42.304504] Process twl6030-irq (pid: 251, stack limit = 0xef9de2f8)
[   42.304504] Stack: (0xef9dfee8 to 0xef9e0000)
[   42.329284] fee0:                   ef8f2ca8 00000000 c063e080
c03524c8 ef9dfef8 00000001
[   42.337829] ff00: ef997460 ef8f2c70 c02b7ce4 ef8f2c60 00000000
c063e080 c0c0c43c 00000001
[   42.337829] ff20: c035249c ffff7e58 00000004 c0350188 ef9dff84
00000000 c0c0c454 00000068
[   42.354888] ff40: c0c0c3cc c0c0c3c4 c0c0c434 c02b7d2c 00000000
00000008 00000000 c0c0c640
[   42.363433] ff60: ef9dff84 c0c0c640 c047cba4 00000027 00000030
00000000 00000000 c02b8fc8
[   42.363433] ff80: 60000013 000000d0 ef833d18 00000002 00000027
c02b8e88 00000000 00000000
[   42.380493] ffa0: 00000000 c0073628 00000001 00000000 00000027
00000000 00000000 dead4ead
[   42.380493] ffc0: ffffffff ffffffff c06d4a74 00000000 00000000
c05628f4 ef9dffd8 ef9dffd8
[   42.380493] ffe0: ef833d18 ef833d18 c00735a0 c0015358 00000013
c0015358 64946642 61340b38
[   42.380493] [<c0351d84>] (omap_i2c_wait_for_bb+0x88/0xa8) from
[<c03524c8>] (omap_i2c_xfer+0x2c/0x388)
[   42.415832] [<c03524c8>] (omap_i2c_xfer+0x2c/0x388) from
[<c0350188>] (i2c_transfer+0xa8/0x118)
[   42.415832] [<c0350188>] (i2c_transfer+0xa8/0x118) from
[<c02b7d2c>] (twl_i2c_write+0xa8/0x124)
[   42.433990] [<c02b7d2c>] (twl_i2c_write+0xa8/0x124) from
[<c02b8fc8>] (twl6030_irq_thread+0x140/0x1a4)
[   42.443725] [<c02b8fc8>] (twl6030_irq_thread+0x140/0x1a4) from
[<c0073628>] (kthread+0x88/0x90)
[   42.443725] [<c0073628>] (kthread+0x88/0x90) from [<c0015358>]
(kernel_thread_exit+0x0/0x8)
[   42.461517] Code: e1a00312 e19010bc e3110a01 1afffff1 (e3a00000)
[   42.467895] ---[ end trace bfbd839e645b5cd8 ]---
[   42.473388] CPU1: shutdown