Re: [aarch64] INFO: rcu_sched detected expedited stalls on CPUs/tasks

[Pierre Gondois]

Hello Bruno,
This looks like something we noticed on the PCC channel of the Tx2. Here was
the original message:
'''
It seems there is synchronization issue on the PCC channels of the ThunderX2.

Some abbreviations first. References are always to ACPI 6.4:
Command Complete bit (CCb):
1 means the OS owns the PCC channel, 0 means the firmware owns the channel,
cf s14.2.2 "Generic Communications Channel Status Field"

Doorbell Write bits (DWb):
Write a mask (just one bit in our case) to the doorbell register to notify the
firmware of a message waiting in the channel,
cf s14.1.4 "HW-Reduced Communications Subspace Structure (type 1)"

Minimum Request Turnaround Time (MRTT):
PCC channels have a 'Minimum Request Turnaround Time', being 'The minimum
amount of time that OSPM must wait after the completion of a command before
issuing the next command'.
cf s14.1.4 "HW-Reduced Communications Subspace Structure (type 1)"

The scenario that seems to cause trouble is:
1. The OS places a payload and clears the CCb bit
2. The OS rings at the doorbell (sets the DWb)
3. The firmware processes the message and then sets the CCb (the DWb seems to
   be still set)
4. The OS continues (the DWb seems to be still set)
5. The OS wants to send another command. The MRTT has elapsed. So the OS does
    1. again. (the DWb seems to be still set)
6. The OS does 2. again, but the DWb are still set so the OS overwrites the DWb
7. The firmware finally clears the DWb.

 From 7.:
- The OS indefinitely waits for an answer, thinking the firmware needs
  to answer. The timeout of this request elapses, but the channel is still
  assumed to belong to the firmware, so the OS never rings the doorbell again.
- The firmware waits for the doorbell to ring (the DWb to be set), but the
  OS never rings again.

This can be reproduced by running a big load (e.g. 60 tasks running at 5%
of the maximum CPU capacity). PCCT tables must have been published by
selecting the right option in UEFI.

Doubling the MRTT (going from 5ms to 10ms) makes the synchronization issue
disappears, but it means decreasing the speed of all PCC channels.
'''

If you get messages such as:
"PCC check channel failed for ss: XX. ret=X"
then this should be the same issue.

What might be happening for you is that a stall is detected while the
sugov_work thread is trying to set a frequency. check_pcc_chan() waits for
500 * 3000 us (the PCC channel nominal latency for the Tx2) = 1.5s, which
is quite long.

Cf. the end of the original message, could you try increasing the mrtt value ?
(here it is doubled)
pcc_data[pcc_ss_idx]->pcc_mrtt = 2 * pcc_chan->min_turnaround_time;
https://github.com/torvalds/linux/blob/50fd82b3a9a9335df5d50c7ddcb81c81d358c4fc/drivers/acpi/cppc_acpi.c#L547
(for info, where the cppc dirvers waits for the mrtt to elapse)
https://github.com/torvalds/linux/blob/50fd82b3a9a9335df5d50c7ddcb81c81d358c4fc/drivers/acpi/cppc_acpi.c#L263

On 6/3/22 11:44, Bruno Goncalves wrote:
> Hello,
>
> We recently started to hit this problem on some of our aarch64
> machines. The stalls can happen even during boot.
>
> [ 1086.949484] rcu: INFO: rcu_sched detected expedited stalls on
> CPUs/tasks: { 23-... } 3 jiffies s: 3441 root: 0x2/.
> [ 1086.949510] rcu: blocking rcu_node structures (internal RCU debug):
> l=1:16-31:0x80/.
> [ 1086.949524] Task dump for CPU 23:
> [ 1086.949528] task:sugov:23        state:R  running task     stack:
>   0 pid: 2914 ppid:     2 flags:0x0000000a
> [ 1086.949543] Call trace:
> [ 1086.949546]  __switch_to+0x104/0x19c
> [ 1086.949568]  __schedule+0x410/0x67c
> [ 1086.949576]  schedule+0x70/0xa8
> [ 1086.949583]  schedule_hrtimeout_range_clock+0x144/0x1d8
> [ 1086.949592]  schedule_hrtimeout_range+0x20/0x2c
> [ 1086.949598]  usleep_range_state+0x5c/0x80
> [ 1086.949603]  check_pcc_chan+0x7c/0xf4
> [ 1086.949615]  send_pcc_cmd+0x130/0x2a8
> [ 1086.949619]  cppc_set_perf+0x12c/0x22c
> [ 1086.949624]  cppc_cpufreq_set_target+0xf8/0x15c [cppc_cpufreq]
> [ 1086.949645]  __cpufreq_driver_target+0x94/0xfc
> [ 1086.949658]  sugov_work+0x98/0xe0
> [ 1086.949675]  kthread_worker_fn+0x124/0x2b8
> [ 1086.949683]  kthread+0xd4/0x558
> [ 1086.949689]  ret_from_fork+0x10/0x20
>
> More logs:
> https://s3.us-east-1.amazonaws.com/arr-cki-prod-datawarehouse-public/datawarehouse-public/2022/06/02/553734635/redhat:553734635_aarch64/tests/Storage_block_filesystem_fio_test/12073991_aarch64_1_dmesg.log
>
> https://s3.us-east-1.amazonaws.com/arr-cki-prod-datawarehouse-public/datawarehouse-public/2022/06/02/553734635/redhat:553734635_aarch64/tests/Boot_test/12073991_aarch64_1_test_console.log
>
> CKI issue tracker: https://datawarehouse.cki-project.org/issue/1259
>
> Thanks,
> Bruno Goncalves