Message ID | 20190109223452.11184-3-niklas.soderlund+renesas@ragnatech.se (mailing list archive) |
---|---|
State | New, archived |
Headers | show |
Series | mmc: tmio: improve how runtime PM is enabled | expand |
On Wed, Jan 09, 2019 at 11:34:52PM +0100, Niklas Söderlund wrote: > Both the Renesas and Uniphier implementations perform actions which > effects runtime PM before calling into the core tmio_mmc_probe() which affect > enabled runtime PM. Move pm_runtime_enable() from the core and > tmio_mmc_probe() into each drivers probe() so it can be called before tmio_mmc_host_probe(). One more time above, too. > any clocks or other resources are switched on. Can you add some kerneldoc to tmio_mmc_host_probe() which describes this new requirement of pm_runtime being enabled before calling? Rest looks good.
Hi Niklas, On Wed, Jan 9, 2019 at 11:36 PM Niklas Söderlund <niklas.soderlund+renesas@ragnatech.se> wrote: > Both the Renesas and Uniphier implementations perform actions which > effects runtime PM before calling into the core tmio_mmc_probe() which > enabled runtime PM. Move pm_runtime_enable() from the core and > tmio_mmc_probe() into each drivers probe() so it can be called before > any clocks or other resources are switched on. > > Reported-by: Geert Uytterhoeven <geert+renesas@glider.be> > Signed-off-by: Niklas Söderlund <niklas.soderlund+renesas@ragnatech.se> Thanks for your patch! /sys/kernel/debug/clk/clk_summary after boot (without your patch): ape6evm (R-Mobile APE6): mmc1 0 0 0 12500000 0 0 50000 mmcif1 0 0 0 12500000 0 0 50000 mmc0 1 1 0 100000000 0 0 50000 mmcif0 2 2 0 100000000 0 0 50000 sdhi2ck 0 0 0 12500000 0 0 50000 sdhi2 0 0 0 12500000 0 0 50000 sdhi1ck 1 1 0 12500000 0 0 50000 sdhi1 2 2 0 12500000 0 0 50000 sdhi0ck 1 1 0 88888888 0 0 50000 sdhi0 1 2 0 88888888 0 0 50000 kzm9g (SH-Mobile AG5): sdhi2ck 1 1 0 69333333 0 0 50000 sdhi2 2 2 0 69333333 0 0 50000 sdhi1ck 0 0 0 69333333 0 0 50000 sdhi1 0 0 0 69333333 0 0 50000 sdhi0ck 1 1 0 69333333 0 0 50000 sdhi0 1 2 0 69333333 0 0 50000 m3-n-salvator-xs (R-Car M3-N): .sdsrc 3 3 0 798720000 0 0 50000 sd3 1 1 0 12480000 0 0 50000 sdif3 1 2 0 12480000 0 0 50000 sd2 1 1 0 199680000 0 0 50000 sdif2 1 2 0 199680000 0 0 50000 sd1 0 0 0 199680000 0 0 50000 sdif1 0 0 0 199680000 0 0 50000 sd0 1 1 0 12480000 0 0 50000 sdif0 1 2 0 12480000 0 0 50000 /sys/kernel/debug/clk/clk_summary after boot (with your patch): ape6evm: mmc1 0 0 0 12500000 0 0 50000 mmcif1 0 0 0 12500000 0 0 50000 mmc0 1 1 0 100000000 0 0 50000 mmcif0 2 2 0 100000000 0 0 50000 sdhi2ck 0 0 0 12500000 0 0 50000 sdhi2 0 0 0 12500000 0 0 50000 sdhi1ck 1 1 0 12500000 0 0 50000 sdhi1 3 3 0 12500000 0 0 50000 sdhi0ck 1 1 0 88888888 0 0 50000 sdhi0 3 3 0 88888888 0 0 50000 kzm9g: sdhi2ck 1 1 0 69333333 0 0 50000 sdhi2 3 3 0 69333333 0 0 50000 sdhi1ck 0 0 0 69333333 0 0 50000 sdhi1 0 0 0 69333333 0 0 50000 sdhi0ck 1 1 0 69333333 0 0 50000 sdhi0 3 3 0 69333333 0 0 50000 m3-n-salvator-xs: .sdsrc 3 3 0 798720000 0 0 50000 sd3 1 1 0 12480000 0 0 50000 sdif3 3 3 0 12480000 0 0 50000 sd2 1 1 0 199680000 0 0 50000 sdif2 3 3 0 199680000 0 0 50000 sd1 0 0 0 199680000 0 0 50000 sdif1 0 0 0 199680000 0 0 50000 sd0 1 1 0 12480000 0 0 50000 sdif0 3 3 0 12480000 0 0 50000 Unfortunately the clock imbalance isn't gone. After resume from s2ram (with your patch): ape6evm: mmc1 0 0 0 12500000 0 0 50000 mmcif1 0 0 0 12500000 0 0 50000 mmc0 0 1 0 100000000 0 0 50000 mmcif0 0 1 0 100000000 0 0 50000 sdhi2ck 0 0 0 12500000 0 0 50000 sdhi2 0 0 0 12500000 0 0 50000 sdhi1ck 1 1 0 12500000 0 0 50000 sdhi1 1 2 0 12500000 0 0 50000 sdhi0ck 1 1 0 88888888 0 0 50000 sdhi0 3 3 0 88888888 0 0 50000 kzm9g: sdhi2ck 1 1 0 69333333 0 0 50000 sdhi2 1 2 0 69333333 0 0 50000 sdhi1ck 0 0 0 69333333 0 0 50000 sdhi1 0 0 0 69333333 0 0 50000 sdhi0ck 1 1 0 69333333 0 0 50000 sdhi0 3 3 0 69333333 0 0 50000 And my debug prints in genpd_st{art,op}_dev() still tell me the device is cycled continuously after resume from s2ram: ape6evm: [ 761.928322] ==== a3sp/ee120000.sd: start [ 762.017086] ==== a3sp/ee120000.sd: stop [ 762.968418] ==== a3sp/ee120000.sd: start [ 763.057139] ==== a3sp/ee120000.sd: stop [ 764.008535] ==== a3sp/ee120000.sd: start [ 764.097261] ==== a3sp/ee120000.sd: stop [ 765.048621] ==== a3sp/ee120000.sd: start [ 765.137359] ==== a3sp/ee120000.sd: stop ... kzm9g: [ 403.676197] ==== a3sp/ee140000.sd: start [ 403.764984] ==== a3sp/ee140000.sd: stop [ 404.716462] ==== a3sp/ee140000.sd: start [ 404.805208] ==== a3sp/ee140000.sd: stop [ 405.756708] ==== a3sp/ee140000.sd: start [ 405.836766] ==== a3sp/ee140000.sd: stop ... Further s2ram cycles make no difference, as before. On R-Car M3-N, there is no such imbalance. This seems to happen on older SH/R-Mobile SoCs only. Gr{oetje,eeting}s, Geert
Hi Niklas, On Thu, Jan 10, 2019 at 5:23 PM Geert Uytterhoeven <geert@linux-m68k.org> wrote: > On Wed, Jan 9, 2019 at 11:36 PM Niklas Söderlund > <niklas.soderlund+renesas@ragnatech.se> wrote: > > Both the Renesas and Uniphier implementations perform actions which > > effects runtime PM before calling into the core tmio_mmc_probe() which > > enabled runtime PM. Move pm_runtime_enable() from the core and > > tmio_mmc_probe() into each drivers probe() so it can be called before > > any clocks or other resources are switched on. > > > > Reported-by: Geert Uytterhoeven <geert+renesas@glider.be> > > Signed-off-by: Niklas Söderlund <niklas.soderlund+renesas@ragnatech.se> > Unfortunately the clock imbalance isn't gone. > > And my debug prints in genpd_st{art,op}_dev() still tell me the device > is cycled continuously after resume from s2ram: > kzm9g: > > [ 403.676197] ==== a3sp/ee140000.sd: start > [ 403.764984] ==== a3sp/ee140000.sd: stop > [ 404.716462] ==== a3sp/ee140000.sd: start > [ 404.805208] ==== a3sp/ee140000.sd: stop > [ 405.756708] ==== a3sp/ee140000.sd: start > [ 405.836766] ==== a3sp/ee140000.sd: stop > ... > > Further s2ram cycles make no difference, as before. > > On R-Car M3-N, there is no such imbalance. This seems to happen > on older SH/R-Mobile SoCs only. As you don't have an ape6evm or kzm9g board, I've sprinkled a few WARN(!strcmp(core->name, "sdhi2"), ...) in the clk_core_(un)prepare() and clk_core_{dis,en}enable() functions on kzm9g. And guess what, the clock imbalance is gone, just like the start/stop debug messages! Likewise, on ape6evm the clock imbalance for sdhi1 disappears when adding a similar WARN() for the sdhi1 clock! The imbalance for mmcif0 is still there. If I change the WARN() to check for mmcif0 instead of sdhi1, the imbalance for sdhi1 reappears. Interestingly, there imbalance for mmcif0 now has a different form: - mmcif0 2 2 0 100000000 0 0 50000 + mmcif0 1 1 0 100000000 0 0 50000 Before it was prepare_count = 0 / enable_count = 1 instead of 1/1. I.e. the clock is prepared and enabled once less than before, due to sh_mmcif_set_ios() not being reenabled during resume, cfr. the log below. The biggest mystery is why adding the WARN() changes the prepare and enable counts. Is there a race condition? I thought the clock operations are protected by prepare_lock and enable_lock? /me puzzled... mmcif0 on r8a73a4 boot: WARNING: CPU: 0 PID: 1 at drivers/clk/clk.c:768 clk_core_prepare+0x94/0x388 clk_core_prepare: prepare_count++ => 1 [<c02d9f64>] (clk_core_prepare) from [<c02dd3c8>] (clk_prepare+0x1c/0x2c) [<c02dd3c8>] (clk_prepare) from [<c033a46c>] (__pm_clk_add+0xc0/0x124) [<c033a46c>] (__pm_clk_add) from [<c02e234c>] (cpg_mstp_attach_dev+0x100/0x14c) [<c02e234c>] (cpg_mstp_attach_dev) from [<c03382c0>] (genpd_add_device.constprop.9+0x1a4/0x1fc) [<c03382c0>] (genpd_add_device.constprop.9) from [<c0338c58>] (__genpd_dev_pm_attach+0xc4/0x1a8) [<c0338c58>] (__genpd_dev_pm_attach) from [<c032ca44>] (dev_pm_domain_attach+0x14/0x24) [<c032ca44>] (dev_pm_domain_attach) from [<c03262ec>] (platform_drv_probe+0x2c/0x94) [<c03262ec>] (platform_drv_probe) from [<c0324558>] (really_probe+0x1f0/0x2c0) WARNING: CPU: 0 PID: 1 at drivers/clk/clk.c:768 clk_core_prepare+0x94/0x388 clk_core_prepare: prepare_count++ => 2 [<c02d9f64>] (clk_core_prepare) from [<c02dd3c8>] (clk_prepare+0x1c/0x2c) [<c02dd3c8>] (clk_prepare) from [<c039033c>] (sh_mmcif_probe+0x1e0/0x4b4) [<c039033c>] (sh_mmcif_probe) from [<c0326308>] (platform_drv_probe+0x48/0x94) [<c0326308>] (platform_drv_probe) from [<c0324558>] (really_probe+0x1f0/0x2c0) WARNING: CPU: 0 PID: 1 at drivers/clk/clk.c:911 clk_core_enable+0x1f4/0x30c clk_core_enable: enable_count++ => 1 [<c02db738>] (clk_core_enable) from [<c02db868>] (clk_core_enable_lock+0x18/0x2c) [<c02db868>] (clk_core_enable_lock) from [<c039034c>] (sh_mmcif_probe+0x1f0/0x4b4) [<c039034c>] (sh_mmcif_probe) from [<c0326308>] (platform_drv_probe+0x48/0x94) [<c0326308>] (platform_drv_probe) from [<c0324558>] (really_probe+0x1f0/0x2c0) WARNING: CPU: 0 PID: 1 at drivers/clk/clk.c:911 clk_core_enable+0x1f4/0x30c clk_core_enable: enable_count++ => 2 [<c02db738>] (clk_core_enable) from [<c02db868>] (clk_core_enable_lock+0x18/0x2c) [<c02db868>] (clk_core_enable_lock) from [<c033aa78>] (pm_clk_resume+0x68/0xa0) [<c033aa78>] (pm_clk_resume) from [<c0338e88>] (genpd_runtime_resume+0x14c/0x1ac) [<c0338e88>] (genpd_runtime_resume) from [<c032e1f0>] (__rpm_callback+0x30/0x188) [<c032e1f0>] (__rpm_callback) from [<c032e3b8>] (rpm_callback+0x70/0x80) [<c032e3b8>] (rpm_callback) from [<c032ee6c>] (rpm_resume+0x584/0x62c) [<c032ee6c>] (rpm_resume) from [<c032e1a4>] (__pm_runtime_resume+0x78/0x94) [<c032e1a4>] (__pm_runtime_resume) from [<c0390410>] (sh_mmcif_probe+0x2b4/0x4b4) [<c0390410>] (sh_mmcif_probe) from [<c0326308>] (platform_drv_probe+0x48/0x94) [<c0326308>] (platform_drv_probe) from [<c0324558>] (really_probe+0x1f0/0x2c0) WARNING: CPU: 0 PID: 1 at drivers/clk/clk.c:768 clk_core_prepare+0x94/0x388 clk_core_prepare: prepare_count++ => 3 [<c02d9f64>] (clk_core_prepare) from [<c02dd3c8>] (clk_prepare+0x1c/0x2c) [<c02dd3c8>] (clk_prepare) from [<c038ffb4>] (sh_mmcif_set_ios+0xb8/0x260) [<c038ffb4>] (sh_mmcif_set_ios) from [<c037aca4>] (mmc_power_up+0x44/0xcc) [<c037aca4>] (mmc_power_up) from [<c037be00>] (mmc_start_host+0x4c/0x78) [<c037be00>] (mmc_start_host) from [<c037d080>] (mmc_add_host+0x64/0x78) [<c037d080>] (mmc_add_host) from [<c0390554>] (sh_mmcif_probe+0x3f8/0x4b4) [<c0390554>] (sh_mmcif_probe) from [<c0326308>] (platform_drv_probe+0x48/0x94) [<c0326308>] (platform_drv_probe) from [<c0324558>] (really_probe+0x1f0/0x2c0) WARNING: CPU: 0 PID: 1 at drivers/clk/clk.c:911 clk_core_enable+0x1f4/0x30c clk_core_enable: enable_count++ => 3 [<c02db738>] (clk_core_enable) from [<c02db868>] (clk_core_enable_lock+0x18/0x2c) [<c02db868>] (clk_core_enable_lock) from [<c038ffc4>] (sh_mmcif_set_ios+0xc8/0x260) [<c038ffc4>] (sh_mmcif_set_ios) from [<c037aca4>] (mmc_power_up+0x44/0xcc) [<c037aca4>] (mmc_power_up) from [<c037be00>] (mmc_start_host+0x4c/0x78) [<c037be00>] (mmc_start_host) from [<c037d080>] (mmc_add_host+0x64/0x78) [<c037d080>] (mmc_add_host) from [<c0390554>] (sh_mmcif_probe+0x3f8/0x4b4) [<c0390554>] (sh_mmcif_probe) from [<c0326308>] (platform_drv_probe+0x48/0x94) [<c0326308>] (platform_drv_probe) from [<c0324558>] (really_probe+0x1f0/0x2c0) WARNING: CPU: 0 PID: 1 at drivers/clk/clk.c:834 clk_core_disable+0x1f0/0x304 clk_core_disable: 3 => --enable_count [<c02da54c>] (clk_core_disable) from [<c02daf40>] (clk_core_disable_lock+0x18/0x24) [<c02daf40>] (clk_core_disable_lock) from [<c03905ac>] (sh_mmcif_probe+0x450/0x4b4) [<c03905ac>] (sh_mmcif_probe) from [<c0326308>] (platform_drv_probe+0x48/0x94) [<c0326308>] (platform_drv_probe) from [<c0324558>] (really_probe+0x1f0/0x2c0) WARNING: CPU: 0 PID: 1 at drivers/clk/clk.c:694 clk_core_unprepare+0x2d4/0x3c0 clk_core_unprepare: 3 => --prepare_count [<c02d9de4>] (clk_core_unprepare) from [<c02dd3a4>] (clk_unprepare+0x24/0x2c) [<c02dd3a4>] (clk_unprepare) from [<c03905b4>] (sh_mmcif_probe+0x458/0x4b4) [<c03905b4>] (sh_mmcif_probe) from [<c0326308>] (platform_drv_probe+0x48/0x94) [<c0326308>] (platform_drv_probe) from [<c0324558>] (really_probe+0x1f0/0x2c0) => mmcif0 prepare_count = 2, enable_count = 2 suspend: WARNING: CPU: 0 PID: 7 at drivers/clk/clk.c:834 clk_core_disable+0x1f0/0x304 clk_core_disable: 2 => --enable_count [<c02da54c>] (clk_core_disable) from [<c02daf40>] (clk_core_disable_lock+0x18/0x24) [<c02daf40>] (clk_core_disable_lock) from [<c0390134>] (sh_mmcif_set_ios+0x238/0x260) [<c0390134>] (sh_mmcif_set_ios) from [<c037ad60>] (mmc_power_off+0x34/0x44) [<c037ad60>] (mmc_power_off) from [<c037daf0>] (_mmc_suspend+0x11c/0x24c) [<c037daf0>] (_mmc_suspend) from [<c037dc80>] (mmc_suspend+0x10/0x40) [<c037dc80>] (mmc_suspend) from [<c037c0c0>] (mmc_bus_suspend+0x28/0x40) [<c037c0c0>] (mmc_bus_suspend) from [<c0331930>] (dpm_run_callback+0x194/0x344) [<c0331930>] (dpm_run_callback) from [<c0333090>] (__device_suspend+0x16c/0x618) [<c0333090>] (__device_suspend) from [<c0333a54>] (async_suspend+0x18/0x84) [<c0333a54>] (async_suspend) from [<c0051284>] (async_run_entry_fn+0x44/0x110) [<c0051284>] (async_run_entry_fn) from [<c00473b4>] (process_one_work+0x3ac/0x6a4) [<c00473b4>] (process_one_work) from [<c0047964>] (worker_thread+0x28c/0x40c) [<c0047964>] (worker_thread) from [<c004dc14>] (kthread+0x140/0x15c) WARNING: CPU: 0 PID: 7 at drivers/clk/clk.c:694 clk_core_unprepare+0x2d4/0x3c0 clk_core_unprepare: 2 => --prepare_count [<c02d9de4>] (clk_core_unprepare) from [<c02dd3a4>] (clk_unprepare+0x24/0x2c) [<c02dd3a4>] (clk_unprepare) from [<c039013c>] (sh_mmcif_set_ios+0x240/0x260) [<c039013c>] (sh_mmcif_set_ios) from [<c037ad60>] (mmc_power_off+0x34/0x44) [<c037ad60>] (mmc_power_off) from [<c037daf0>] (_mmc_suspend+0x11c/0x24c) [<c037daf0>] (_mmc_suspend) from [<c037dc80>] (mmc_suspend+0x10/0x40) [<c037dc80>] (mmc_suspend) from [<c037c0c0>] (mmc_bus_suspend+0x28/0x40) [<c037c0c0>] (mmc_bus_suspend) from [<c0331930>] (dpm_run_callback+0x194/0x344) [<c0331930>] (dpm_run_callback) from [<c0333090>] (__device_suspend+0x16c/0x618) [<c0333090>] (__device_suspend) from [<c0333a54>] (async_suspend+0x18/0x84) [<c0333a54>] (async_suspend) from [<c0051284>] (async_run_entry_fn+0x44/0x110) [<c0051284>] (async_run_entry_fn) from [<c00473b4>] (process_one_work+0x3ac/0x6a4) [<c00473b4>] (process_one_work) from [<c0047964>] (worker_thread+0x28c/0x40c) [<c0047964>] (worker_thread) from [<c004dc14>] (kthread+0x140/0x15c) WARNING: CPU: 0 PID: 562 at drivers/clk/clk.c:834 clk_core_disable+0x1f0/0x304 clk_core_disable: 1 => --enable_count [<c02da54c>] (clk_core_disable) from [<c02daf40>] (clk_core_disable_lock+0x18/0x24) [<c02daf40>] (clk_core_disable_lock) from [<c033a9fc>] (pm_clk_suspend+0x64/0x78) [<c033a9fc>] (pm_clk_suspend) from [<c03384cc>] (genpd_finish_suspend+0xac/0x118) [<c03384cc>] (genpd_finish_suspend) from [<c0331930>] (dpm_run_callback+0x194/0x344) [<c0331930>] (dpm_run_callback) from [<c0334500>] (__device_suspend_noirq+0x108/0x280) [<c0334500>] (__device_suspend_noirq) from [<c033499c>] (dpm_noirq_suspend_devices+0x324/0x494) [<c033499c>] (dpm_noirq_suspend_devices) from [<c0334b20>] (dpm_suspend_noirq+0x14/0x30) [<c0334b20>] (dpm_suspend_noirq) from [<c008e400>] (suspend_devices_and_enter+0x614/0xcb0) [<c008e400>] (suspend_devices_and_enter) from [<c008f420>] (pm_suspend+0x984/0xa14) [<c008f420>] (pm_suspend) from [<c008cc0c>] (state_store+0x9c/0xcc) [<c008cc0c>] (state_store) from [<c01e4100>] (kernfs_fop_write+0x154/0x1cc) [<c01e4100>] (kernfs_fop_write) from [<c016a21c>] (__vfs_write+0x28/0x178) [<c016a21c>] (__vfs_write) from [<c016a4fc>] (vfs_write+0xb8/0x14c) [<c016a4fc>] (vfs_write) from [<c016a6c0>] (ksys_write+0x4c/0x9c) [<c016a6c0>] (ksys_write) from [<c000a000>] (ret_fast_syscall+0x0/0x28) resume WARNING: CPU: 0 PID: 562 at drivers/clk/clk.c:911 clk_core_enable+0x1f4/0x30c clk_core_enable: enable_count++ => 1 [<c02db738>] (clk_core_enable) from [<c02db868>] (clk_core_enable_lock+0x18/0x2c) [<c02db868>] (clk_core_enable_lock) from [<c033aa78>] (pm_clk_resume+0x68/0xa0) [<c033aa78>] (pm_clk_resume) from [<c0338784>] (genpd_resume_noirq+0xc0/0xd8) [<c0338784>] (genpd_resume_noirq) from [<c0331930>] (dpm_run_callback+0x194/0x344) [<c0331930>] (dpm_run_callback) from [<c0333e94>] (device_resume_noirq+0x144/0x1b4) [<c0333e94>] (device_resume_noirq) from [<c03341fc>] (dpm_noirq_resume_devices+0x2f8/0x488) [<c03341fc>] (dpm_noirq_resume_devices) from [<c0334394>] (dpm_resume_noirq+0x8/0x10) [<c0334394>] (dpm_resume_noirq) from [<c008e810>] (suspend_devices_and_enter+0xa24/0xcb0) [<c008e810>] (suspend_devices_and_enter) from [<c008f420>] (pm_suspend+0x984/0xa14) [<c008f420>] (pm_suspend) from [<c008cc0c>] (state_store+0x9c/0xcc) [<c008cc0c>] (state_store) from [<c01e4100>] (kernfs_fop_write+0x154/0x1cc) [<c01e4100>] (kernfs_fop_write) from [<c016a21c>] (__vfs_write+0x28/0x178) [<c016a21c>] (__vfs_write) from [<c016a4fc>] (vfs_write+0xb8/0x14c) [<c016a4fc>] (vfs_write) from [<c016a6c0>] (ksys_write+0x4c/0x9c) [<c016a6c0>] (ksys_write) from [<c000a000>] (ret_fast_syscall+0x0/0x28) => mmcif0 prepare_count = 1, enable_count = 1 2nd suspend: WARNING: CPU: 0 PID: 636 at drivers/clk/clk.c:834 clk_core_disable+0x1f0/0x304 clk_core_disable: 1 => --enable_count [<c02da54c>] (clk_core_disable) from [<c02daf40>] (clk_core_disable_lock+0x18/0x24) [<c02daf40>] (clk_core_disable_lock) from [<c033a9fc>] (pm_clk_suspend+0x64/0x78) [<c033a9fc>] (pm_clk_suspend) from [<c03384cc>] (genpd_finish_suspend+0xac/0x118) [<c03384cc>] (genpd_finish_suspend) from [<c0331930>] (dpm_run_callback+0x194/0x344) [<c0331930>] (dpm_run_callback) from [<c0334500>] (__device_suspend_noirq+0x108/0x280) [<c0334500>] (__device_suspend_noirq) from [<c033499c>] (dpm_noirq_suspend_devices+0x324/0x494) [<c033499c>] (dpm_noirq_suspend_devices) from [<c0334b20>] (dpm_suspend_noirq+0x14/0x30) [<c0334b20>] (dpm_suspend_noirq) from [<c008e400>] (suspend_devices_and_enter+0x614/0xcb0) [<c008e400>] (suspend_devices_and_enter) from [<c008f420>] (pm_suspend+0x984/0xa14) [<c008f420>] (pm_suspend) from [<c008cc0c>] (state_store+0x9c/0xcc) [<c008cc0c>] (state_store) from [<c01e4100>] (kernfs_fop_write+0x154/0x1cc) [<c01e4100>] (kernfs_fop_write) from [<c016a21c>] (__vfs_write+0x28/0x178) [<c016a21c>] (__vfs_write) from [<c016a4fc>] (vfs_write+0xb8/0x14c) [<c016a4fc>] (vfs_write) from [<c016a6c0>] (ksys_write+0x4c/0x9c) [<c016a6c0>] (ksys_write) from [<c000a000>] (ret_fast_syscall+0x0/0x28) 2nd resume: WARNING: CPU: 0 PID: 636 at drivers/clk/clk.c:911 clk_core_enable+0x1f4/0x30c clk_core_enable: enable_count++ => 1 [<c02db738>] (clk_core_enable) from [<c02db868>] (clk_core_enable_lock+0x18/0x2c) [<c02db868>] (clk_core_enable_lock) from [<c033aa78>] (pm_clk_resume+0x68/0xa0) [<c033aa78>] (pm_clk_resume) from [<c0338784>] (genpd_resume_noirq+0xc0/0xd8) [<c0338784>] (genpd_resume_noirq) from [<c0331930>] (dpm_run_callback+0x194/0x344) [<c0331930>] (dpm_run_callback) from [<c0333e94>] (device_resume_noirq+0x144/0x1b4) [<c0333e94>] (device_resume_noirq) from [<c03341fc>] (dpm_noirq_resume_devices+0x2f8/0x488) [<c03341fc>] (dpm_noirq_resume_devices) from [<c0334394>] (dpm_resume_noirq+0x8/0x10) [<c0334394>] (dpm_resume_noirq) from [<c008e810>] (suspend_devices_and_enter+0xa24/0xcb0) [<c008e810>] (suspend_devices_and_enter) from [<c008f420>] (pm_suspend+0x984/0xa14) [<c008f420>] (pm_suspend) from [<c008cc0c>] (state_store+0x9c/0xcc) [<c008cc0c>] (state_store) from [<c01e4100>] (kernfs_fop_write+0x154/0x1cc) [<c01e4100>] (kernfs_fop_write) from [<c016a21c>] (__vfs_write+0x28/0x178) [<c016a21c>] (__vfs_write) from [<c016a4fc>] (vfs_write+0xb8/0x14c) [<c016a4fc>] (vfs_write) from [<c016a6c0>] (ksys_write+0x4c/0x9c) [<c016a6c0>] (ksys_write) from [<c000a000>] (ret_fast_syscall+0x0/0x28) => mmcif0 prepare_count = 1, enable_count = 1 Gr{oetje,eeting}s, Geert -- Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org In personal conversations with technical people, I call myself a hacker. But when I'm talking to journalists I just say "programmer" or something like that. -- Linus Torvalds
Hi Geert, Thanks for your feedback. Sorry for following up a tad late on this getting hold of and getting started with the APE6 took some time (thanks again for your help in that area too!). On 2019-01-10 17:23:46 +0100, Geert Uytterhoeven wrote: > Hi Niklas, > > On Wed, Jan 9, 2019 at 11:36 PM Niklas Söderlund > <niklas.soderlund+renesas@ragnatech.se> wrote: > > Both the Renesas and Uniphier implementations perform actions which > > effects runtime PM before calling into the core tmio_mmc_probe() which > > enabled runtime PM. Move pm_runtime_enable() from the core and > > tmio_mmc_probe() into each drivers probe() so it can be called before > > any clocks or other resources are switched on. > > > > Reported-by: Geert Uytterhoeven <geert+renesas@glider.be> > > Signed-off-by: Niklas Söderlund <niklas.soderlund+renesas@ragnatech.se> > > Thanks for your patch! > > /sys/kernel/debug/clk/clk_summary after boot (without your patch): > > ape6evm (R-Mobile APE6): > > mmc1 0 0 0 12500000 0 0 50000 > mmcif1 0 0 0 12500000 0 0 50000 > mmc0 1 1 0 100000000 0 0 50000 > mmcif0 2 2 0 100000000 0 0 50000 > sdhi2ck 0 0 0 12500000 0 0 50000 > sdhi2 0 0 0 12500000 0 0 50000 > sdhi1ck 1 1 0 12500000 0 0 50000 > sdhi1 2 2 0 12500000 0 0 50000 > sdhi0ck 1 1 0 88888888 0 0 50000 > sdhi0 1 2 0 88888888 0 0 50000 > > kzm9g (SH-Mobile AG5): > > sdhi2ck 1 1 0 69333333 0 0 50000 > sdhi2 2 2 0 69333333 0 0 50000 > sdhi1ck 0 0 0 69333333 0 0 50000 > sdhi1 0 0 0 69333333 0 0 50000 > sdhi0ck 1 1 0 69333333 0 0 50000 > sdhi0 1 2 0 69333333 0 0 50000 > > m3-n-salvator-xs (R-Car M3-N): > > .sdsrc 3 3 0 798720000 0 0 50000 > sd3 1 1 0 12480000 0 0 50000 > sdif3 1 2 0 12480000 0 0 50000 > sd2 1 1 0 199680000 0 0 50000 > sdif2 1 2 0 199680000 0 0 50000 > sd1 0 0 0 199680000 0 0 50000 > sdif1 0 0 0 199680000 0 0 50000 > sd0 1 1 0 12480000 0 0 50000 > sdif0 1 2 0 12480000 0 0 50000 > > > /sys/kernel/debug/clk/clk_summary after boot (with your patch): > > ape6evm: > > mmc1 0 0 0 12500000 0 0 50000 > mmcif1 0 0 0 12500000 0 0 50000 > mmc0 1 1 0 100000000 0 0 50000 > mmcif0 2 2 0 100000000 0 0 50000 > sdhi2ck 0 0 0 12500000 0 0 50000 > sdhi2 0 0 0 12500000 0 0 50000 > sdhi1ck 1 1 0 12500000 0 0 50000 > sdhi1 3 3 0 12500000 0 0 50000 > sdhi0ck 1 1 0 88888888 0 0 50000 > sdhi0 3 3 0 88888888 0 0 50000 > > kzm9g: > > sdhi2ck 1 1 0 69333333 0 0 50000 > sdhi2 3 3 0 69333333 0 0 50000 > sdhi1ck 0 0 0 69333333 0 0 50000 > sdhi1 0 0 0 69333333 0 0 50000 > sdhi0ck 1 1 0 69333333 0 0 50000 > sdhi0 3 3 0 69333333 0 0 50000 > > m3-n-salvator-xs: > > .sdsrc 3 3 0 798720000 0 0 50000 > sd3 1 1 0 12480000 0 0 50000 > sdif3 3 3 0 12480000 0 0 50000 > sd2 1 1 0 199680000 0 0 50000 > sdif2 3 3 0 199680000 0 0 50000 > sd1 0 0 0 199680000 0 0 50000 > sdif1 0 0 0 199680000 0 0 50000 > sd0 1 1 0 12480000 0 0 50000 > sdif0 3 3 0 12480000 0 0 50000 > > > Unfortunately the clock imbalance isn't gone. > After resume from s2ram (with your patch): > > ape6evm: > > mmc1 0 0 0 12500000 0 0 50000 > mmcif1 0 0 0 12500000 0 0 50000 > mmc0 0 1 0 100000000 0 0 50000 > mmcif0 0 1 0 100000000 0 0 50000 These clocks are handled by the sh_mmcif driver and I observe the same thing. I suspect however that this is the correct behavior as the driver uses dev_pm_qos_expose_latency_limit() and trying to use the mmc changes this to 1/1 and it seems to work fine. My knowledge in this area of PM is not good so I might be wrong but I'm not trying to deal with this clock in this patch. > sdhi2ck 0 0 0 12500000 0 0 50000 > sdhi2 0 0 0 12500000 0 0 50000 > sdhi1ck 1 1 0 12500000 0 0 50000 > sdhi1 1 2 0 12500000 0 0 50000 > sdhi0ck 1 1 0 88888888 0 0 50000 > sdhi0 3 3 0 88888888 0 0 50000 I can not reproduce this with this patch on top of v4.20 which the original patch was based on nor on today's mmc/next. For me clocks are the same as before suspending. I do however get this result if I run on ether base without this patch. > > kzm9g: > > sdhi2ck 1 1 0 69333333 0 0 50000 > sdhi2 1 2 0 69333333 0 0 50000 > sdhi1ck 0 0 0 69333333 0 0 50000 > sdhi1 0 0 0 69333333 0 0 50000 > sdhi0ck 1 1 0 69333333 0 0 50000 > sdhi0 3 3 0 69333333 0 0 50000 > > And my debug prints in genpd_st{art,op}_dev() still tell me the device > is cycled continuously after resume from s2ram: > > ape6evm: > > [ 761.928322] ==== a3sp/ee120000.sd: start > [ 762.017086] ==== a3sp/ee120000.sd: stop > [ 762.968418] ==== a3sp/ee120000.sd: start > [ 763.057139] ==== a3sp/ee120000.sd: stop > [ 764.008535] ==== a3sp/ee120000.sd: start > [ 764.097261] ==== a3sp/ee120000.sd: stop > [ 765.048621] ==== a3sp/ee120000.sd: start > [ 765.137359] ==== a3sp/ee120000.sd: stop > ... I tried the same on my end and I can observe the start and stop as I expected and can't observe this ping-pong. > > kzm9g: > > [ 403.676197] ==== a3sp/ee140000.sd: start > [ 403.764984] ==== a3sp/ee140000.sd: stop > [ 404.716462] ==== a3sp/ee140000.sd: start > [ 404.805208] ==== a3sp/ee140000.sd: stop > [ 405.756708] ==== a3sp/ee140000.sd: start > [ 405.836766] ==== a3sp/ee140000.sd: stop > ... > > Further s2ram cycles make no difference, as before. > > On R-Car M3-N, there is no such imbalance. This seems to happen > on older SH/R-Mobile SoCs only. I will send out a v2 of 2/2 addressing Wolframs comments, I would appreciate if you could test that as well as I'm not able to reproduce the same issue as you. I'm using the same configuration you sent me when you helped me to get started with the APE6EVM.
diff --git a/drivers/mmc/host/renesas_sdhi_core.c b/drivers/mmc/host/renesas_sdhi_core.c index 31a351a20dc02aab..ab07f9d1f7909412 100644 --- a/drivers/mmc/host/renesas_sdhi_core.c +++ b/drivers/mmc/host/renesas_sdhi_core.c @@ -755,6 +755,8 @@ int renesas_sdhi_probe(struct platform_device *pdev, /* All SDHI have SDIO status bits which must be 1 */ mmc_data->flags |= TMIO_MMC_SDIO_STATUS_SETBITS; + pm_runtime_enable(&pdev->dev); + ret = renesas_sdhi_clk_enable(host); if (ret) goto efree; @@ -833,6 +835,8 @@ int renesas_sdhi_probe(struct platform_device *pdev, efree: tmio_mmc_host_free(host); + pm_runtime_disable(&pdev->dev); + return ret; } EXPORT_SYMBOL_GPL(renesas_sdhi_probe); @@ -844,6 +848,8 @@ int renesas_sdhi_remove(struct platform_device *pdev) tmio_mmc_host_remove(host); renesas_sdhi_clk_disable(host); + pm_runtime_disable(&pdev->dev); + return 0; } EXPORT_SYMBOL_GPL(renesas_sdhi_remove); diff --git a/drivers/mmc/host/tmio_mmc.c b/drivers/mmc/host/tmio_mmc.c index 93e83ad25976e756..8539e10784b40961 100644 --- a/drivers/mmc/host/tmio_mmc.c +++ b/drivers/mmc/host/tmio_mmc.c @@ -172,6 +172,8 @@ static int tmio_mmc_probe(struct platform_device *pdev) host->mmc->f_max = pdata->hclk; host->mmc->f_min = pdata->hclk / 512; + pm_runtime_enable(&pdev->dev); + ret = tmio_mmc_host_probe(host); if (ret) goto host_free; @@ -191,6 +193,7 @@ static int tmio_mmc_probe(struct platform_device *pdev) tmio_mmc_host_remove(host); host_free: tmio_mmc_host_free(host); + pm_runtime_disable(&pdev->dev); cell_disable: if (cell->disable) cell->disable(pdev); @@ -207,6 +210,8 @@ static int tmio_mmc_remove(struct platform_device *pdev) if (cell->disable) cell->disable(pdev); + pm_runtime_disable(&pdev->dev); + return 0; } diff --git a/drivers/mmc/host/tmio_mmc_core.c b/drivers/mmc/host/tmio_mmc_core.c index 7323a5935fff786f..efc0ca83c001b948 100644 --- a/drivers/mmc/host/tmio_mmc_core.c +++ b/drivers/mmc/host/tmio_mmc_core.c @@ -1253,7 +1253,6 @@ int tmio_mmc_host_probe(struct tmio_mmc_host *_host) pm_runtime_set_active(&pdev->dev); pm_runtime_set_autosuspend_delay(&pdev->dev, 50); pm_runtime_use_autosuspend(&pdev->dev); - pm_runtime_enable(&pdev->dev); ret = mmc_add_host(mmc); if (ret) @@ -1289,7 +1288,6 @@ void tmio_mmc_host_remove(struct tmio_mmc_host *host) pm_runtime_dont_use_autosuspend(&pdev->dev); pm_runtime_put_sync(&pdev->dev); - pm_runtime_disable(&pdev->dev); } EXPORT_SYMBOL_GPL(tmio_mmc_host_remove); diff --git a/drivers/mmc/host/uniphier-sd.c b/drivers/mmc/host/uniphier-sd.c index 91a2be41edf6196b..49aad9a79c18d24a 100644 --- a/drivers/mmc/host/uniphier-sd.c +++ b/drivers/mmc/host/uniphier-sd.c @@ -631,6 +631,7 @@ static int uniphier_sd_probe(struct platform_device *pdev) host->clk_disable = uniphier_sd_clk_disable; host->set_clock = uniphier_sd_set_clock; + pm_runtime_enable(&pdev->dev); ret = uniphier_sd_clk_enable(host); if (ret) goto free_host; @@ -652,6 +653,7 @@ static int uniphier_sd_probe(struct platform_device *pdev) free_host: tmio_mmc_host_free(host); + pm_runtime_disable(&pdev->dev); return ret; } @@ -662,6 +664,7 @@ static int uniphier_sd_remove(struct platform_device *pdev) tmio_mmc_host_remove(host); uniphier_sd_clk_disable(host); + pm_runtime_disable(&pdev->dev); return 0; }
Both the Renesas and Uniphier implementations perform actions which effects runtime PM before calling into the core tmio_mmc_probe() which enabled runtime PM. Move pm_runtime_enable() from the core and tmio_mmc_probe() into each drivers probe() so it can be called before any clocks or other resources are switched on. Reported-by: Geert Uytterhoeven <geert+renesas@glider.be> Signed-off-by: Niklas Söderlund <niklas.soderlund+renesas@ragnatech.se> --- drivers/mmc/host/renesas_sdhi_core.c | 6 ++++++ drivers/mmc/host/tmio_mmc.c | 5 +++++ drivers/mmc/host/tmio_mmc_core.c | 2 -- drivers/mmc/host/uniphier-sd.c | 3 +++ 4 files changed, 14 insertions(+), 2 deletions(-)