Message-ID: <f0fd057e-95cb-4a85-00fc-9eb25ef7b9b3@os.amperecomputing.com>
Date:   Thu, 20 Apr 2023 13:49:24 -0700
From:   Yang Shi <yang@...amperecomputing.com>
To:     Pierre Gondois <pierre.gondois@....com>,
        Ionela Voinescu <Ionela.Voinescu@....com>
Cc:     viresh.kumar@...aro.org, scott@...amperecomputing.com,
        linux-pm@...r.kernel.org, linux-kernel@...r.kernel.org,
        "Rafael J. Wysocki" <rafael@...nel.org>
Subject: Re: [PATCH] cpufreq: CPPC: use 10ms delay instead of 2us to avoid
 high error



On 4/20/23 9:01 AM, Pierre Gondois wrote:
>
>>>
>>> You say that the cause of this is a congestion in the interconnect. I
>>> don't
>>> see a way to check that right now.
>>> However your trace is on the CPU0, so maybe all the other cores were
>>> shutdown
>>> in your test. If this is the case, do you think a congestion could
>>> happen with
>>> only one CPU ?
>>
>> No, other CPUs were not shut down in my test. I just ran "yes" on all
>> cores except CPU 0, then ran the reading freq script. Since all other
>> cores are busy, so the script should be always running on CPU 0.
>>
>> Since the counters, memory and other devices are on the interconnect, so
>> the congestion may be caused by plenty of factors IIUC.
>
> +Ionela
>
> Ionela pointed me to the following patch-set, which seems realated:
> https://lore.kernel.org/all/20230418113459.12860-5-sumitg@nvidia.com/

Thanks for the information. I think we do have the similar syndrome. But 
I'm not sure how their counters are implemented, we may not have similar 
root cause.

