Re: [PATCH V2 2/2] cpufreq: dt: Refactor initialization to handle probe deferral properly

[Viresh Kumar]

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@xxxxxxxxxx/

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