question about behaviour of cpuidle on 6.6...seeing *many* missed estimates

[Chris Friesen <chris.friesen@windriver.com>]

Hi,

I've got an Ice Lake server running 6.6 PREEMPT_RT, currently using the 
acpi_idle cpuidle driver and the "menu" governor.  I'm seeing some weird 
behaviour with cpuidle and C-states and was hoping someone might be able 
to shed some light on what's happening.

I'm doing a test with qperf, running a qperf server on one CPU and then 
on another CPU running the client in a loop to test latency:

while [ 1 ]; do date;  qperf ${ip} tcp_lat;  qperf ${ip} udp_lat; done


CPU 34 is running the server, and CPU 3 is running the client.


Initially, both CPU 3 and 34 are allowed to sleep in C2.   In this case 
the qperf tests report a latency of around 120 usec.   Tracing the 
cpu_idle events on CPU 34 shows it asking for C2 and sleeping for ~175usec.

<idle>-0       [034] d..1. 763120.481960: cpu_idle: state=2 cpu_id=34
<idle>-0       [034] dN.1. 763120.482140: cpu_idle: state=4294967295 
cpu_id=34
<idle>-0       [034] d..1. 763120.482199: cpu_idle: state=2 cpu_id=34
<idle>-0       [034] dN.1. 763120.482373: cpu_idle: state=4294967295 
cpu_id=34

CPU 3 sees similar behaviour:

<idle>-0       [003] d..1. 763120.479151: cpu_idle: state=2 cpu_id=3
<idle>-0       [003] dN.1. 763120.479329: cpu_idle: state=4294967295 
cpu_id=3
<idle>-0       [003] d..1. 763120.479390: cpu_idle: state=2 cpu_id=3
<idle>-0       [003] dN.1. 763120.479575: cpu_idle: state=4294967295 
cpu_id=3


If I disable C2 on CPU 34, the reported qperf latency goes down to 
around 17 usec.  Tracing the cpu_idle events on CPU 34 shows it asking 
for C1 and sleeping for ~20 usec.

<idle>-0       [034] d..1. 763619.245990: cpu_idle: state=1 cpu_id=34
<idle>-0       [034] dN.1. 763619.246009: cpu_idle: state=4294967295 
cpu_id=34
<idle>-0       [034] d..1. 763619.246021: cpu_idle: state=1 cpu_id=34
<idle>-0       [034] dN.1. 763619.246042: cpu_idle: state=4294967295 
cpu_id=34

On CPU 3 however, we see it repeatedly asking for C2, sleeping for ~20 
usec, and reporting a cpu_idle_miss event.

<idle>-0       [003] d..1. 763619.464429: cpu_idle: state=2 cpu_id=3
<idle>-0       [003] dN.1. 763619.464441: cpu_idle: state=4294967295 
cpu_id=3
<idle>-0       [003] .N.1. 763619.464441: cpu_idle_miss: cpu_id=3 
state=2 type=above
<idle>-0       [003] d..1. 763619.464464: cpu_idle: state=2 cpu_id=3
<idle>-0       [003] dN.1. 763619.464475: cpu_idle: state=4294967295 
cpu_id=3
<idle>-0       [003] .N.1. 763619.464476: cpu_idle_miss: cpu_id=3 
state=2 type=above

Interestingly, turbostat reports that we're not actually spending much 
time in C2 (aka C6) even though it was requested:

CPU     POLL    C1      C2      POLL%   C1%     C2%     CPU%c1  CPU%c6
34      1       152881  0       0.00    62.25   0.00    58.10
3       0       54      152813  0.00    0.01    34.00   26.78   0.08


Similarly, if I disable C2 on CPU 3 (where the client is running), I 
*also* see the reported qperf latency going down to around 17 usec.  In 
this case the roles are reversed, with CPU 34 asking for C2 sleep, then 
sleeping for 12 usec and reporting a cpu_idle_miss event.   During this 
run CPU 3 asks for a C1 sleep and then sleeps for ~22usec.


I have several questions:

1) Is this qperf behaviour expected?   It looks like there's a sort of 
vicious circle where the server sleeps in C2 and so it takes longer to 
handle an incoming packet, the wakeup latency means the client sees a 
longer latency, so it sleeps in C2, which causes a longer latency so the 
server sleeps in C2 again, etc.   As soon as either end is restricted to 
C1, the other end also sleeps for shorter periods.

2) How is it possible that CPU 3 is continuously asking for C2 sleeps 
even though every single idle sleep results in an early wakeup after 
about 20 usec?  Shouldn't it eventually clue in and start asking for C1?

3) How does CPU 3 end up mostly in C1 when it's asking for C2 (aka C6)? 
Is the processor essentially overriding the request for C2?


Thanks,
Chris Friesen