* Re: [PATCH V2 2/2] cpufreq: dt: Refactor initialization to handle probe deferral properly [not found] ` <f75c61f193f396608d592ae2a9938264d582c038.1598260050.git.viresh.kumar@linaro.org> @ 2020-10-13 9:47 ` Geert Uytterhoeven 2020-10-13 9:56 ` Viresh Kumar 0 siblings, 1 reply; 10+ messages in thread From: Geert Uytterhoeven @ 2020-10-13 9:47 UTC (permalink / raw) To: Viresh Kumar, Stephan Gerhold Cc: Ulf Hansson, Rafael J. Wysocki, Liam Girdwood, Mark Brown, Linux PM list, Vincent Guittot, Stephen Boyd, Nishanth Menon, nks, Georgi Djakov, Linux Kernel Mailing List, Wolfram Sang, Linux I2C, Linux-Renesas Hi Viresh, Stephan, On Mon, Aug 24, 2020 at 11:12 AM Viresh Kumar <viresh.kumar@linaro.org> wrote: > From: Stephan Gerhold <stephan@gerhold.net> > > cpufreq-dt is currently unable to handle -EPROBE_DEFER properly > because the error code is not propagated for the cpufreq_driver->init() > callback. Instead, it attempts to avoid the situation by temporarily > requesting all resources within resources_available() and releasing them > again immediately after. This has several disadvantages: > > - Whenever we add something like interconnect handling to the OPP core > we need to patch cpufreq-dt to request these resources early. > > - resources_available() is only run for CPU0, but other clusters may > eventually depend on other resources that are not available yet. > (See FIXME comment removed by this commit...) > > - All resources need to be looked up several times. > > Now that the OPP core can propagate -EPROBE_DEFER during initialization, > it would be nice to avoid all that trouble and just propagate its error > code when necessary. > > This commit refactors the cpufreq-dt driver to initialize private_data > before registering the cpufreq driver. We do this by iterating over > all possible CPUs and ensure that all resources are initialized: > > 1. dev_pm_opp_get_opp_table() ensures the OPP table is allocated > and initialized with clock and interconnects. > > 2. dev_pm_opp_set_regulators() requests the regulators and assigns > them to the OPP table. > > 3. We call dev_pm_opp_of_get_sharing_cpus() early so that we only > initialize the OPP table once for each shared policy. > > With these changes, we actually end up saving a few lines of code, > the resources are no longer looked up multiple times and everything > should be much more robust. > > Signed-off-by: Stephan Gerhold <stephan@gerhold.net> > [ Viresh: Use list_head structure for maintaining the list and minor > changes ] > Signed-off-by: Viresh Kumar <viresh.kumar@linaro.org> Thanks for your patch, which is now commit dc279ac6e5b4e06e ("cpufreq: dt: Refactor initialization to handle probe deferral properly") in pm/linux-next, and to which I bisected a regression. Reverting this commit fixes the issue. On r8a7791/koelsch, during resume from s2ram: PM: suspend entry (deep) Filesystems sync: 0.000 seconds Freezing user space processes ... (elapsed 0.003 seconds) done. OOM killer disabled. Freezing remaining freezable tasks ... (elapsed 0.009 seconds) done. Disabling non-boot CPUs ... Enabling non-boot CPUs ... +i2c-sh_mobile e60b0000.i2c: Transfer request timed out +i2c-sh_mobile e60b0000.i2c: Transfer request timed out +i2c-sh_mobile e60b0000.i2c: Transfer request timed out +i2c-sh_mobile e60b0000.i2c: Transfer request timed out +i2c-sh_mobile e60b0000.i2c: Transfer request timed out +i2c-sh_mobile e60b0000.i2c: Transfer request timed out +i2c-sh_mobile e60b0000.i2c: Transfer request timed out +i2c-sh_mobile e60b0000.i2c: Transfer request timed out +i2c-sh_mobile e60b0000.i2c: Transfer request timed out +i2c-sh_mobile e60b0000.i2c: Transfer request timed out +i2c-sh_mobile e60b0000.i2c: Transfer request timed out +i2c-sh_mobile e60b0000.i2c: Transfer request timed out +cpu cpu0: OPP table can't be empty CPU1 is up rcar-pcie fe000000.pcie: PCIe x1: link up The cpufreq code tries to talk to the PMIC, while the I2C controller that hosts the PMIC is suspended, and thus any communication attempt times out. __i2c_check_suspended() fails to notice that, as the i2c_shmobile_i2c driver doesn't have a suspend callback calling i2c_mark_adapter_suspended() yet. After fixing that (will send a patch soon), the I2C core rightfully complains with: WARNING: CPU: 1 PID: 13 at drivers/i2c/i2c-core.h:54 __i2c_transfer+0x4a4/0x4e4 i2c i2c-6: Transfer while suspended CPU: 1 PID: 13 Comm: cpuhp/1 Not tainted 5.9.0-shmobile-09581-g05a3e5886c7615b1-dirty #718 Hardware name: Generic R-Car Gen2 (Flattened Device Tree) [<c010dcec>] (unwind_backtrace) from [<c0109b18>] (show_stack+0x10/0x14) [<c0109b18>] (show_stack) from [<c075e928>] (dump_stack+0x8c/0xac) [<c075e928>] (dump_stack) from [<c011c23c>] (__warn+0xd0/0xe8) [<c011c23c>] (__warn) from [<c011c2c4>] (warn_slowpath_fmt+0x70/0x9c) [<c011c2c4>] (warn_slowpath_fmt) from [<c0548be8>] (__i2c_transfer+0x4a4/0x4e4) [<c0548be8>] (__i2c_transfer) from [<c0548cd8>] (i2c_transfer+0xb0/0xf8) [<c0548cd8>] (i2c_transfer) from [<c046f884>] (regmap_i2c_read+0x54/0x88) [<c046f884>] (regmap_i2c_read) from [<c046b69c>] (_regmap_raw_read+0x118/0x1f0) [<c046b69c>] (_regmap_raw_read) from [<c046b7b8>] (_regmap_bus_read+0x44/0x68) [<c046b7b8>] (_regmap_bus_read) from [<c04698a0>] (_regmap_read+0x84/0x110) [<c04698a0>] (_regmap_read) from [<c046c10c>] (regmap_read+0x40/0x58) [<c046c10c>] (regmap_read) from [<c03cf0a8>] (regulator_get_voltage_sel_regmap+0x28/0x74) [<c03cf0a8>] (regulator_get_voltage_sel_regmap) from [<c03cb29c>] (regulator_get_voltage_rdev+0xa4/0x14c) [<c03cb29c>] (regulator_get_voltage_rdev) from [<c03cc658>] (regulator_get_voltage+0x2c/0x60) [<c03cc658>] (regulator_get_voltage) from [<c03cd994>] (regulator_is_supported_voltage+0x30/0xd8) [<c03cd994>] (regulator_is_supported_voltage) from [<c05a32b4>] (_opp_add+0x164/0x1b8) [<c05a32b4>] (_opp_add) from [<c05a3388>] (_opp_add_v1+0x80/0xb8) [<c05a3388>] (_opp_add_v1) from [<c05a5220>] (dev_pm_opp_of_add_table+0x130/0x168) [<c05a5220>] (dev_pm_opp_of_add_table) from [<c05a5330>] (dev_pm_opp_of_cpumask_add_table+0x60/0xac) [<c05a5330>] (dev_pm_opp_of_cpumask_add_table) from [<c05ab88c>] (cpufreq_init+0x94/0x1c4) [<c05ab88c>] (cpufreq_init) from [<c05a8190>] (cpufreq_online+0x148/0x7ac) [<c05a8190>] (cpufreq_online) from [<c05a87fc>] (cpuhp_cpufreq_online+0x8/0x10) [<c05a87fc>] (cpuhp_cpufreq_online) from [<c011d088>] (cpuhp_invoke_callback+0xf8/0x2e4) [<c011d088>] (cpuhp_invoke_callback) from [<c011d418>] (cpuhp_thread_fun+0xac/0x244) [<c011d418>] (cpuhp_thread_fun) from [<c013c090>] (smpboot_thread_fn+0x19c/0x1a8) [<c013c090>] (smpboot_thread_fn) from [<c0138408>] (kthread+0x104/0x110) [<c0138408>] (kthread) from [<c0100148>] (ret_from_fork+0x14/0x2c) 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH V2 2/2] cpufreq: dt: Refactor initialization to handle probe deferral properly 2020-10-13 9:47 ` [PATCH V2 2/2] cpufreq: dt: Refactor initialization to handle probe deferral properly Geert Uytterhoeven @ 2020-10-13 9:56 ` Viresh Kumar 2020-10-14 16:40 ` Geert Uytterhoeven 0 siblings, 1 reply; 10+ messages in thread From: Viresh Kumar @ 2020-10-13 9:56 UTC (permalink / raw) To: Geert Uytterhoeven Cc: Stephan Gerhold, Ulf Hansson, Rafael J. Wysocki, Liam Girdwood, Mark Brown, Linux PM list, Vincent Guittot, Stephen Boyd, Nishanth Menon, nks, Georgi Djakov, Linux Kernel Mailing List, Wolfram Sang, Linux I2C, Linux-Renesas On 13-10-20, 11:47, Geert Uytterhoeven wrote: > Thanks for your patch, which is now commit dc279ac6e5b4e06e ("cpufreq: > dt: Refactor initialization to handle probe deferral properly") in > pm/linux-next, and to which I bisected a regression. > Reverting this commit fixes the issue. Strange. I had a look again and I failed to understand why it would happen this way. > On r8a7791/koelsch, during resume from s2ram: > > PM: suspend entry (deep) > Filesystems sync: 0.000 seconds > Freezing user space processes ... (elapsed 0.003 seconds) done. > OOM killer disabled. > Freezing remaining freezable tasks ... (elapsed 0.009 seconds) done. > Disabling non-boot CPUs ... > Enabling non-boot CPUs ... > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > +cpu cpu0: OPP table can't be empty > CPU1 is up > rcar-pcie fe000000.pcie: PCIe x1: link up > > The cpufreq code tries to talk to the PMIC, while the I2C controller > that hosts the PMIC is suspended, and thus any communication attempt > times out. __i2c_check_suspended() fails to notice that, as the > i2c_shmobile_i2c driver doesn't have a suspend callback calling > i2c_mark_adapter_suspended() yet. After fixing that (will send a patch > soon), the I2C core rightfully complains with: > > WARNING: CPU: 1 PID: 13 at drivers/i2c/i2c-core.h:54 > __i2c_transfer+0x4a4/0x4e4 > i2c i2c-6: Transfer while suspended > CPU: 1 PID: 13 Comm: cpuhp/1 Not tainted > 5.9.0-shmobile-09581-g05a3e5886c7615b1-dirty #718 > Hardware name: Generic R-Car Gen2 (Flattened Device Tree) > [<c010dcec>] (unwind_backtrace) from [<c0109b18>] (show_stack+0x10/0x14) > [<c0109b18>] (show_stack) from [<c075e928>] (dump_stack+0x8c/0xac) > [<c075e928>] (dump_stack) from [<c011c23c>] (__warn+0xd0/0xe8) > [<c011c23c>] (__warn) from [<c011c2c4>] (warn_slowpath_fmt+0x70/0x9c) > [<c011c2c4>] (warn_slowpath_fmt) from [<c0548be8>] > (__i2c_transfer+0x4a4/0x4e4) > [<c0548be8>] (__i2c_transfer) from [<c0548cd8>] (i2c_transfer+0xb0/0xf8) > [<c0548cd8>] (i2c_transfer) from [<c046f884>] (regmap_i2c_read+0x54/0x88) > [<c046f884>] (regmap_i2c_read) from [<c046b69c>] > (_regmap_raw_read+0x118/0x1f0) > [<c046b69c>] (_regmap_raw_read) from [<c046b7b8>] > (_regmap_bus_read+0x44/0x68) > [<c046b7b8>] (_regmap_bus_read) from [<c04698a0>] (_regmap_read+0x84/0x110) > [<c04698a0>] (_regmap_read) from [<c046c10c>] (regmap_read+0x40/0x58) > [<c046c10c>] (regmap_read) from [<c03cf0a8>] > (regulator_get_voltage_sel_regmap+0x28/0x74) > [<c03cf0a8>] (regulator_get_voltage_sel_regmap) from [<c03cb29c>] > (regulator_get_voltage_rdev+0xa4/0x14c) > [<c03cb29c>] (regulator_get_voltage_rdev) from [<c03cc658>] > (regulator_get_voltage+0x2c/0x60) > [<c03cc658>] (regulator_get_voltage) from [<c03cd994>] > (regulator_is_supported_voltage+0x30/0xd8) > [<c03cd994>] (regulator_is_supported_voltage) from [<c05a32b4>] > (_opp_add+0x164/0x1b8) > [<c05a32b4>] (_opp_add) from [<c05a3388>] (_opp_add_v1+0x80/0xb8) > [<c05a3388>] (_opp_add_v1) from [<c05a5220>] > (dev_pm_opp_of_add_table+0x130/0x168) > [<c05a5220>] (dev_pm_opp_of_add_table) from [<c05a5330>] > (dev_pm_opp_of_cpumask_add_table+0x60/0xac) > [<c05a5330>] (dev_pm_opp_of_cpumask_add_table) from [<c05ab88c>] > (cpufreq_init+0x94/0x1c4) > [<c05ab88c>] (cpufreq_init) from [<c05a8190>] (cpufreq_online+0x148/0x7ac) > [<c05a8190>] (cpufreq_online) from [<c05a87fc>] > (cpuhp_cpufreq_online+0x8/0x10) > [<c05a87fc>] (cpuhp_cpufreq_online) from [<c011d088>] > (cpuhp_invoke_callback+0xf8/0x2e4) > [<c011d088>] (cpuhp_invoke_callback) from [<c011d418>] > (cpuhp_thread_fun+0xac/0x244) > [<c011d418>] (cpuhp_thread_fun) from [<c013c090>] > (smpboot_thread_fn+0x19c/0x1a8) > [<c013c090>] (smpboot_thread_fn) from [<c0138408>] (kthread+0x104/0x110) > [<c0138408>] (kthread) from [<c0100148>] (ret_from_fork+0x14/0x2c) So there is a dependency chain here. cpufreq->regulator->i2c, specially with the patch you pointed out, we handle defer-probing in a better way and so I would expect i2c driver to get in first and cpufreq should get registered later only. And I would have expected the same during suspend/resume. Can you see why this happens ? -- viresh ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH V2 2/2] cpufreq: dt: Refactor initialization to handle probe deferral properly 2020-10-13 9:56 ` Viresh Kumar @ 2020-10-14 16:40 ` Geert Uytterhoeven 2020-10-16 5:03 ` Viresh Kumar 0 siblings, 1 reply; 10+ messages in thread From: Geert Uytterhoeven @ 2020-10-14 16:40 UTC (permalink / raw) To: Viresh Kumar Cc: Stephan Gerhold, Ulf Hansson, Rafael J. Wysocki, Liam Girdwood, Mark Brown, Linux PM list, Vincent Guittot, Stephen Boyd, Nishanth Menon, nks, Georgi Djakov, Linux Kernel Mailing List, Wolfram Sang, Linux I2C, Linux-Renesas Hi Viresh, On Tue, Oct 13, 2020 at 11:56 AM Viresh Kumar <viresh.kumar@linaro.org> wrote: > On 13-10-20, 11:47, Geert Uytterhoeven wrote: > > Thanks for your patch, which is now commit dc279ac6e5b4e06e ("cpufreq: > > dt: Refactor initialization to handle probe deferral properly") in > > pm/linux-next, and to which I bisected a regression. > > Reverting this commit fixes the issue. > > Strange. I had a look again and I failed to understand why it would > happen this way. > > > On r8a7791/koelsch, during resume from s2ram: > > > > PM: suspend entry (deep) > > Filesystems sync: 0.000 seconds > > Freezing user space processes ... (elapsed 0.003 seconds) done. > > OOM killer disabled. > > Freezing remaining freezable tasks ... (elapsed 0.009 seconds) done. > > Disabling non-boot CPUs ... > > Enabling non-boot CPUs ... > > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > +i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > +cpu cpu0: OPP table can't be empty > > CPU1 is up > > rcar-pcie fe000000.pcie: PCIe x1: link up > > > > The cpufreq code tries to talk to the PMIC, while the I2C controller > > that hosts the PMIC is suspended, and thus any communication attempt > > times out. __i2c_check_suspended() fails to notice that, as the > > i2c_shmobile_i2c driver doesn't have a suspend callback calling > > i2c_mark_adapter_suspended() yet. After fixing that (will send a patch > > soon), the I2C core rightfully complains with: > > > > WARNING: CPU: 1 PID: 13 at drivers/i2c/i2c-core.h:54 > > __i2c_transfer+0x4a4/0x4e4 > > i2c i2c-6: Transfer while suspended > > CPU: 1 PID: 13 Comm: cpuhp/1 Not tainted > > 5.9.0-shmobile-09581-g05a3e5886c7615b1-dirty #718 > > Hardware name: Generic R-Car Gen2 (Flattened Device Tree) > > [<c010dcec>] (unwind_backtrace) from [<c0109b18>] (show_stack+0x10/0x14) > > [<c0109b18>] (show_stack) from [<c075e928>] (dump_stack+0x8c/0xac) > > [<c075e928>] (dump_stack) from [<c011c23c>] (__warn+0xd0/0xe8) > > [<c011c23c>] (__warn) from [<c011c2c4>] (warn_slowpath_fmt+0x70/0x9c) > > [<c011c2c4>] (warn_slowpath_fmt) from [<c0548be8>] > > (__i2c_transfer+0x4a4/0x4e4) > > [<c0548be8>] (__i2c_transfer) from [<c0548cd8>] (i2c_transfer+0xb0/0xf8) > > [<c0548cd8>] (i2c_transfer) from [<c046f884>] (regmap_i2c_read+0x54/0x88) > > [<c046f884>] (regmap_i2c_read) from [<c046b69c>] > > (_regmap_raw_read+0x118/0x1f0) > > [<c046b69c>] (_regmap_raw_read) from [<c046b7b8>] > > (_regmap_bus_read+0x44/0x68) > > [<c046b7b8>] (_regmap_bus_read) from [<c04698a0>] (_regmap_read+0x84/0x110) > > [<c04698a0>] (_regmap_read) from [<c046c10c>] (regmap_read+0x40/0x58) > > [<c046c10c>] (regmap_read) from [<c03cf0a8>] > > (regulator_get_voltage_sel_regmap+0x28/0x74) > > [<c03cf0a8>] (regulator_get_voltage_sel_regmap) from [<c03cb29c>] > > (regulator_get_voltage_rdev+0xa4/0x14c) > > [<c03cb29c>] (regulator_get_voltage_rdev) from [<c03cc658>] > > (regulator_get_voltage+0x2c/0x60) > > [<c03cc658>] (regulator_get_voltage) from [<c03cd994>] > > (regulator_is_supported_voltage+0x30/0xd8) > > [<c03cd994>] (regulator_is_supported_voltage) from [<c05a32b4>] > > (_opp_add+0x164/0x1b8) > > [<c05a32b4>] (_opp_add) from [<c05a3388>] (_opp_add_v1+0x80/0xb8) > > [<c05a3388>] (_opp_add_v1) from [<c05a5220>] > > (dev_pm_opp_of_add_table+0x130/0x168) > > [<c05a5220>] (dev_pm_opp_of_add_table) from [<c05a5330>] > > (dev_pm_opp_of_cpumask_add_table+0x60/0xac) > > [<c05a5330>] (dev_pm_opp_of_cpumask_add_table) from [<c05ab88c>] > > (cpufreq_init+0x94/0x1c4) > > [<c05ab88c>] (cpufreq_init) from [<c05a8190>] (cpufreq_online+0x148/0x7ac) > > [<c05a8190>] (cpufreq_online) from [<c05a87fc>] > > (cpuhp_cpufreq_online+0x8/0x10) > > [<c05a87fc>] (cpuhp_cpufreq_online) from [<c011d088>] > > (cpuhp_invoke_callback+0xf8/0x2e4) > > [<c011d088>] (cpuhp_invoke_callback) from [<c011d418>] > > (cpuhp_thread_fun+0xac/0x244) > > [<c011d418>] (cpuhp_thread_fun) from [<c013c090>] > > (smpboot_thread_fn+0x19c/0x1a8) > > [<c013c090>] (smpboot_thread_fn) from [<c0138408>] (kthread+0x104/0x110) > > [<c0138408>] (kthread) from [<c0100148>] (ret_from_fork+0x14/0x2c) > > So there is a dependency chain here. cpufreq->regulator->i2c, > specially with the patch you pointed out, we handle defer-probing in a > better way and so I would expect i2c driver to get in first and > cpufreq should get registered later only. And I would have expected > the same during suspend/resume. > > Can you see why this happens ? On this platform (r8a7791-koelsch.dts), there is no opp table in DT. Before: boot: cpufreq-dt cpufreq-dt: dt_cpufreq_probe:362 cpu cpu0: resources_available:95 cpu cpu0: resources_available:102: clk_get() returned z cpu cpu0: resources_available:120: dev_pm_opp_of_find_icc_paths() returned 0 cpu cpu0: resources_available:125: find_supply_name() returned cpu0 cpu cpu0: resources_available:132: regulator_get_optional() returned -EPROBE_DEFER cpu cpu0: cpu0 regulator not ready, retry cpufreq-dt cpufreq-dt: dt_cpufreq_probe:371: resources_available() returned -517 ... cpufreq-dt cpufreq-dt: dt_cpufreq_probe:362 cpu cpu0: resources_available:95 cpu cpu0: resources_available:102: clk_get() returned z cpu cpu0: resources_available:120: dev_pm_opp_of_find_icc_paths() returned 0 cpu cpu0: resources_available:125: find_supply_name() returned cpu0 cpu cpu0: resources_available:132: regulator_get_optional() returned (ptrval) cpufreq-dt cpufreq-dt: dt_cpufreq_probe:371: resources_available() returned 0 cpufreq-dt cpufreq-dt: dt_cpufreq_probe:375 cpufreq_dt: cpufreq_init:162 cpu cpu0: cpufreq_init:170: clk_get() returned z cpu cpu0: cpufreq_init:179: dev_pm_opp_of_get_sharing_cpus() returned -2 cpu cpu0: cpufreq_init:198: find_supply_name() returned cpu0 <i2c comm> cpu cpu0: cpufreq_init:201: dev_pm_opp_set_regulators() returned (ptrval) <i2c comm> cpu cpu0: cpufreq_init:230: dev_pm_opp_of_cpumask_add_table() returned 0 cpu cpu0: cpufreq_init:239: dev_pm_opp_get_opp_count() returned 0 cpu cpu0: OPP table is not ready, deferring probe cpufreq_dt: cpufreq_init:162 cpu cpu1: cpufreq_init:170: clk_get() returned z cpu cpu1: cpufreq_init:179: dev_pm_opp_of_get_sharing_cpus() returned -2 cpu cpu1: no regulator for cpu1 cpu cpu1: cpufreq_init:198: find_supply_name() returned (null) cpu cpu1: cpufreq_init:230: dev_pm_opp_of_cpumask_add_table() returned 0 cpu cpu1: cpufreq_init:239: dev_pm_opp_get_opp_count() returned 0 cpu cpu1: OPP table is not ready, deferring probe s2ram: cpufreq_dt: cpufreq_init:162 cpu cpu1: cpufreq_init:170: clk_get() returned z cpu cpu1: cpufreq_init:179: dev_pm_opp_of_get_sharing_cpus() returned -2 cpu cpu1: no regulator for cpu1 cpu cpu1: cpufreq_init:198: find_supply_name() returned (null) cpu cpu1: cpufreq_init:230: dev_pm_opp_of_cpumask_add_table() returned 0 cpu cpu1: cpufreq_init:239: dev_pm_opp_get_opp_count() returned 0 cpu cpu1: OPP table is not ready, deferring probe CPU1 is up After: boot: cpufreq-dt cpufreq-dt: dt_cpufreq_probe:356 cpufreq_dt: dt_cpufreq_early_init:251 cpu cpu0: dt_cpufreq_early_init:256 cpu cpu0: dt_cpufreq_early_init:271: dev_pm_opp_get_opp_table() returned (ptrval) cpu cpu0: dt_cpufreq_early_init:284: find_supply_name() returned cpu0 cpu cpu0: dt_cpufreq_early_init:288: dev_pm_opp_set_regulators() returned -EPROBE_DEFER cpufreq-dt cpufreq-dt: dt_cpufreq_probe:360: dt_cpufreq_early_init() returned -517 ... cpufreq-dt cpufreq-dt: dt_cpufreq_probe:356 cpufreq_dt: dt_cpufreq_early_init:251 cpu cpu0: dt_cpufreq_early_init:256 cpu cpu0: dt_cpufreq_early_init:271: dev_pm_opp_get_opp_table() returned (ptrval) cpu cpu0: dt_cpufreq_early_init:284: find_supply_name() returned cpu0 cpu cpu0: dt_cpufreq_early_init:288: dev_pm_opp_set_regulators() returned (ptrval) cpu cpu0: dt_cpufreq_early_init:301: dev_pm_opp_of_get_sharing_cpus() returned -2 cpufreq-dt cpufreq-dt: dt_cpufreq_probe:360: dt_cpufreq_early_init() returned 0 cpufreq_dt: dt_cpufreq_early_init:251 cpufreq-dt cpufreq-dt: dt_cpufreq_probe:360: dt_cpufreq_early_init() returned 0 cpufreq-dt cpufreq-dt: dt_cpufreq_probe:365 cpufreq_dt: cpufreq_init:114 cpu cpu0: cpufreq_init:124: clk_get() returned z cpu cpu0: cpufreq_init:142: dev_pm_opp_of_cpumask_add_table() returned 0 cpu cpu0: cpufreq_init:151: dev_pm_opp_get_opp_count() returned 0 cpu cpu0: OPP table can't be empty cpufreq_dt: cpufreq_init:114 cpu cpu0: cpufreq_init:124: clk_get() returned z <i2c comm> cpu cpu0: cpufreq_init:142: dev_pm_opp_of_cpumask_add_table() returned 0 cpu cpu0: cpufreq_init:151: dev_pm_opp_get_opp_count() returned 0 s2ram: cpufreq_dt: cpufreq_init:114 cpu cpu0: cpufreq_init:124: clk_get() returned z WARNING: CPU: 1 PID: 14 at drivers/i2c/i2c-core.h:54 __i2c_transfer+0x2d8/0x310 i2c i2c-6: Transfer while suspended cpu cpu0: cpufreq_init:142: dev_pm_opp_of_cpumask_add_table() returned 0 cpu cpu0: cpufreq_init:151: dev_pm_opp_get_opp_count() returned 0 cpu cpu0: OPP table can't be empty CPU1 is up I hope this helps. Thanks! 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH V2 2/2] cpufreq: dt: Refactor initialization to handle probe deferral properly 2020-10-14 16:40 ` Geert Uytterhoeven @ 2020-10-16 5:03 ` Viresh Kumar 2020-10-16 6:44 ` Geert Uytterhoeven 0 siblings, 1 reply; 10+ messages in thread From: Viresh Kumar @ 2020-10-16 5:03 UTC (permalink / raw) To: Geert Uytterhoeven Cc: Stephan Gerhold, Ulf Hansson, Rafael J. Wysocki, Liam Girdwood, Mark Brown, Linux PM list, Vincent Guittot, Stephen Boyd, Nishanth Menon, nks, Georgi Djakov, Linux Kernel Mailing List, Wolfram Sang, Linux I2C, Linux-Renesas On 14-10-20, 18:40, Geert Uytterhoeven wrote: > On this platform (r8a7791-koelsch.dts), there is no opp table in DT. > > Before: I assume this means before this patchset came in.. > boot: > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:362 > cpu cpu0: resources_available:95 > cpu cpu0: resources_available:102: clk_get() returned z > cpu cpu0: resources_available:120: > dev_pm_opp_of_find_icc_paths() returned 0 > cpu cpu0: resources_available:125: find_supply_name() returned cpu0 > cpu cpu0: resources_available:132: regulator_get_optional() > returned -EPROBE_DEFER > cpu cpu0: cpu0 regulator not ready, retry > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:371: > resources_available() returned -517 we deferred probe once. > ... > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:362 > cpu cpu0: resources_available:95 > cpu cpu0: resources_available:102: clk_get() returned z > cpu cpu0: resources_available:120: > dev_pm_opp_of_find_icc_paths() returned 0 > cpu cpu0: resources_available:125: find_supply_name() returned cpu0 > cpu cpu0: resources_available:132: regulator_get_optional() > returned (ptrval) found regulator next time. > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:371: > resources_available() returned 0 > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:375 > cpufreq_dt: cpufreq_init:162 > cpu cpu0: cpufreq_init:170: clk_get() returned z > cpu cpu0: cpufreq_init:179: dev_pm_opp_of_get_sharing_cpus() returned -2 > cpu cpu0: cpufreq_init:198: find_supply_name() returned cpu0 > <i2c comm> > cpu cpu0: cpufreq_init:201: dev_pm_opp_set_regulators() returned (ptrval) > <i2c comm> > cpu cpu0: cpufreq_init:230: dev_pm_opp_of_cpumask_add_table() returned 0 > cpu cpu0: cpufreq_init:239: dev_pm_opp_get_opp_count() returned 0 > cpu cpu0: OPP table is not ready, deferring probe This failed, as we couldn't have deferred probe from cpufreq_init. Which means that cpufreq didn't work here. > cpufreq_dt: cpufreq_init:162 > cpu cpu1: cpufreq_init:170: clk_get() returned z > cpu cpu1: cpufreq_init:179: dev_pm_opp_of_get_sharing_cpus() returned -2 > cpu cpu1: no regulator for cpu1 > cpu cpu1: cpufreq_init:198: find_supply_name() returned (null) > cpu cpu1: cpufreq_init:230: dev_pm_opp_of_cpumask_add_table() returned 0 > cpu cpu1: cpufreq_init:239: dev_pm_opp_get_opp_count() returned 0 > cpu cpu1: OPP table is not ready, deferring probe Same for CPU1. > > s2ram: > cpufreq_dt: cpufreq_init:162 > cpu cpu1: cpufreq_init:170: clk_get() returned z > cpu cpu1: cpufreq_init:179: dev_pm_opp_of_get_sharing_cpus() returned -2 > cpu cpu1: no regulator for cpu1 > cpu cpu1: cpufreq_init:198: find_supply_name() returned (null) > cpu cpu1: cpufreq_init:230: dev_pm_opp_of_cpumask_add_table() returned 0 > cpu cpu1: cpufreq_init:239: dev_pm_opp_get_opp_count() returned 0 > cpu cpu1: OPP table is not ready, deferring probe And same here. > CPU1 is up > > After: > boot: > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:356 > cpufreq_dt: dt_cpufreq_early_init:251 > cpu cpu0: dt_cpufreq_early_init:256 > cpu cpu0: dt_cpufreq_early_init:271: dev_pm_opp_get_opp_table() > returned (ptrval) > cpu cpu0: dt_cpufreq_early_init:284: find_supply_name() returned cpu0 > cpu cpu0: dt_cpufreq_early_init:288: dev_pm_opp_set_regulators() > returned -EPROBE_DEFER > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:360: > dt_cpufreq_early_init() returned -517 > ... > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:356 > cpufreq_dt: dt_cpufreq_early_init:251 > cpu cpu0: dt_cpufreq_early_init:256 > cpu cpu0: dt_cpufreq_early_init:271: dev_pm_opp_get_opp_table() > returned (ptrval) > cpu cpu0: dt_cpufreq_early_init:284: find_supply_name() returned cpu0 > cpu cpu0: dt_cpufreq_early_init:288: dev_pm_opp_set_regulators() > returned (ptrval) > cpu cpu0: dt_cpufreq_early_init:301: > dev_pm_opp_of_get_sharing_cpus() returned -2 > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:360: > dt_cpufreq_early_init() returned 0 > cpufreq_dt: dt_cpufreq_early_init:251 > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:360: > dt_cpufreq_early_init() returned 0 > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:365 > cpufreq_dt: cpufreq_init:114 > cpu cpu0: cpufreq_init:124: clk_get() returned z > cpu cpu0: cpufreq_init:142: dev_pm_opp_of_cpumask_add_table() returned 0 > cpu cpu0: cpufreq_init:151: dev_pm_opp_get_opp_count() returned 0 > cpu cpu0: OPP table can't be empty Same issue here. > cpufreq_dt: cpufreq_init:114 > cpu cpu0: cpufreq_init:124: clk_get() returned z > <i2c comm> > cpu cpu0: cpufreq_init:142: dev_pm_opp_of_cpumask_add_table() returned 0 > cpu cpu0: cpufreq_init:151: dev_pm_opp_get_opp_count() returned 0 > > s2ram: > > cpufreq_dt: cpufreq_init:114 > cpu cpu0: cpufreq_init:124: clk_get() returned z > WARNING: CPU: 1 PID: 14 at drivers/i2c/i2c-core.h:54 > __i2c_transfer+0x2d8/0x310 > i2c i2c-6: Transfer while suspended > cpu cpu0: cpufreq_init:142: dev_pm_opp_of_cpumask_add_table() returned 0 > cpu cpu0: cpufreq_init:151: dev_pm_opp_get_opp_count() returned 0 > cpu cpu0: OPP table can't be empty > CPU1 is up > > I hope this helps. Unfortunately it raised more questions than what it answered :( -- viresh ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH V2 2/2] cpufreq: dt: Refactor initialization to handle probe deferral properly 2020-10-16 5:03 ` Viresh Kumar @ 2020-10-16 6:44 ` Geert Uytterhoeven 2020-10-16 8:07 ` Viresh Kumar 0 siblings, 1 reply; 10+ messages in thread From: Geert Uytterhoeven @ 2020-10-16 6:44 UTC (permalink / raw) To: Viresh Kumar Cc: Stephan Gerhold, Ulf Hansson, Rafael J. Wysocki, Liam Girdwood, Mark Brown, Linux PM list, Vincent Guittot, Stephen Boyd, Nishanth Menon, nks, Georgi Djakov, Linux Kernel Mailing List, Wolfram Sang, Linux I2C, Linux-Renesas Hi Viresh, On Fri, Oct 16, 2020 at 7:03 AM Viresh Kumar <viresh.kumar@linaro.org> wrote: > On 14-10-20, 18:40, Geert Uytterhoeven wrote: > > On this platform (r8a7791-koelsch.dts), there is no opp table in DT. I think you missed the clue above: this DTS does not have an opp-table with operating-points-v2, but cpu0 does have the operating-points (v1) property (note the latter is something I missed before). > > > > Before: > > I assume this means before this patchset came in.. Indeed. > > boot: > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:362 > > cpu cpu0: resources_available:95 > > cpu cpu0: resources_available:102: clk_get() returned z > > cpu cpu0: resources_available:120: > > dev_pm_opp_of_find_icc_paths() returned 0 > > cpu cpu0: resources_available:125: find_supply_name() returned cpu0 > > cpu cpu0: resources_available:132: regulator_get_optional() > > returned -EPROBE_DEFER > > cpu cpu0: cpu0 regulator not ready, retry > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:371: > > resources_available() returned -517 > > we deferred probe once. > > > ... > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:362 > > cpu cpu0: resources_available:95 > > cpu cpu0: resources_available:102: clk_get() returned z > > cpu cpu0: resources_available:120: > > dev_pm_opp_of_find_icc_paths() returned 0 > > cpu cpu0: resources_available:125: find_supply_name() returned cpu0 > > cpu cpu0: resources_available:132: regulator_get_optional() > > returned (ptrval) > > found regulator next time. > > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:371: > > resources_available() returned 0 > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:375 > > cpufreq_dt: cpufreq_init:162 > > cpu cpu0: cpufreq_init:170: clk_get() returned z > > cpu cpu0: cpufreq_init:179: dev_pm_opp_of_get_sharing_cpus() returned -2 > > cpu cpu0: cpufreq_init:198: find_supply_name() returned cpu0 > > <i2c comm> > > cpu cpu0: cpufreq_init:201: dev_pm_opp_set_regulators() returned (ptrval) > > <i2c comm> > > cpu cpu0: cpufreq_init:230: dev_pm_opp_of_cpumask_add_table() returned 0 > > cpu cpu0: cpufreq_init:239: dev_pm_opp_get_opp_count() returned 0 > > cpu cpu0: OPP table is not ready, deferring probe > > This failed, as we couldn't have deferred probe from cpufreq_init. > Which means that cpufreq didn't work here. No opp-table in DT. Shouldn't it use operating-points v1 instead? > > cpufreq_dt: cpufreq_init:162 > > cpu cpu1: cpufreq_init:170: clk_get() returned z > > cpu cpu1: cpufreq_init:179: dev_pm_opp_of_get_sharing_cpus() returned -2 > > cpu cpu1: no regulator for cpu1 > > cpu cpu1: cpufreq_init:198: find_supply_name() returned (null) > > cpu cpu1: cpufreq_init:230: dev_pm_opp_of_cpumask_add_table() returned 0 > > cpu cpu1: cpufreq_init:239: dev_pm_opp_get_opp_count() returned 0 > > cpu cpu1: OPP table is not ready, deferring probe > > Same for CPU1. Note that only CPU0 has operating-points v1. > > > > > s2ram: > > cpufreq_dt: cpufreq_init:162 > > cpu cpu1: cpufreq_init:170: clk_get() returned z > > cpu cpu1: cpufreq_init:179: dev_pm_opp_of_get_sharing_cpus() returned -2 > > cpu cpu1: no regulator for cpu1 > > cpu cpu1: cpufreq_init:198: find_supply_name() returned (null) > > cpu cpu1: cpufreq_init:230: dev_pm_opp_of_cpumask_add_table() returned 0 > > cpu cpu1: cpufreq_init:239: dev_pm_opp_get_opp_count() returned 0 > > cpu cpu1: OPP table is not ready, deferring probe > > And same here. > > > CPU1 is up > > > > After: > > boot: > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:356 > > cpufreq_dt: dt_cpufreq_early_init:251 > > cpu cpu0: dt_cpufreq_early_init:256 > > cpu cpu0: dt_cpufreq_early_init:271: dev_pm_opp_get_opp_table() > > returned (ptrval) > > cpu cpu0: dt_cpufreq_early_init:284: find_supply_name() returned cpu0 > > cpu cpu0: dt_cpufreq_early_init:288: dev_pm_opp_set_regulators() > > returned -EPROBE_DEFER > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:360: > > dt_cpufreq_early_init() returned -517 > > ... > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:356 > > cpufreq_dt: dt_cpufreq_early_init:251 > > cpu cpu0: dt_cpufreq_early_init:256 > > cpu cpu0: dt_cpufreq_early_init:271: dev_pm_opp_get_opp_table() > > returned (ptrval) > > cpu cpu0: dt_cpufreq_early_init:284: find_supply_name() returned cpu0 > > cpu cpu0: dt_cpufreq_early_init:288: dev_pm_opp_set_regulators() > > returned (ptrval) > > cpu cpu0: dt_cpufreq_early_init:301: > > dev_pm_opp_of_get_sharing_cpus() returned -2 > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:360: > > dt_cpufreq_early_init() returned 0 > > cpufreq_dt: dt_cpufreq_early_init:251 > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:360: > > dt_cpufreq_early_init() returned 0 > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:365 > > cpufreq_dt: cpufreq_init:114 > > cpu cpu0: cpufreq_init:124: clk_get() returned z > > cpu cpu0: cpufreq_init:142: dev_pm_opp_of_cpumask_add_table() returned 0 > > cpu cpu0: cpufreq_init:151: dev_pm_opp_get_opp_count() returned 0 > > cpu cpu0: OPP table can't be empty > > Same issue here. > > > cpufreq_dt: cpufreq_init:114 > > cpu cpu0: cpufreq_init:124: clk_get() returned z > > <i2c comm> > > cpu cpu0: cpufreq_init:142: dev_pm_opp_of_cpumask_add_table() returned 0 > > cpu cpu0: cpufreq_init:151: dev_pm_opp_get_opp_count() returned 0 > > > > s2ram: > > > > cpufreq_dt: cpufreq_init:114 > > cpu cpu0: cpufreq_init:124: clk_get() returned z > > WARNING: CPU: 1 PID: 14 at drivers/i2c/i2c-core.h:54 > > __i2c_transfer+0x2d8/0x310 > > i2c i2c-6: Transfer while suspended > > cpu cpu0: cpufreq_init:142: dev_pm_opp_of_cpumask_add_table() returned 0 > > cpu cpu0: cpufreq_init:151: dev_pm_opp_get_opp_count() returned 0 > > cpu cpu0: OPP table can't be empty > > CPU1 is up > > > > I hope this helps. > > Unfortunately it raised more questions than what it answered :( Before, it bailed out before talking to the regulator during s2ram, After, it talks to the regulator before bailing out, triggering the WARN(). 1. Why is it bailing out without an opp-table, as operating-points (v1) is present? 2. Even in the presence of an opp-table, the code would talk to the PMIC while the I2C controller is suspended. 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH V2 2/2] cpufreq: dt: Refactor initialization to handle probe deferral properly 2020-10-16 6:44 ` Geert Uytterhoeven @ 2020-10-16 8:07 ` Viresh Kumar 2020-10-27 16:29 ` Geert Uytterhoeven 0 siblings, 1 reply; 10+ messages in thread From: Viresh Kumar @ 2020-10-16 8:07 UTC (permalink / raw) To: Geert Uytterhoeven Cc: Stephan Gerhold, Ulf Hansson, Rafael J. Wysocki, Liam Girdwood, Mark Brown, Linux PM list, Vincent Guittot, Stephen Boyd, Nishanth Menon, nks, Georgi Djakov, Linux Kernel Mailing List, Wolfram Sang, Linux I2C, Linux-Renesas On 16-10-20, 08:44, Geert Uytterhoeven wrote: > On Fri, Oct 16, 2020 at 7:03 AM Viresh Kumar <viresh.kumar@linaro.org> wrote: > > On 14-10-20, 18:40, Geert Uytterhoeven wrote: > > > On this platform (r8a7791-koelsch.dts), there is no opp table in DT. > > I think you missed the clue above: I read it earlier as well. > this DTS does not have an opp-table > with operating-points-v2, but cpu0 does have the operating-points (v1) > property (note the latter is something I missed before). This is different than having no OPP table in DT. > > > > > > Before: > > > > I assume this means before this patchset came in.. > > Indeed. > > > > boot: > > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:362 > > > cpu cpu0: resources_available:95 > > > cpu cpu0: resources_available:102: clk_get() returned z > > > cpu cpu0: resources_available:120: > > > dev_pm_opp_of_find_icc_paths() returned 0 > > > cpu cpu0: resources_available:125: find_supply_name() returned cpu0 > > > cpu cpu0: resources_available:132: regulator_get_optional() > > > returned -EPROBE_DEFER > > > cpu cpu0: cpu0 regulator not ready, retry > > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:371: > > > resources_available() returned -517 > > > > we deferred probe once. > > > > > ... > > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:362 > > > cpu cpu0: resources_available:95 > > > cpu cpu0: resources_available:102: clk_get() returned z > > > cpu cpu0: resources_available:120: > > > dev_pm_opp_of_find_icc_paths() returned 0 > > > cpu cpu0: resources_available:125: find_supply_name() returned cpu0 > > > cpu cpu0: resources_available:132: regulator_get_optional() > > > returned (ptrval) > > > > found regulator next time. > > > > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:371: > > > resources_available() returned 0 > > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:375 > > > cpufreq_dt: cpufreq_init:162 > > > cpu cpu0: cpufreq_init:170: clk_get() returned z > > > cpu cpu0: cpufreq_init:179: dev_pm_opp_of_get_sharing_cpus() returned -2 > > > cpu cpu0: cpufreq_init:198: find_supply_name() returned cpu0 > > > <i2c comm> > > > cpu cpu0: cpufreq_init:201: dev_pm_opp_set_regulators() returned (ptrval) > > > <i2c comm> > > > cpu cpu0: cpufreq_init:230: dev_pm_opp_of_cpumask_add_table() returned 0 > > > cpu cpu0: cpufreq_init:239: dev_pm_opp_get_opp_count() returned 0 > > > cpu cpu0: OPP table is not ready, deferring probe > > > > This failed, as we couldn't have deferred probe from cpufreq_init. > > Which means that cpufreq didn't work here. > > No opp-table in DT. V1 is also an OPP table. > Shouldn't it use operating-points v1 instead? Both v1 and v2 are considered as OPP tables. When we say that the opp-count is 0, it means that it failed to find any of them. > > > cpufreq_dt: cpufreq_init:162 > > > cpu cpu1: cpufreq_init:170: clk_get() returned z > > > cpu cpu1: cpufreq_init:179: dev_pm_opp_of_get_sharing_cpus() returned -2 > > > cpu cpu1: no regulator for cpu1 > > > cpu cpu1: cpufreq_init:198: find_supply_name() returned (null) > > > cpu cpu1: cpufreq_init:230: dev_pm_opp_of_cpumask_add_table() returned 0 > > > cpu cpu1: cpufreq_init:239: dev_pm_opp_get_opp_count() returned 0 > > > cpu cpu1: OPP table is not ready, deferring probe > > > > Same for CPU1. > > Note that only CPU0 has operating-points v1. Both should have it ideally, though it works if CPU0 gets probed first. But if CPU0 is hotplugged out and we try to probe CPU1, then it will fail. The fact that cpufreq core tried to probe CPU1 means that it failed for CPU0. And this is before the patchset in question came in. I don't think cpufreq was working earlier for your platform, please check why. > > > > > > > > s2ram: > > > cpufreq_dt: cpufreq_init:162 > > > cpu cpu1: cpufreq_init:170: clk_get() returned z > > > cpu cpu1: cpufreq_init:179: dev_pm_opp_of_get_sharing_cpus() returned -2 > > > cpu cpu1: no regulator for cpu1 > > > cpu cpu1: cpufreq_init:198: find_supply_name() returned (null) > > > cpu cpu1: cpufreq_init:230: dev_pm_opp_of_cpumask_add_table() returned 0 > > > cpu cpu1: cpufreq_init:239: dev_pm_opp_get_opp_count() returned 0 > > > cpu cpu1: OPP table is not ready, deferring probe > > > > And same here. > > > > > CPU1 is up > > > > > > After: > > > boot: > > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:356 > > > cpufreq_dt: dt_cpufreq_early_init:251 > > > cpu cpu0: dt_cpufreq_early_init:256 > > > cpu cpu0: dt_cpufreq_early_init:271: dev_pm_opp_get_opp_table() > > > returned (ptrval) > > > cpu cpu0: dt_cpufreq_early_init:284: find_supply_name() returned cpu0 > > > cpu cpu0: dt_cpufreq_early_init:288: dev_pm_opp_set_regulators() > > > returned -EPROBE_DEFER > > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:360: > > > dt_cpufreq_early_init() returned -517 > > > ... > > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:356 > > > cpufreq_dt: dt_cpufreq_early_init:251 > > > cpu cpu0: dt_cpufreq_early_init:256 > > > cpu cpu0: dt_cpufreq_early_init:271: dev_pm_opp_get_opp_table() > > > returned (ptrval) > > > cpu cpu0: dt_cpufreq_early_init:284: find_supply_name() returned cpu0 > > > cpu cpu0: dt_cpufreq_early_init:288: dev_pm_opp_set_regulators() > > > returned (ptrval) > > > cpu cpu0: dt_cpufreq_early_init:301: > > > dev_pm_opp_of_get_sharing_cpus() returned -2 > > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:360: > > > dt_cpufreq_early_init() returned 0 > > > cpufreq_dt: dt_cpufreq_early_init:251 > > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:360: > > > dt_cpufreq_early_init() returned 0 > > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:365 > > > cpufreq_dt: cpufreq_init:114 > > > cpu cpu0: cpufreq_init:124: clk_get() returned z > > > cpu cpu0: cpufreq_init:142: dev_pm_opp_of_cpumask_add_table() returned 0 > > > cpu cpu0: cpufreq_init:151: dev_pm_opp_get_opp_count() returned 0 > > > cpu cpu0: OPP table can't be empty > > > > Same issue here. > > > > > cpufreq_dt: cpufreq_init:114 > > > cpu cpu0: cpufreq_init:124: clk_get() returned z > > > <i2c comm> > > > cpu cpu0: cpufreq_init:142: dev_pm_opp_of_cpumask_add_table() returned 0 > > > cpu cpu0: cpufreq_init:151: dev_pm_opp_get_opp_count() returned 0 > > > > > > s2ram: > > > > > > cpufreq_dt: cpufreq_init:114 > > > cpu cpu0: cpufreq_init:124: clk_get() returned z > > > WARNING: CPU: 1 PID: 14 at drivers/i2c/i2c-core.h:54 > > > __i2c_transfer+0x2d8/0x310 > > > i2c i2c-6: Transfer while suspended > > > cpu cpu0: cpufreq_init:142: dev_pm_opp_of_cpumask_add_table() returned 0 > > > cpu cpu0: cpufreq_init:151: dev_pm_opp_get_opp_count() returned 0 > > > cpu cpu0: OPP table can't be empty > > > CPU1 is up > > > > > > I hope this helps. > > > > Unfortunately it raised more questions than what it answered :( > > Before, it bailed out before talking to the regulator during s2ram, > After, it talks to the regulator before bailing out, triggering the WARN(). It wasn't working before and it isn't working now. Though I do see a problem with cpufreq core where it tries suspend/resume even though ->init() failed for all CPUs earlier. I will fix that separately. I think someone needs to see why it wasn't working earlier and then we can see if we have pending issues. -- viresh ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH V2 2/2] cpufreq: dt: Refactor initialization to handle probe deferral properly 2020-10-16 8:07 ` Viresh Kumar @ 2020-10-27 16:29 ` Geert Uytterhoeven 2020-10-28 5:48 ` Viresh Kumar 0 siblings, 1 reply; 10+ messages in thread From: Geert Uytterhoeven @ 2020-10-27 16:29 UTC (permalink / raw) To: Viresh Kumar Cc: Stephan Gerhold, Ulf Hansson, Rafael J. Wysocki, Liam Girdwood, Mark Brown, Linux PM list, Vincent Guittot, Stephen Boyd, Nishanth Menon, nks, Georgi Djakov, Linux Kernel Mailing List, Wolfram Sang, Linux I2C, Linux-Renesas Hi Viresh, On Fri, Oct 16, 2020 at 10:07 AM Viresh Kumar <viresh.kumar@linaro.org> wrote: > On 16-10-20, 08:44, Geert Uytterhoeven wrote: > > On Fri, Oct 16, 2020 at 7:03 AM Viresh Kumar <viresh.kumar@linaro.org> wrote: > > > On 14-10-20, 18:40, Geert Uytterhoeven wrote: > > > > On this platform (r8a7791-koelsch.dts), there is no opp table in DT. > > > > I think you missed the clue above: > > I read it earlier as well. > > > this DTS does not have an opp-table > > with operating-points-v2, but cpu0 does have the operating-points (v1) > > property (note the latter is something I missed before). > > This is different than having no OPP table in DT. > > > > > > > > > Before: > > > > > > I assume this means before this patchset came in.. > > > > Indeed. > > > > > > boot: > > > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:362 > > > > cpu cpu0: resources_available:95 > > > > cpu cpu0: resources_available:102: clk_get() returned z > > > > cpu cpu0: resources_available:120: > > > > dev_pm_opp_of_find_icc_paths() returned 0 > > > > cpu cpu0: resources_available:125: find_supply_name() returned cpu0 > > > > cpu cpu0: resources_available:132: regulator_get_optional() > > > > returned -EPROBE_DEFER > > > > cpu cpu0: cpu0 regulator not ready, retry > > > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:371: > > > > resources_available() returned -517 > > > > > > we deferred probe once. > > > > > > > ... > > > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:362 > > > > cpu cpu0: resources_available:95 > > > > cpu cpu0: resources_available:102: clk_get() returned z > > > > cpu cpu0: resources_available:120: > > > > dev_pm_opp_of_find_icc_paths() returned 0 > > > > cpu cpu0: resources_available:125: find_supply_name() returned cpu0 > > > > cpu cpu0: resources_available:132: regulator_get_optional() > > > > returned (ptrval) > > > > > > found regulator next time. > > > > > > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:371: > > > > resources_available() returned 0 > > > > cpufreq-dt cpufreq-dt: dt_cpufreq_probe:375 > > > > cpufreq_dt: cpufreq_init:162 > > > > cpu cpu0: cpufreq_init:170: clk_get() returned z > > > > cpu cpu0: cpufreq_init:179: dev_pm_opp_of_get_sharing_cpus() returned -2 > > > > cpu cpu0: cpufreq_init:198: find_supply_name() returned cpu0 > > > > <i2c comm> > > > > cpu cpu0: cpufreq_init:201: dev_pm_opp_set_regulators() returned (ptrval) > > > > <i2c comm> > > > > cpu cpu0: cpufreq_init:230: dev_pm_opp_of_cpumask_add_table() returned 0 > > > > cpu cpu0: cpufreq_init:239: dev_pm_opp_get_opp_count() returned 0 > > > > cpu cpu0: OPP table is not ready, deferring probe > > > > > > This failed, as we couldn't have deferred probe from cpufreq_init. > > > Which means that cpufreq didn't work here. > > > > No opp-table in DT. > > V1 is also an OPP table. OK. > > Shouldn't it use operating-points v1 instead? > > Both v1 and v2 are considered as OPP tables. When we say that the > opp-count is 0, it means that it failed to find any of them. Interestingly, first the v1 table is found, later opp-count is 0 (see below). > > > > cpufreq_dt: cpufreq_init:162 > > > > cpu cpu1: cpufreq_init:170: clk_get() returned z > > > > cpu cpu1: cpufreq_init:179: dev_pm_opp_of_get_sharing_cpus() returned -2 > > > > cpu cpu1: no regulator for cpu1 > > > > cpu cpu1: cpufreq_init:198: find_supply_name() returned (null) > > > > cpu cpu1: cpufreq_init:230: dev_pm_opp_of_cpumask_add_table() returned 0 > > > > cpu cpu1: cpufreq_init:239: dev_pm_opp_get_opp_count() returned 0 > > > > cpu cpu1: OPP table is not ready, deferring probe > > > > > > Same for CPU1. > > > > Note that only CPU0 has operating-points v1. > > Both should have it ideally, though it works if CPU0 gets probed > first. But if CPU0 is hotplugged out and we try to probe CPU1, then it > will fail. > > The fact that cpufreq core tried to probe CPU1 means that it failed > for CPU0. And this is before the patchset in question came in. > > I don't think cpufreq was working earlier for your platform, please > check why. [...] > I think someone needs to see why it wasn't working earlier and then we > can see if we have pending issues. On plain v5.9, with #define DEBUG and a few extra debug prints added, I get: cpufreq_dt: cpufreq_init:164: policy->cpu = 0 cpufreq_dt: cpufreq_init:165: policy->cpus = 0 cpufreq_dt: cpufreq_init:166: policy->related_cpus = cpufreq_dt: cpufreq_init:167: policy->real_cpus = cpu cpu0: dev_pm_opp_of_get_sharing_cpus: Couldn't find opp node. of: dev_pm_opp_of_cpumask_add_table:1049 of: dev_pm_opp_of_cpumask_add_table:1054: cpu 0 cpu cpu0: dev_pm_opp_of_add_table:954 cpu cpu0: dev_pm_opp_of_add_table:956: dev_pm_opp_get_opp_table_indexed() returned (ptrval) cpu cpu0: _of_add_opp_table_v1:891 cpu cpu0: _of_add_opp_table_v1:893: _find_opp_table() returned (ptrval) cpu cpu0: _of_add_opp_table_v1:909: 6 entries cpu cpu0: dev_pm_opp_get_opp_count:331 cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned (ptrval) cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 6 cpu cpu0: dev_pm_opp_get_opp_count:331 cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned (ptrval) cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 6 cpu cpu0: dev_pm_opp_get_opp_count:331 cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned (ptrval) cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 6 cpu cpu0: Couldn't find proper 'dynamic-power-coefficient' in DT cpu cpu0: Couldn't register Energy Model -22 This happens quite late in the boot sequence, long after cpu1 has been brought online. So it finds the v1 opp table for cpu0, which has 6 entries. The last two messages should be harmless, right? So you say cpufreq is not working? How can I verify that? Note that it never tries to do anything for cpu1. Note that during s2ram, nothing related is printed. On v5.10, with similar debug code, things are different. During boot: cpu cpu0: dev_pm_opp_of_get_sharing_cpus: Couldn't find opp node. cpufreq_dt: cpufreq_init:112: policy->cpu = 0 cpufreq_dt: cpufreq_init:113: policy->cpus = 0 cpufreq_dt: cpufreq_init:114: policy->related_cpus = cpufreq_dt: cpufreq_init:115: policy->real_cpus = of: dev_pm_opp_of_cpumask_add_table:1075 of: dev_pm_opp_of_cpumask_add_table:1080: cpu 0 cpu cpu0: dev_pm_opp_of_add_table:980 cpu cpu0: dev_pm_opp_of_add_table:982: dev_pm_opp_get_opp_table_indexed() returned (ptrval) cpu cpu0: _of_add_opp_table_v1:914 cpu cpu0: _of_add_opp_table_v1:916: _find_opp_table() returned (ptrval) cpu cpu0: _of_add_opp_table_v1:937: 6 entries Good, found the table with 6 entries. of: dev_pm_opp_of_cpumask_add_table:1080: cpu 1 cpu cpu1: dev_pm_opp_of_add_table:980 cpu cpu1: dev_pm_opp_of_add_table:982: dev_pm_opp_get_opp_table_indexed() returned (ptrval) cpu cpu1: _of_add_opp_table_v1:914 cpu cpu1: _of_add_opp_table_v1:916: _find_opp_table() returned (ptrval) cpu cpu1: _of_add_opp_table_v1:937: 6 entries Oh, this time it checked cpu1, too (why?), and found 6 entries, good. cpu cpu0: dev_pm_opp_get_opp_count:331 cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned (ptrval) cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 0 cpu cpu0: OPP table can't be empty Wait, _get_opp_count() returns 0? cpufreq_dt: cpufreq_init:112: policy->cpu = 1 cpufreq_dt: cpufreq_init:113: policy->cpus = 1 cpufreq_dt: cpufreq_init:114: policy->related_cpus = cpufreq_dt: cpufreq_init:115: policy->real_cpus = Oh, this time cpufreq_init() is called for cpu1, too. of: dev_pm_opp_of_cpumask_add_table:1075 of: dev_pm_opp_of_cpumask_add_table:1080: cpu 0 cpu cpu0: dev_pm_opp_of_add_table:980 cpu cpu0: dev_pm_opp_of_add_table:982: dev_pm_opp_get_opp_table_indexed() returned (ptrval) cpu cpu0: _of_add_opp_table_v1:914 cpu cpu0: _of_add_opp_table_v1:916: _find_opp_table() returned (ptrval) cpu cpu0: _of_add_opp_table_v1:937: 6 entries Checking cpu0 again (why?), 6 entries. of: dev_pm_opp_of_cpumask_add_table:1080: cpu 1 cpu cpu1: dev_pm_opp_of_add_table:980 cpu cpu1: dev_pm_opp_of_add_table:982: dev_pm_opp_get_opp_table_indexed() returned (ptrval) cpu cpu1: _of_add_opp_table_v1:914 cpu cpu1: _of_add_opp_table_v1:916: _find_opp_table() returned (ptrval) cpu cpu1: _of_add_opp_table_v1:937: 6 entries Checking cpu1 again, 6 entries. cpu cpu0: dev_pm_opp_get_opp_count:331 cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned (ptrval) cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 0 cpu cpu0: OPP table can't be empty Huh, cpu0 again, not cpu1? And _get_opp_count() returns 0? During s2ram, v5.10-rc1, it redoes most of the above, incl. touching the PMIC, which it shouldn't due in this phase of system resume: Disabling non-boot CPUs ... Enabling non-boot CPUs ... cpufreq_dt: cpufreq_init:112: policy->cpu = 1 cpufreq_dt: cpufreq_init:113: policy->cpus = 1 cpufreq_dt: cpufreq_init:114: policy->related_cpus = cpufreq_dt: cpufreq_init:115: policy->real_cpus = of: dev_pm_opp_of_cpumask_add_table:1075 of: dev_pm_opp_of_cpumask_add_table:1080: cpu 0 cpu cpu0: dev_pm_opp_of_add_table:980 cpu cpu0: dev_pm_opp_of_add_table:982: dev_pm_opp_get_opp_table_indexed() returned f680980b cpu cpu0: _of_add_opp_table_v1:914 cpu cpu0: _of_add_opp_table_v1:916: _find_opp_table() returned a4afd426 cpu cpu0: _of_add_opp_table_v1:937: 6 entries i2c-sh_mobile e60b0000.i2c: Transfer request timed out The i2c controller is suspended, this could go boom... i2c-sh_mobile e60b0000.i2c: Transfer request timed out i2c-sh_mobile e60b0000.i2c: Transfer request timed out i2c-sh_mobile e60b0000.i2c: Transfer request timed out i2c-sh_mobile e60b0000.i2c: Transfer request timed out i2c-sh_mobile e60b0000.i2c: Transfer request timed out of: dev_pm_opp_of_cpumask_add_table:1080: cpu 1 cpu cpu1: dev_pm_opp_of_add_table:980 cpu cpu1: dev_pm_opp_of_add_table:982: dev_pm_opp_get_opp_table_indexed() returned f680980b cpu cpu1: _of_add_opp_table_v1:914 cpu cpu1: _of_add_opp_table_v1:916: _find_opp_table() returned 9087c76d cpu cpu1: _of_add_opp_table_v1:937: 6 entries i2c-sh_mobile e60b0000.i2c: Transfer request timed out i2c-sh_mobile e60b0000.i2c: Transfer request timed out i2c-sh_mobile e60b0000.i2c: Transfer request timed out i2c-sh_mobile e60b0000.i2c: Transfer request timed out i2c-sh_mobile e60b0000.i2c: Transfer request timed out i2c-sh_mobile e60b0000.i2c: Transfer request timed out cpu cpu0: dev_pm_opp_get_opp_count:331 cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned f680980b cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 0 cpu cpu0: OPP table can't be empty CPU1 is up Thanks for your comments! 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH V2 2/2] cpufreq: dt: Refactor initialization to handle probe deferral properly 2020-10-27 16:29 ` Geert Uytterhoeven @ 2020-10-28 5:48 ` Viresh Kumar 2020-10-28 9:49 ` Geert Uytterhoeven 0 siblings, 1 reply; 10+ messages in thread From: Viresh Kumar @ 2020-10-28 5:48 UTC (permalink / raw) To: Geert Uytterhoeven Cc: Stephan Gerhold, Ulf Hansson, Rafael J. Wysocki, Liam Girdwood, Mark Brown, Linux PM list, Vincent Guittot, Stephen Boyd, Nishanth Menon, nks, Georgi Djakov, Linux Kernel Mailing List, Wolfram Sang, Linux I2C, Linux-Renesas On 27-10-20, 17:29, Geert Uytterhoeven wrote: > On plain v5.9, with #define DEBUG and a few extra debug prints > added, I get: > > cpufreq_dt: cpufreq_init:164: policy->cpu = 0 > cpufreq_dt: cpufreq_init:165: policy->cpus = 0 > cpufreq_dt: cpufreq_init:166: policy->related_cpus = > cpufreq_dt: cpufreq_init:167: policy->real_cpus = > cpu cpu0: dev_pm_opp_of_get_sharing_cpus: Couldn't find opp node. > of: dev_pm_opp_of_cpumask_add_table:1049 > of: dev_pm_opp_of_cpumask_add_table:1054: cpu 0 > cpu cpu0: dev_pm_opp_of_add_table:954 > cpu cpu0: dev_pm_opp_of_add_table:956: > dev_pm_opp_get_opp_table_indexed() returned (ptrval) > cpu cpu0: _of_add_opp_table_v1:891 > cpu cpu0: _of_add_opp_table_v1:893: _find_opp_table() returned (ptrval) > cpu cpu0: _of_add_opp_table_v1:909: 6 entries > cpu cpu0: dev_pm_opp_get_opp_count:331 > cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned (ptrval) > cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 6 > cpu cpu0: dev_pm_opp_get_opp_count:331 > cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned (ptrval) > cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 6 > cpu cpu0: dev_pm_opp_get_opp_count:331 > cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned (ptrval) > cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 6 > cpu cpu0: Couldn't find proper 'dynamic-power-coefficient' in DT > cpu cpu0: Couldn't register Energy Model -22 > > This happens quite late in the boot sequence, long after cpu1 has been > brought online. > So it finds the v1 opp table for cpu0, which has 6 entries. > The last two messages should be harmless, right? Yes. > So you say cpufreq is not working? How can I verify that? I said it because your earlier logs showed that we defered probed again or the count was 0 and we failed. Something like that. Give output of this to verify if cpufreq is working or not: grep . /sys/devices/system/cpu/cpufreq/policy*/* This will be empty if there is no cpufreq. > Note that it never tries to do anything for cpu1. Yes, because we set policy->cpus to both CPU0 and CPU1. > Note that during s2ram, nothing related is printed. > > On v5.10, with similar debug code, things are different. During boot: > > cpu cpu0: dev_pm_opp_of_get_sharing_cpus: Couldn't find opp node. > cpufreq_dt: cpufreq_init:112: policy->cpu = 0 > cpufreq_dt: cpufreq_init:113: policy->cpus = 0 > cpufreq_dt: cpufreq_init:114: policy->related_cpus = > cpufreq_dt: cpufreq_init:115: policy->real_cpus = > of: dev_pm_opp_of_cpumask_add_table:1075 > of: dev_pm_opp_of_cpumask_add_table:1080: cpu 0 > cpu cpu0: dev_pm_opp_of_add_table:980 > cpu cpu0: dev_pm_opp_of_add_table:982: > dev_pm_opp_get_opp_table_indexed() returned (ptrval) > cpu cpu0: _of_add_opp_table_v1:914 > cpu cpu0: _of_add_opp_table_v1:916: _find_opp_table() returned (ptrval) > cpu cpu0: _of_add_opp_table_v1:937: 6 entries > > Good, found the table with 6 entries. Good. > of: dev_pm_opp_of_cpumask_add_table:1080: cpu 1 > cpu cpu1: dev_pm_opp_of_add_table:980 > cpu cpu1: dev_pm_opp_of_add_table:982: > dev_pm_opp_get_opp_table_indexed() returned (ptrval) > cpu cpu1: _of_add_opp_table_v1:914 > cpu cpu1: _of_add_opp_table_v1:916: _find_opp_table() returned (ptrval) > cpu cpu1: _of_add_opp_table_v1:937: 6 entries > > Oh, this time it checked cpu1, too (why?), and found 6 entries, good. Yeah, because of some changes in cpufreq-dt.c, it shouldn't cause any issues though. > cpu cpu0: dev_pm_opp_get_opp_count:331 > cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned (ptrval) > cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 0 > cpu cpu0: OPP table can't be empty > > Wait, _get_opp_count() returns 0? Does this fix it for you as well ? https://lore.kernel.org/lkml/2c73ab54717ef358b118ea0cfb727b1427e7730a.1602648719.git.viresh.kumar@linaro.org/ I didn't point you to this earlier as your logs said something else. This is already there in linux-next now. > cpufreq_dt: cpufreq_init:112: policy->cpu = 1 > cpufreq_dt: cpufreq_init:113: policy->cpus = 1 > cpufreq_dt: cpufreq_init:114: policy->related_cpus = > cpufreq_dt: cpufreq_init:115: policy->real_cpus = > > Oh, this time cpufreq_init() is called for cpu1, too. Because we failed for CPU0. > During s2ram, v5.10-rc1, it redoes most of the above, incl. touching the > PMIC, which it shouldn't due in this phase of system resume: > > Disabling non-boot CPUs ... > Enabling non-boot CPUs ... > cpufreq_dt: cpufreq_init:112: policy->cpu = 1 > cpufreq_dt: cpufreq_init:113: policy->cpus = 1 > cpufreq_dt: cpufreq_init:114: policy->related_cpus = > cpufreq_dt: cpufreq_init:115: policy->real_cpus = > of: dev_pm_opp_of_cpumask_add_table:1075 > of: dev_pm_opp_of_cpumask_add_table:1080: cpu 0 > cpu cpu0: dev_pm_opp_of_add_table:980 > cpu cpu0: dev_pm_opp_of_add_table:982: > dev_pm_opp_get_opp_table_indexed() returned f680980b > cpu cpu0: _of_add_opp_table_v1:914 > cpu cpu0: _of_add_opp_table_v1:916: _find_opp_table() returned a4afd426 > cpu cpu0: _of_add_opp_table_v1:937: 6 entries > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > The i2c controller is suspended, this could go boom... > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > of: dev_pm_opp_of_cpumask_add_table:1080: cpu 1 > cpu cpu1: dev_pm_opp_of_add_table:980 > cpu cpu1: dev_pm_opp_of_add_table:982: > dev_pm_opp_get_opp_table_indexed() returned f680980b > cpu cpu1: _of_add_opp_table_v1:914 > cpu cpu1: _of_add_opp_table_v1:916: _find_opp_table() returned 9087c76d > cpu cpu1: _of_add_opp_table_v1:937: 6 entries > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > cpu cpu0: dev_pm_opp_get_opp_count:331 > cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned f680980b > cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 0 > cpu cpu0: OPP table can't be empty > CPU1 is up Lets make the normal boot work first and see about this later. Also for your next version of debug prints, use %px while printing addresses, that way the kernel doesn't hide them anymore and we can see which OPP table pointer is getting used at different places. That also means that you need to print the opp table's address at different places. -- viresh ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH V2 2/2] cpufreq: dt: Refactor initialization to handle probe deferral properly 2020-10-28 5:48 ` Viresh Kumar @ 2020-10-28 9:49 ` Geert Uytterhoeven 2020-10-28 9:52 ` Viresh Kumar 0 siblings, 1 reply; 10+ messages in thread From: Geert Uytterhoeven @ 2020-10-28 9:49 UTC (permalink / raw) To: Viresh Kumar Cc: Stephan Gerhold, Ulf Hansson, Rafael J. Wysocki, Liam Girdwood, Mark Brown, Linux PM list, Vincent Guittot, Stephen Boyd, Nishanth Menon, nks, Georgi Djakov, Linux Kernel Mailing List, Wolfram Sang, Linux I2C, Linux-Renesas Hi Viresh, On Wed, Oct 28, 2020 at 6:48 AM Viresh Kumar <viresh.kumar@linaro.org> wrote: > On 27-10-20, 17:29, Geert Uytterhoeven wrote: > > On plain v5.9, with #define DEBUG and a few extra debug prints > > added, I get: > > > > cpufreq_dt: cpufreq_init:164: policy->cpu = 0 > > cpufreq_dt: cpufreq_init:165: policy->cpus = 0 > > cpufreq_dt: cpufreq_init:166: policy->related_cpus = > > cpufreq_dt: cpufreq_init:167: policy->real_cpus = > > cpu cpu0: dev_pm_opp_of_get_sharing_cpus: Couldn't find opp node. > > of: dev_pm_opp_of_cpumask_add_table:1049 > > of: dev_pm_opp_of_cpumask_add_table:1054: cpu 0 > > cpu cpu0: dev_pm_opp_of_add_table:954 > > cpu cpu0: dev_pm_opp_of_add_table:956: > > dev_pm_opp_get_opp_table_indexed() returned (ptrval) > > cpu cpu0: _of_add_opp_table_v1:891 > > cpu cpu0: _of_add_opp_table_v1:893: _find_opp_table() returned (ptrval) > > cpu cpu0: _of_add_opp_table_v1:909: 6 entries > > cpu cpu0: dev_pm_opp_get_opp_count:331 > > cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned (ptrval) > > cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 6 > > cpu cpu0: dev_pm_opp_get_opp_count:331 > > cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned (ptrval) > > cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 6 > > cpu cpu0: dev_pm_opp_get_opp_count:331 > > cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned (ptrval) > > cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 6 > > cpu cpu0: Couldn't find proper 'dynamic-power-coefficient' in DT > > cpu cpu0: Couldn't register Energy Model -22 > > > > This happens quite late in the boot sequence, long after cpu1 has been > > brought online. > > So it finds the v1 opp table for cpu0, which has 6 entries. > > The last two messages should be harmless, right? > > Yes. > > > So you say cpufreq is not working? How can I verify that? > > I said it because your earlier logs showed that we defered probed > again or the count was 0 and we failed. Something like that. > > Give output of this to verify if cpufreq is working or not: > > grep . /sys/devices/system/cpu/cpufreq/policy*/* > > This will be empty if there is no cpufreq. /sys/devices/system/cpu/cpufreq/policy0/affected_cpus:0 1 /sys/devices/system/cpu/cpufreq/policy0/cpuinfo_cur_freq:375000 /sys/devices/system/cpu/cpufreq/policy0/cpuinfo_max_freq:1500000 /sys/devices/system/cpu/cpufreq/policy0/cpuinfo_min_freq:375000 /sys/devices/system/cpu/cpufreq/policy0/cpuinfo_transition_latency:300000 /sys/devices/system/cpu/cpufreq/policy0/related_cpus:0 1 /sys/devices/system/cpu/cpufreq/policy0/scaling_available_frequencies:375000 750000 937500 1125000 1312500 1500000 /sys/devices/system/cpu/cpufreq/policy0/scaling_available_governors:conservative ondemand userspace powersave performance schedutil /sys/devices/system/cpu/cpufreq/policy0/scaling_cur_freq:375000 /sys/devices/system/cpu/cpufreq/policy0/scaling_driver:cpufreq-dt /sys/devices/system/cpu/cpufreq/policy0/scaling_governor:schedutil /sys/devices/system/cpu/cpufreq/policy0/scaling_max_freq:1500000 /sys/devices/system/cpu/cpufreq/policy0/scaling_min_freq:375000 /sys/devices/system/cpu/cpufreq/policy0/scaling_setspeed:<unsupported> So it works in v5.9, but not in v5.10-rc1. Bisection says it was broken by commit 90d46d71cce279d8 ("opp: Handle multiple calls for same OPP table in _of_add_opp_table_v1()"). > > cpu cpu0: dev_pm_opp_get_opp_count:331 > > cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned (ptrval) > > cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 0 > > cpu cpu0: OPP table can't be empty > > > > Wait, _get_opp_count() returns 0? > > Does this fix it for you as well ? > > https://lore.kernel.org/lkml/2c73ab54717ef358b118ea0cfb727b1427e7730a.1602648719.git.viresh.kumar@linaro.org/ Thanks, it does. I had arrived at the same conclusion after bisection. > I didn't point you to this earlier as your logs said something else. All my logs said _get_opp_count() returns 0. > > During s2ram, v5.10-rc1, it redoes most of the above, incl. touching the > > PMIC, which it shouldn't due in this phase of system resume: > > > > Disabling non-boot CPUs ... > > Enabling non-boot CPUs ... > > cpufreq_dt: cpufreq_init:112: policy->cpu = 1 > > cpufreq_dt: cpufreq_init:113: policy->cpus = 1 > > cpufreq_dt: cpufreq_init:114: policy->related_cpus = > > cpufreq_dt: cpufreq_init:115: policy->real_cpus = > > of: dev_pm_opp_of_cpumask_add_table:1075 > > of: dev_pm_opp_of_cpumask_add_table:1080: cpu 0 > > cpu cpu0: dev_pm_opp_of_add_table:980 > > cpu cpu0: dev_pm_opp_of_add_table:982: > > dev_pm_opp_get_opp_table_indexed() returned f680980b > > cpu cpu0: _of_add_opp_table_v1:914 > > cpu cpu0: _of_add_opp_table_v1:916: _find_opp_table() returned a4afd426 > > cpu cpu0: _of_add_opp_table_v1:937: 6 entries > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > > > The i2c controller is suspended, this could go boom... > > > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > of: dev_pm_opp_of_cpumask_add_table:1080: cpu 1 > > cpu cpu1: dev_pm_opp_of_add_table:980 > > cpu cpu1: dev_pm_opp_of_add_table:982: > > dev_pm_opp_get_opp_table_indexed() returned f680980b > > cpu cpu1: _of_add_opp_table_v1:914 > > cpu cpu1: _of_add_opp_table_v1:916: _find_opp_table() returned 9087c76d > > cpu cpu1: _of_add_opp_table_v1:937: 6 entries > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > cpu cpu0: dev_pm_opp_get_opp_count:331 > > cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned f680980b > > cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 0 > > cpu cpu0: OPP table can't be empty > > CPU1 is up > > Lets make the normal boot work first and see about this later. This is also fixed by your patch: the PMIC is no longer accessed while suspended. 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH V2 2/2] cpufreq: dt: Refactor initialization to handle probe deferral properly 2020-10-28 9:49 ` Geert Uytterhoeven @ 2020-10-28 9:52 ` Viresh Kumar 0 siblings, 0 replies; 10+ messages in thread From: Viresh Kumar @ 2020-10-28 9:52 UTC (permalink / raw) To: Geert Uytterhoeven Cc: Stephan Gerhold, Ulf Hansson, Rafael J. Wysocki, Liam Girdwood, Mark Brown, Linux PM list, Vincent Guittot, Stephen Boyd, Nishanth Menon, nks, Georgi Djakov, Linux Kernel Mailing List, Wolfram Sang, Linux I2C, Linux-Renesas On 28-10-20, 10:49, Geert Uytterhoeven wrote: > Hi Viresh, > > On Wed, Oct 28, 2020 at 6:48 AM Viresh Kumar <viresh.kumar@linaro.org> wrote: > > On 27-10-20, 17:29, Geert Uytterhoeven wrote: > > > On plain v5.9, with #define DEBUG and a few extra debug prints > > > added, I get: > > > > > > cpufreq_dt: cpufreq_init:164: policy->cpu = 0 > > > cpufreq_dt: cpufreq_init:165: policy->cpus = 0 > > > cpufreq_dt: cpufreq_init:166: policy->related_cpus = > > > cpufreq_dt: cpufreq_init:167: policy->real_cpus = > > > cpu cpu0: dev_pm_opp_of_get_sharing_cpus: Couldn't find opp node. > > > of: dev_pm_opp_of_cpumask_add_table:1049 > > > of: dev_pm_opp_of_cpumask_add_table:1054: cpu 0 > > > cpu cpu0: dev_pm_opp_of_add_table:954 > > > cpu cpu0: dev_pm_opp_of_add_table:956: > > > dev_pm_opp_get_opp_table_indexed() returned (ptrval) > > > cpu cpu0: _of_add_opp_table_v1:891 > > > cpu cpu0: _of_add_opp_table_v1:893: _find_opp_table() returned (ptrval) > > > cpu cpu0: _of_add_opp_table_v1:909: 6 entries > > > cpu cpu0: dev_pm_opp_get_opp_count:331 > > > cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned (ptrval) > > > cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 6 > > > cpu cpu0: dev_pm_opp_get_opp_count:331 > > > cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned (ptrval) > > > cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 6 > > > cpu cpu0: dev_pm_opp_get_opp_count:331 > > > cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned (ptrval) > > > cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 6 > > > cpu cpu0: Couldn't find proper 'dynamic-power-coefficient' in DT > > > cpu cpu0: Couldn't register Energy Model -22 > > > > > > This happens quite late in the boot sequence, long after cpu1 has been > > > brought online. > > > So it finds the v1 opp table for cpu0, which has 6 entries. > > > The last two messages should be harmless, right? > > > > Yes. > > > > > So you say cpufreq is not working? How can I verify that? > > > > I said it because your earlier logs showed that we defered probed > > again or the count was 0 and we failed. Something like that. > > > > Give output of this to verify if cpufreq is working or not: > > > > grep . /sys/devices/system/cpu/cpufreq/policy*/* > > > > This will be empty if there is no cpufreq. > > /sys/devices/system/cpu/cpufreq/policy0/affected_cpus:0 1 > /sys/devices/system/cpu/cpufreq/policy0/cpuinfo_cur_freq:375000 > /sys/devices/system/cpu/cpufreq/policy0/cpuinfo_max_freq:1500000 > /sys/devices/system/cpu/cpufreq/policy0/cpuinfo_min_freq:375000 > /sys/devices/system/cpu/cpufreq/policy0/cpuinfo_transition_latency:300000 > /sys/devices/system/cpu/cpufreq/policy0/related_cpus:0 1 > /sys/devices/system/cpu/cpufreq/policy0/scaling_available_frequencies:375000 > 750000 937500 1125000 1312500 1500000 > /sys/devices/system/cpu/cpufreq/policy0/scaling_available_governors:conservative > ondemand userspace powersave performance schedutil > /sys/devices/system/cpu/cpufreq/policy0/scaling_cur_freq:375000 > /sys/devices/system/cpu/cpufreq/policy0/scaling_driver:cpufreq-dt > /sys/devices/system/cpu/cpufreq/policy0/scaling_governor:schedutil > /sys/devices/system/cpu/cpufreq/policy0/scaling_max_freq:1500000 > /sys/devices/system/cpu/cpufreq/policy0/scaling_min_freq:375000 > /sys/devices/system/cpu/cpufreq/policy0/scaling_setspeed:<unsupported> > > So it works in v5.9, but not in v5.10-rc1. > > Bisection says it was broken by commit 90d46d71cce279d8 ("opp: Handle > multiple calls for same OPP table in _of_add_opp_table_v1()"). > > > > cpu cpu0: dev_pm_opp_get_opp_count:331 > > > cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned (ptrval) > > > cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 0 > > > cpu cpu0: OPP table can't be empty > > > > > > Wait, _get_opp_count() returns 0? > > > > Does this fix it for you as well ? > > > > https://lore.kernel.org/lkml/2c73ab54717ef358b118ea0cfb727b1427e7730a.1602648719.git.viresh.kumar@linaro.org/ > > Thanks, it does. I had arrived at the same conclusion after bisection. > > > I didn't point you to this earlier as your logs said something else. > > All my logs said _get_opp_count() returns 0. > > > > During s2ram, v5.10-rc1, it redoes most of the above, incl. touching the > > > PMIC, which it shouldn't due in this phase of system resume: > > > > > > Disabling non-boot CPUs ... > > > Enabling non-boot CPUs ... > > > cpufreq_dt: cpufreq_init:112: policy->cpu = 1 > > > cpufreq_dt: cpufreq_init:113: policy->cpus = 1 > > > cpufreq_dt: cpufreq_init:114: policy->related_cpus = > > > cpufreq_dt: cpufreq_init:115: policy->real_cpus = > > > of: dev_pm_opp_of_cpumask_add_table:1075 > > > of: dev_pm_opp_of_cpumask_add_table:1080: cpu 0 > > > cpu cpu0: dev_pm_opp_of_add_table:980 > > > cpu cpu0: dev_pm_opp_of_add_table:982: > > > dev_pm_opp_get_opp_table_indexed() returned f680980b > > > cpu cpu0: _of_add_opp_table_v1:914 > > > cpu cpu0: _of_add_opp_table_v1:916: _find_opp_table() returned a4afd426 > > > cpu cpu0: _of_add_opp_table_v1:937: 6 entries > > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > > > > > The i2c controller is suspended, this could go boom... > > > > > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > > of: dev_pm_opp_of_cpumask_add_table:1080: cpu 1 > > > cpu cpu1: dev_pm_opp_of_add_table:980 > > > cpu cpu1: dev_pm_opp_of_add_table:982: > > > dev_pm_opp_get_opp_table_indexed() returned f680980b > > > cpu cpu1: _of_add_opp_table_v1:914 > > > cpu cpu1: _of_add_opp_table_v1:916: _find_opp_table() returned 9087c76d > > > cpu cpu1: _of_add_opp_table_v1:937: 6 entries > > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > > i2c-sh_mobile e60b0000.i2c: Transfer request timed out > > > cpu cpu0: dev_pm_opp_get_opp_count:331 > > > cpu cpu0: dev_pm_opp_get_opp_count:333: _find_opp_table() returned f680980b > > > cpu cpu0: dev_pm_opp_get_opp_count:342: _get_opp_count() returned 0 > > > cpu cpu0: OPP table can't be empty > > > CPU1 is up > > > > Lets make the normal boot work first and see about this later. > > This is also fixed by your patch: the PMIC is no longer accessed while > suspended. Ah finally. Thanks, everything worked as expected :) -- viresh ^ permalink raw reply [flat|nested] 10+ messages in thread
end of thread, other threads:[~2020-10-28 23:42 UTC | newest]
Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
[not found] <24ff92dd1b0ee1b802b45698520f2937418f8094.1598260050.git.viresh.kumar@linaro.org>
[not found] ` <f75c61f193f396608d592ae2a9938264d582c038.1598260050.git.viresh.kumar@linaro.org>
2020-10-13 9:47 ` [PATCH V2 2/2] cpufreq: dt: Refactor initialization to handle probe deferral properly Geert Uytterhoeven
2020-10-13 9:56 ` Viresh Kumar
2020-10-14 16:40 ` Geert Uytterhoeven
2020-10-16 5:03 ` Viresh Kumar
2020-10-16 6:44 ` Geert Uytterhoeven
2020-10-16 8:07 ` Viresh Kumar
2020-10-27 16:29 ` Geert Uytterhoeven
2020-10-28 5:48 ` Viresh Kumar
2020-10-28 9:49 ` Geert Uytterhoeven
2020-10-28 9:52 ` Viresh Kumar
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).