Hi Niklas,
On Thu, Jan 10, 2019 at 5:23 PM Geert Uytterhoeven <geert@xxxxxxxxxxxxxx> wrote:
> On Wed, Jan 9, 2019 at 11:36 PM Niklas Söderlund
> <niklas.soderlund+renesas@xxxxxxxxxxxx> 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@xxxxxxxxx>
> > Signed-off-by: Niklas Söderlund <niklas.soderlund+renesas@xxxxxxxxxxxx>
> 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@xxxxxxxxxxxxxx
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