>
> One thing that we didn't check I believe is and that Ionela pointed out
> is that we don't know whether we are accessing the present CPU or a 
> remote
> CPU'AMUs. In the latter case there would be IPIs and possible delays in
> waking up/accessing the remote CPU).
>
>>
>>>
>>> Just 2 other comments:
>>> a-
>>> It might be interesting to change the order in which cpc registers are
>>> read
>>> just to see if it has an impact, but even if it has, I m not sure how
>>> this
>>> could be exploitable.
>>> Just in case, I mean doing that, but I think that b. might be better
>>> to try.
>>>
>>> diff --git a/drivers/acpi/cppc_acpi.c b/drivers/acpi/cppc_acpi.c
>>> index c51d3ccb4cca..479b55006020 100644
>>> --- a/drivers/acpi/cppc_acpi.c
>>> +++ b/drivers/acpi/cppc_acpi.c
>>> @@ -1350,8 +1350,8 @@ int cppc_get_perf_ctrs(int cpunum, struct
>>> cppc_perf_fb_ctrs *perf_fb_ctrs)
>>>                  }
>>>          }
>>>
>>> -       cpc_read(cpunum, delivered_reg, &delivered);
>>>          cpc_read(cpunum, reference_reg, &reference);
>>> +       cpc_read(cpunum, delivered_reg, &delivered);
>>>          cpc_read(cpunum, ref_perf_reg, &ref_perf);
>>>
>>>          /*
>>>
>>> b-
>>> In the trace that you shared, the cpc_read() calls in the fist
>>> cppc_get_perf_ctrs() calls seem to always take a bit more time than in
>>> the
>>> second cppc_get_perf_ctrs() call.
>>> Would it be possible to collect traces similar as above with 3 or 4
>>> calls to
>>> cppc_get_perf_ctrs() instead of 2 ? It would allow to check whether in
>>> the first
>>> call, accessing the cpc registers takes more time than in the
>>> following calls,
>>> due to cache misses or other reasons.
>>
>> Cache miss? The counters should be not cached and reading the counters
>> should not hit cache IIUC.
>
> Yes you are correct, what I said is copmletely wrong.
>
>>
>>> Ideally statistics on the result would be the best, or if you have a
>>> trace.dat
>>> to share containing a trace with multiple cppc_cpufreq_get_rate() 
>>> calls.
>>
>> Tried option b, I managed to get histogram:
>>
>> @hist_first_ns[cat]:
>> [4K, 8K)          112321
>> |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
>> [8K, 16K)            212
>> |                                                    |
>> [16K, 32K)            25
>> |                                                    |
>> [32K, 64K)            59
>> |                                                    |
>> [64K, 128K)            6
>> |                                                    |
>> [128K, 256K)           9
>> |                                                    |
>>
>> @hist_second_ns[cat]:
>> [2K, 4K)          112590
>> |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
>> [4K, 8K)               4
>> |                                                    |
>> [8K, 16K)              0
>> |                                                    |
>> [16K, 32K)            15
>> |                                                    |
>> [32K, 64K)            18
>> |                                                    |
>> [64K, 128K)            1
>> |                                                    |
>> [128K, 256K)           4
>> |                                                    |
>>
>> The "first" means the first cppc_get_perf_ctrs() call. But the bpftrace
>> script can't tell the second, the third and the fourth, so all them are
>> shown as "second". Anyway it seems fine. We can tell the first read took
>> longer than the later ones for the most time.
>>
>> And a typical func_graph trace shows:
>>
>> # tracer: function_graph
>> #
>> #     TIME        CPU  DURATION                  FUNCTION CALLS
>> #      |          |     |   |                     |   |   | |
>>    4447.171333 |     0)               |  cppc_cpufreq_get_rate
>> [cppc_cpufreq]() {
>>    4447.171334 |     0)               |    cpufreq_cpu_get() {
>>    4447.171334 |     0)   1.060 us    | _raw_read_lock_irqsave();
>>    4447.171336 |     0)   0.560 us    | _raw_read_unlock_irqrestore();
>>    4447.171337 |     0)   3.480 us    | }
>>    4447.171338 |     0)   0.400 us    | cpufreq_cpu_put();
>>    4447.171338 |     0)               |    cppc_get_perf_ctrs() {
>>    4447.171339 |     0)   0.720 us    | cpc_read.isra.0();
>>    4447.171341 |     0)   0.700 us    | cpc_read.isra.0();
>>    4447.171342 |     0)   0.380 us    | cpc_read.isra.0();
>>    4447.171342 |     0)   0.600 us    | cpc_read.isra.0();
>>    4447.171343 |     0)   4.900 us    | }
>>    4447.171344 |     0)               |    __delay() {
>>    4447.171344 |     0)   0.540 us    | arch_timer_evtstrm_available();
>>    4447.171346 |     0)   2.420 us    | }
>>    4447.171347 |     0)               |    cppc_get_perf_ctrs() {
>>    4447.171347 |     0)   0.540 us    | cpc_read.isra.0();
>>    4447.171348 |     0)   0.520 us    | cpc_read.isra.0();
>>    4447.171349 |     0)   0.400 us    | cpc_read.isra.0();
>>    4447.171350 |     0)   0.440 us    | cpc_read.isra.0();
>>    4447.171350 |     0)   3.660 us    | }
>>    4447.171351 |     0)               |    __delay() {
>>    4447.171351 |     0)   0.400 us    | arch_timer_evtstrm_available();
>>    4447.171353 |     0)   2.400 us    | }
>>    4447.171353 |     0)               |    cppc_get_perf_ctrs() {
>>    4447.171354 |     0)   0.540 us    | cpc_read.isra.0();
>>    4447.171355 |     0)   0.540 us    | cpc_read.isra.0();
>>    4447.171356 |     0)   0.380 us    | cpc_read.isra.0();
>>    4447.171356 |     0)   0.420 us    | cpc_read.isra.0();
>>    4447.171357 |     0)   3.640 us    | }
>>    4447.171357 |     0)               |    __delay() {
>>    4447.171358 |     0)   0.380 us    | arch_timer_evtstrm_available();
>>    4447.171360 |     0)   2.380 us    |    }
>>    4447.171360 |     0)               |    cppc_get_perf_ctrs() {
>>    4447.171361 |     0)   0.520 us    |      cpc_read.isra.0();
>>    4447.171361 |     0)   0.520 us    |      cpc_read.isra.0();
>>    4447.171362 |     0)   0.400 us    |      cpc_read.isra.0();
>>    4447.171363 |     0)   0.440 us    |      cpc_read.isra.0();
>>    4447.171364 |     0)   3.640 us    |    }
>>    4447.171364 |     0)   0.520 us    | cppc_cpufreq_perf_to_khz
>> [cppc_cpufreq]();
>>    4447.171365 |     0) + 34.240 us   |  }
>>
>> It also shows the first reading typically took longer than the later
>> ones. The second, the third and the fourth actually took almost same 
>> time.
>>
>> I also tried to read perf_fb_ctrs_t0 twice (so total 3 reads, 2 for t0,
>> 1 for t1, 2us delay between each read), but I didn't see noticeable
>> improvement. 4 reads (2 for t0, 2 for t1) does show some noticeable
>> improvement.
>>
>
> Thanks for the new data.
>
>>>
>>> Example of code where we do 4 calls to cppc_get_perf_ctrs():
>>>
>>> diff --git a/drivers/cpufreq/cppc_cpufreq.c
>>> b/drivers/cpufreq/cppc_cpufreq.c
>>> index 022e3555407c..6370f2f0bdad 100644
>>> --- a/drivers/cpufreq/cppc_cpufreq.c
>>> +++ b/drivers/cpufreq/cppc_cpufreq.c
>>> @@ -853,6 +853,20 @@ static unsigned int
>>> cppc_cpufreq_get_rate(unsigned int cpu)
>>>
>>>          udelay(2); /* 2usec delay between sampling */
>>>
>>> +       ret = cppc_get_perf_ctrs(cpu, &fb_ctrs_t1);
>>> +       if (ret)
>>> +               return ret;
>>> +
>>> +       udelay(2); /* 2usec delay between sampling */
>>> +
>>> +       /* Do a third call. */
>>> +       ret = cppc_get_perf_ctrs(cpu, &fb_ctrs_t1);
>>> +       if (ret)
>>> +               return ret;
>>> +
>>> +       udelay(2); /* 2usec delay between sampling */
>>> +
>>> +       /* Do a fourth call. */
>>>          ret = cppc_get_perf_ctrs(cpu, &fb_ctrs_t1);
>>>          if (ret)
>>>                  return ret;
>>>
>>>>
>>>> The above trace data shows some cpc reading took a little bit longer
>>>> than usual. I suspected it was caused by interconnect congestion.
>>>>
>>>>
>>>> So it looks like IRQ is the major contributing factor of high error
>>>> (4xxxxxx KHz), interconnect congestion is the major contributing 
>>>> factor
>>>> of low error (3xxxxxx KHz).
>>>>
>>>> So I did the below test:
>>>> 1. Disable IRQ: The high errors were gone (> 3700000KHz), but low 
>>>> errors
>>>> were still seen.
>>>> 2.10us delay: The high errors were still seen.
>>>> 3. Disable IRQ + 10us delay: all the errors were gone.
>>>>
>>>> I think the test result also supports the tracing data.
>>>>
>>>>
>>>> I also got some confusion about calling cppc_cpufreq_get_rate() 
>>>> with irq
>>>> disabled. Rafael thought 10ms delay is too long because the 
>>>> function may
>>>> be called with irq disabled. But a deeper look at the function 
>>>> shows it
>>>> should *NOT* be called with irq disabled at all.
>>>>
>>>> First, if pcc channel is used, cpc reading may take over 100ms, it is
>>>> way larger the proposed 10ms delay.
>>>> Second, reading from cpc channel needs to take a semaphore, so it may
>>>> sleep. But sleep with IRQ disabled is not allowed.
>>>
>>> Yes right, however the semaphore is not taken in between the 
>>> sequence of
>>> cpc_read() calls in cppc_get_perf_ctrs(). So maybe the change below
>>> should
>>> be acceptable:
>>
>> Yeah, we should be able to find a smaller irq disable section.
>>
>>>
>>> diff --git a/drivers/acpi/cppc_acpi.c b/drivers/acpi/cppc_acpi.c
>>> index c51d3ccb4cca..105a7e2ffffa 100644
>>> --- a/drivers/acpi/cppc_acpi.c
>>> +++ b/drivers/acpi/cppc_acpi.c
>>> @@ -1315,6 +1315,7 @@ int cppc_get_perf_ctrs(int cpunum, struct
>>> cppc_perf_fb_ctrs *perf_fb_ctrs)
>>>          struct cppc_pcc_data *pcc_ss_data = NULL;
>>>          u64 delivered, reference, ref_perf, ctr_wrap_time;
>>>          int ret = 0, regs_in_pcc = 0;
>>> +       unsigned long flags;
>>>
>>>          if (!cpc_desc) {
>>>                  pr_debug("No CPC descriptor for CPU:%d\n", cpunum);
>>> @@ -1350,10 +1351,14 @@ int cppc_get_perf_ctrs(int cpunum, struct
>>> cppc_perf_fb_ctrs *perf_fb_ctrs)
>>>                  }
>>>          }
>>>
>>> +       local_irq_save(flags);
>>> +
>>>          cpc_read(cpunum, delivered_reg, &delivered);
>>>          cpc_read(cpunum, reference_reg, &reference);
>>>          cpc_read(cpunum, ref_perf_reg, &ref_perf);
>>>
>>> +       local_irq_restore(flags);
>>> +
>>
>> cpc_read_ffh() would return -EPERM if irq is disabled.
>>
>> So, the irq disabling must happen for mmio only in cpc_read(), for 
>> example:
>
> I thought the issue was that irqs could happen in between cpc_read() 
> functions,
> the patch below would not cover it. If the frequency is more accurate
> with this patch, I think I don't understand something.

