Re: [PATCH v1] cgroup/rstat: add cgroup_rstat_cpu_lock helpers and tracepoints

[Jesper Dangaard Brouer <hawk@kernel.org>]

On 01/05/2024 20.41, Waiman Long wrote:
> On 5/1/24 13:22, Jesper Dangaard Brouer wrote:
>>
>>
>> On 01/05/2024 16.24, Waiman Long wrote:
>>> On 5/1/24 10:04, Jesper Dangaard Brouer wrote:
>>>> This closely resembles helpers added for the global 
>>>> cgroup_rstat_lock in
>>>> commit fc29e04ae1ad ("cgroup/rstat: add cgroup_rstat_lock helpers and
>>>> tracepoints"). This is for the per CPU lock cgroup_rstat_cpu_lock.
>>>>
>>>> Based on production workloads, we observe the fast-path "update" 
>>>> function
>>>> cgroup_rstat_updated() is invoked around 3 million times per sec, 
>>>> while the
>>>> "flush" function cgroup_rstat_flush_locked(), walking each possible 
>>>> CPU,
>>>> can see periodic spikes of 700 invocations/sec.
>>>>
>>>> For this reason, the tracepoints are split into normal and fastpath
>>>> versions for this per-CPU lock. Making it feasible for production to
>>>> continuously monitor the non-fastpath tracepoint to detect lock 
>>>> contention
>>>> issues. The reason for monitoring is that lock disables IRQs which can
>>>> disturb e.g. softirq processing on the local CPUs involved. When the
>>>> global cgroup_rstat_lock stops disabling IRQs (e.g converted to a 
>>>> mutex),
>>>> this per CPU lock becomes the next bottleneck that can introduce 
>>>> latency
>>>> variations.
>>>>
>>>> A practical bpftrace script for monitoring contention latency:
>>>>
>>>>   bpftrace -e '
>>>>     tracepoint:cgroup:cgroup_rstat_cpu_lock_contended {
>>>>       @start[tid]=nsecs; @cnt[probe]=count()}
>>>>     tracepoint:cgroup:cgroup_rstat_cpu_locked {
>>>>       if (args->contended) {
>>>>         @wait_ns=hist(nsecs-@start[tid]); delete(@start[tid]);}
>>>>       @cnt[probe]=count()}
>>>>     interval:s:1 {time("%H:%M:%S "); print(@wait_ns); print(@cnt); 
>>>> clear(@cnt);}'
>>>
>>> This is a per-cpu lock. So the only possible contention involves only 
>>> 2 CPUs - a local CPU invoking cgroup_rstat_updated(). A flusher CPU 
>>> doing cgroup_rstat_flush_locked() calling into 
>>> cgroup_rstat_updated_list(). With recent commits to reduce the percpu 
>>> lock hold time, I doubt lock contention on the percpu lock will have 
>>> a great impact on latency. 
>>
>> I do appriciate your recent changes to reduce the percpu lock hold time.
>> These tracepoints allow me to measure and differentiate the percpu lock
>> hold time vs. the flush time.
>>
>> In production (using [1]) I'm seeing "Long lock-hold time" [L100] e.g.
>> upto 29 ms, which is time spend after obtaining the lock (runtime under
>> lock).  I was expecting to see "High Lock-contention wait" [L82] which
>> is the time waiting for obtaining the lock.
>>
>> This is why I'm adding these tracepoints, as they allow me to digg
>> deeper, to understand where this high runtime variations originate from.
>>
>>
>> Data:
>>
>>  16:52:09 Long lock-hold time: 14950 usec (14 ms) on CPU:34 comm:kswapd4
>>  16:52:09 Long lock-hold time: 14821 usec (14 ms) on CPU:34 comm:kswapd4
>>  16:52:09 Long lock-hold time: 11299 usec (11 ms) on CPU:98 comm:kswapd4
>>  16:52:09 Long lock-hold time: 17237 usec (17 ms) on CPU:113 comm:kswapd6
>>  16:52:09 Long lock-hold time: 29000 usec (29 ms) on CPU:36 
>> comm:kworker/u261:12
> That lock hold time is much higher than I would have expected.
>>  16:52:09 time elapsed: 80 sec (interval = 1 sec)
>>   Flushes(5033) 294/interval (avg 62/sec)
>>   Locks(53374) 1748/interval (avg 667/sec)
>>   Yields(48341) 1454/interval (avg 604/sec)
>>   Contended(48104) 1450/interval (avg 601/sec)
>>
>>
>>> So do we really need such an elaborate scheme to monitor this? BTW, 
>>> the additional code will also add to the worst case latency.
>>
>> Hmm, I designed this code to have minimal impact, as tracepoints are
>> no-ops until activated.  I really doubt this code will change the 
>> latency.
>>
>>
>> [1] 
>> https://github.com/xdp-project/xdp-project/blob/master/areas/latency/cgroup_rstat_tracepoint.bt
>>
>> [L100] 
>> https://github.com/xdp-project/xdp-project/blob/master/areas/latency/cgroup_rstat_tracepoint.bt#L100
>>
>> [L82] 
>> https://github.com/xdp-project/xdp-project/blob/master/areas/latency/cgroup_rstat_tracepoint.bt#L82
>>
>>>>
>>>> Signed-off-by: Jesper Dangaard Brouer <hawk@kernel.org>
>>
>> More data, the histogram of time spend under the lock have some strange
>> variation issues with a group in 4ms to 65ms area. Investigating what
>> can be causeing this... which next step depend in these tracepoints.
>>
>> @lock_cnt: 759146
>>
>> @locked_ns:
>> [1K, 2K)             499 |      |
>> [2K, 4K)          206928 
>> |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
>> [4K, 8K)          147904 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@      |
>> [8K, 16K)          64453 |@@@@@@@@@@@@@@@@      |
>> [16K, 32K)        135467 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ |
>> [32K, 64K)         75943 |@@@@@@@@@@@@@@@@@@@      |
>> [64K, 128K)        38359 |@@@@@@@@@      |
>> [128K, 256K)       46597 |@@@@@@@@@@@      |
>> [256K, 512K)       32466 |@@@@@@@@      |
>> [512K, 1M)          3945 |      |
>> [1M, 2M)             642 |      |
>> [2M, 4M)             750 |      |
>> [4M, 8M)            1932 |      |
>> [8M, 16M)           2114 |      |
>> [16M, 32M)          1039 |      |
>> [32M, 64M)           108 |      |
>>
>>
>>
>>
>>>> ---
>>>>   include/trace/events/cgroup.h |   56 
>>>> +++++++++++++++++++++++++++++----
>>>>   kernel/cgroup/rstat.c         |   70 
>>>> ++++++++++++++++++++++++++++++++++-------
>>>>   2 files changed, 108 insertions(+), 18 deletions(-)
>>>>
>>>> diff --git a/include/trace/events/cgroup.h 
>>>> b/include/trace/events/cgroup.h
>>>> index 13f375800135..0b95865a90f3 100644
>>>> --- a/include/trace/events/cgroup.h
[...]
>>>> +++ b/include/trace/events/cgroup.h >>>> +DEFINE_EVENT(cgroup_rstat, cgroup_rstat_cpu_unlock_fastpath,
>>>> +
>>>> +    TP_PROTO(struct cgroup *cgrp, int cpu, bool contended),
>>>> +
>>>> +    TP_ARGS(cgrp, cpu, contended)
>>>> +);
>>>> +
>>>>   #endif /* _TRACE_CGROUP_H */
>>>>   /* This part must be outside protection */
>>>> diff --git a/kernel/cgroup/rstat.c b/kernel/cgroup/rstat.c
>>>> index 52e3b0ed1cee..fb8b49437573 100644
>>>> --- a/kernel/cgroup/rstat.c
>>>> +++ b/kernel/cgroup/rstat.c
>>>> @@ -19,6 +19,60 @@ static struct cgroup_rstat_cpu 
>>>> *cgroup_rstat_cpu(struct cgroup *cgrp, int cpu)
>>>>       return per_cpu_ptr(cgrp->rstat_cpu, cpu);
>>>>   }
>>>> +/*
>>>> + * Helper functions for rstat per CPU lock (cgroup_rstat_cpu_lock).
>>>> + *
>>>> + * This makes it easier to diagnose locking issues and contention in
>>>> + * production environments. The parameter @fast_path determine the
>>>> + * tracepoints being added, allowing us to diagnose "flush" related
>>>> + * operations without handling high-frequency fast-path "update" 
>>>> events.
>>>> + */
>>>> +static __always_inline
>>>> +unsigned long _cgroup_rstat_cpu_lock(raw_spinlock_t *cpu_lock, int 
>>>> cpu,
>>>> +                     struct cgroup *cgrp, const bool fast_path)
>>>> +{
>>>> +    unsigned long flags;
>>>> +    bool contended;
>>>> +
>>>> +    /*
>>>> +     * The _irqsave() is needed because cgroup_rstat_lock is
>>>> +     * spinlock_t which is a sleeping lock on PREEMPT_RT. Acquiring
>>>> +     * this lock with the _irq() suffix only disables interrupts on
>>>> +     * a non-PREEMPT_RT kernel. The raw_spinlock_t below disables
>>>> +     * interrupts on both configurations. The _irqsave() ensures
>>>> +     * that interrupts are always disabled and later restored.
>>>> +     */
>>>> +    contended = !raw_spin_trylock_irqsave(cpu_lock, flags);
>>>> +    if (contended) {
>>>> +        if (fast_path)
>>>> + trace_cgroup_rstat_cpu_lock_contended_fastpath(cgrp, cpu, contended);
>>>> +        else
>>>> +            trace_cgroup_rstat_cpu_lock_contended(cgrp, cpu, 
>>>> contended);
>>>> +
>>>> +        raw_spin_lock_irqsave(cpu_lock, flags);
> 
> Could you do a local_irq_save() before calling trace_cgroup*() and 
> raw_spin_lock()? Would that help in eliminating this high lock hold time?
> 

Nope it will not eliminating high lock *hold* time, because the hold
start timestamp is first taken *AFTER* obtaining the lock.

It could help the contended "wait-time" measurement, but my prod
measurements show this isn't an issues.

> You can also do a local_irq_save() first before the trylock. That will 
> eliminate the duplicated irq_restore() and irq_save() when there is 
> contention.

I wrote the code like this on purpose ;-)
My issue with this code/lock is it cause latency issues for softirq 
NET_RX. So, when I detect a "contended" lock event, I do want a 
irq_restore() as that will allow networking/do_softirq() to run before I 
start waiting for the lock (with IRQ disabled).


> If not, there may be NMIs mixed in.
> 

NMIs are definitely on my list of things to investigate.
These AMD CPUs also have other types of interrupts that needs a close look.

The easier explaination is that the lock isn't "yielded" on every cycle
through the for each CPU loop.

Lets look at the data I provided above:

 >>   Flushes(5033) 294/interval (avg 62/sec)
 >>   Locks(53374) 1748/interval (avg 667/sec)
 >>   Yields(48341) 1454/interval (avg 604/sec)
 >>   Contended(48104) 1450/interval (avg 601/sec)

In this 1 second sample, we have 294 flushes, and more yields 1454,
great but the factor is not 128 (num-of-CPUs) but closer to 5.  Thus, on
average we hold the lock for (128/5) 25.6 CPUs-walks.

We have spoken about releasing the lock on for_each CPU before... it
will likely solve this long hold time, but IMHO a mutex is still the
better solution.

--Jesper