Re: [PATCH v1] perf lock contention: skip traceiter functions

Anne Macedo
2024-03-11T19:25:32Z

Anne Macedo <retpolanne@posteo.net> writes:

> Namhyung Kim <namhyung@kernel.org> writes:
>
>> Hello Anne,
>>
>> On Sat, Mar 9, 2024 at 5:27 AM Anne Macedo <retpolanne@posteo.net> wrote:
>>>
>>> The perf lock contention program currently shows the caller of the locks
>>> as __traceiter_contention_begin+0x??. This caller can be ignored, as it is
>>> from the traceiter itself. Instead, it should show the real callers for
>>> the locks.
>>>
>>> When fiddling with the --stack-skip parameter, the actual callers for
>>> the locks start to show up. However, just ignore the
>>> __traceiter_contention_begin and the __traceiter_contention_end symbols
>>> so the actual callers will show up.
>>>
>>> Before this patch is applied:
>>>
>>> sudo perf lock con -a -b -- sleep 3
>>> contended total wait max wait avg wait type caller
>>>
>>> 8 2.33 s 2.28 s 291.18 ms rwlock:W __traceiter_contention_begin+0x44
>>> 4 2.33 s 2.28 s 582.35 ms rwlock:W __traceiter_contention_begin+0x44
>>> 7 140.30 ms 46.77 ms 20.04 ms rwlock:W __traceiter_contention_begin+0x44
>>> 2 63.35 ms 33.76 ms 31.68 ms mutex trace_contention_begin+0x84
>>> 2 46.74 ms 46.73 ms 23.37 ms rwlock:W __traceiter_contention_begin+0x44
>>> 1 13.54 us 13.54 us 13.54 us mutex trace_contention_begin+0x84
>>> 1 3.67 us 3.67 us 3.67 us rwsem:R __traceiter_contention_begin+0x44
>>>
>>> Before this patch is applied - using --stack-skip 5
>>>
>>> sudo perf lock con --stack-skip 5 -a -b -- sleep 3
>>> contended total wait max wait avg wait type caller
>>>
>>> 2 2.24 s 2.24 s 1.12 s rwlock:W do_epoll_wait+0x5a0
>>> 4 1.65 s 824.21 ms 412.08 ms rwlock:W do_exit+0x338
>>> 2 824.35 ms 824.29 ms 412.17 ms spinlock get_signal+0x108
>>> 2 824.14 ms 824.14 ms 412.07 ms rwlock:W release_task+0x68
>>> 1 25.22 ms 25.22 ms 25.22 ms mutex cgroup_kn_lock_live+0x58
>>> 1 24.71 us 24.71 us 24.71 us spinlock do_exit+0x44
>>> 1 22.04 us 22.04 us 22.04 us rwsem:R lock_mm_and_find_vma+0xb0
>>>
>>> After this patch is applied:
>>>
>>> sudo ./perf lock con -a -b -- sleep 3
>>> contended total wait max wait avg wait type caller
>>>
>>> 4 4.13 s 2.07 s 1.03 s rwlock:W release_task+0x68
>>> 2 2.07 s 2.07 s 1.03 s rwlock:R mm_update_next_owner+0x50
>>> 2 2.07 s 2.07 s 1.03 s rwlock:W do_exit+0x338
>>> 1 41.56 ms 41.56 ms 41.56 ms mutex cgroup_kn_lock_live+0x58
>>> 2 36.12 us 18.83 us 18.06 us rwlock:W do_exit+0x338
>>>
>>> changes since v0:
>>>
>>> - skip trace_contention functions
>>> - use sym->end instead of __traceiter_contention_end for text_end
>>>
>>> Signed-off-by: Anne Macedo <retpolanne@posteo.net>
>>> ---
>>> tools/perf/util/machine.c | 17 +++++++++++++++++
>>> tools/perf/util/machine.h | 2 +-
>>> 2 files changed, 18 insertions(+), 1 deletion(-)
>>>
>>> diff --git a/tools/perf/util/machine.c b/tools/perf/util/machine.c
>>> index 527517db3182..db443947ccd1 100644
>>> --- a/tools/perf/util/machine.c
>>> +++ b/tools/perf/util/machine.c
>>> @@ -3266,6 +3266,14 @@ bool machine__is_lock_function(struct machine *machine, u64 addr)
>>>
>>> sym = machine__find_kernel_symbol_by_name(machine, "__lock_text_end", &kmap);
>>> machine->lock.text_end = map__unmap_ip(kmap, sym->start);
>>> +
>>> + sym = machine__find_kernel_symbol_by_name(machine, "__traceiter_contention_begin", &kmap);
>>
>> Unlike __sched_text_{start,end} and __lock_text_{start,end} I guess
>> this traceiter thing is optional so it might not be there. You need to
>> handle if it's NULL.
>>
>
> Let me test with CONFIG_TRACEPOINTS=n then.
>
Thanks for pointing out, with CONFIG_TRACEPOINTS=n perf lock contention
won't work, but I tried with a faux symbol and got a segfault. v2 will
handle that.
>
>> I think it depends on the kernel version and configuration. I remember
>> I saw a different symbol on old kernels. But it'd be hard to handle all
>> the cases. Let's have a single trace text section in the struct machine
>> and use __traceiter_contention_begin only. If it's not found you can
>> fallback to trace_contention_begin.

However, if we fallback to trace_contention_begin, we won't be able to
filter out both __traceiter_contention_begin and trace_contention_begin
at the same time.

>>
> ACK :)
>>
>> Thanks,
>> Namhyung
>>
>>
>>> + machine->traceiter.text_start = map__unmap_ip(kmap, sym->start);
>>> + machine->traceiter.text_end = map__unmap_ip(kmap, sym->end);
>>> +
>>> + sym = machine__find_kernel_symbol_by_name(machine, "trace_contention_begin", &kmap);
>>> + machine->trace.text_start = map__unmap_ip(kmap, sym->start);
>>> + machine->trace.text_end = map__unmap_ip(kmap, sym->end);
>>> }
>>>
>>> /* failed to get kernel symbols */
>>> @@ -3280,5 +3288,14 @@ bool machine__is_lock_function(struct machine *machine, u64 addr)
>>> if (machine->lock.text_start <= addr && addr < machine->lock.text_end)
>>> return true;
>>>
>>> + /* traceiter functions currently don't have their own section
>>> + * but we consider them lock functions
>>> + */
>>> + if (machine->traceiter.text_start <= addr && addr < machine->traceiter.text_end)
>>> + return true;
>>> +
>>> + if (machine->trace.text_start <= addr && addr < machine->trace.text_end)
>>> + return true;
>>> +
>>> return false;
>>> }
>>> diff --git a/tools/perf/util/machine.h b/tools/perf/util/machine.h
>>> index e28c787616fe..4312f6db6de0 100644
>>> --- a/tools/perf/util/machine.h
>>> +++ b/tools/perf/util/machine.h
>>> @@ -49,7 +49,7 @@ struct machine {
>>> struct {
>>> u64 text_start;
>>> u64 text_end;
>>> - } sched, lock;
>>> + } sched, lock, traceiter, trace;
>>> pid_t *current_tid;
>>> size_t current_tid_sz;
>>> union { /* Tool specific area */
>>> --
>>> 2.39.2
>>>
Thanks, Anne