Yeah, you are correct. The irq disabling window has to cover all the 
cpc_read(). I didn't test with this patch. My test was done conceptually 
with:

disable irq
cppc_get_perf_ctrs(t0)
udelay(2)
cppc_get_perf_ctrs(t1)
enable irq

But this will break cpc_read_ffh().

>
> (asking for more information)
> Just to check, the core/perf counters are AMUs and the other CPPC 
> registers
> are mmio right ? Is it possible to know the CPPC registers that are
> implemented on your platform ?

AFAIK, the perf counters are implemented by AMU and accessed via mmio, 
the other CPPC registers are implemented by PCC.

> Also is it possible which platform you are using ?

Ampere One

>
>>
>> diff --git a/drivers/acpi/cppc_acpi.c b/drivers/acpi/cppc_acpi.c
>> index c51d3ccb4cca..f3c92d844074 100644
>> --- a/drivers/acpi/cppc_acpi.c
>> +++ b/drivers/acpi/cppc_acpi.c
>> @@ -982,6 +982,7 @@ static int cpc_read(int cpu, struct
>> cpc_register_resource *reg_res, u64 *val)
>>           void __iomem *vaddr = NULL;
>>           int pcc_ss_id = per_cpu(cpu_pcc_subspace_idx, cpu);
>>           struct cpc_reg *reg = &reg_res->cpc_entry.reg;
>> +       unsigned long flags;
>>
>>           if (reg_res->type == ACPI_TYPE_INTEGER) {
>>                   *val = reg_res->cpc_entry.int_value;
>> @@ -1015,6 +1016,7 @@ static int cpc_read(int cpu, struct
>> cpc_register_resource *reg_res, u64 *val)
>>                   return
>> acpi_os_read_memory((acpi_physical_address)reg->address,
>>                                   val, reg->bit_width);
>>
>> +       local_irq_save(flags);
>>           switch (reg->bit_width) {
>>           case 8:
>>                   *val = readb_relaxed(vaddr);
>> @@ -1029,10 +1031,12 @@ static int cpc_read(int cpu, struct
>> cpc_register_resource *reg_res, u64 *val)
>>                   *val = readq_relaxed(vaddr);
>>                   break;
>>           default:
>> +               local_irq_restore(flags);
>>                   pr_debug("Error: Cannot read %u bit width from PCC for
>> ss: %d\n",
>>                            reg->bit_width, pcc_ss_id);
>>                   return -EFAULT;
>>           }
>> +       local_irq_restore(flags);
>>
>>           return 0;
>>    }
>>
>>>          /*
>>>           * Per spec, if ctr_wrap_time optional register is
>>> unsupported, then the
>>>           * performance counters are assumed to never wrap during the
>>> lifetime of
>>>
>>>> Third, if the counters are implemented by AMU, cpc_read_ffh() needs to
>>>> send IPI so it requires IRQ enabled.
>>>
>>> If I'm not mistaken, the CPU calling cpc_read_ffh() might have IRQs
>>> disabled,
>>> it should not prevent it to send IPIs no ?
>>
>> It can't work with irq disabled. The comment in counters_read_on_cpu()
>> says "Abort call on counterless CPU or when interrupts are disabled -
>> can lead to deadlock in smp sync call."
>>
>>
>> And it just returns -EPERM and raise a warning if irq is disabled.
>
> Ok right,
>
> Regards,
> Piere

Powered by blists - more mailing lists