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 v3:
- remove dummy value and assume machine->traceiter and machine->trace
have zero address
changes since v2:
- add dummy value to machine->traceiter and machine->trace to make
necessary checks, fixing possible null pointer access
changes since v1:
- consider trace_contention and __traceiter_contention functions as
optional (i.e. check if sym is null to avoid segfault)
changes since v0:
- skip trace_contention functions
- use sym->end instead of __traceiter_contention_end for text_end
Signed-off-by: Anne Macedo <[email protected]>
---
tools/perf/util/machine.c | 24 ++++++++++++++++++++++++
tools/perf/util/machine.h | 2 +-
2 files changed, 25 insertions(+), 1 deletion(-)
diff --git a/tools/perf/util/machine.c b/tools/perf/util/machine.c
index 527517db3182..5eb9044bc223 100644
--- a/tools/perf/util/machine.c
+++ b/tools/perf/util/machine.c
@@ -3266,6 +3266,17 @@ 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);
+ if (sym) {
+ 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);
+ if (sym) {
+ 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 +3291,18 @@ 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 != 0) {
+ if (machine->traceiter.text_start <= addr && addr < machine->traceiter.text_end)
+ return true;
+ }
+
+ if (machine->trace.text_start != 0) {
+ 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
Hi Anne,
On Tue, Mar 19, 2024 at 7:36 AM Anne Macedo <[email protected]> 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 v3:
>
> - remove dummy value and assume machine->traceiter and machine->trace
> have zero address
>
> changes since v2:
>
> - add dummy value to machine->traceiter and machine->trace to make
> necessary checks, fixing possible null pointer access
>
> changes since v1:
>
> - consider trace_contention and __traceiter_contention functions as
> optional (i.e. check if sym is null to avoid segfault)
>
> changes since v0:
>
> - skip trace_contention functions
> - use sym->end instead of __traceiter_contention_end for text_end
>
> Signed-off-by: Anne Macedo <[email protected]>
Thanks for your work!
Acked-by: Namhyung Kim <[email protected]>
Thanks,
Namhyung
> ---
> tools/perf/util/machine.c | 24 ++++++++++++++++++++++++
> tools/perf/util/machine.h | 2 +-
> 2 files changed, 25 insertions(+), 1 deletion(-)
>
> diff --git a/tools/perf/util/machine.c b/tools/perf/util/machine.c
> index 527517db3182..5eb9044bc223 100644
> --- a/tools/perf/util/machine.c
> +++ b/tools/perf/util/machine.c
> @@ -3266,6 +3266,17 @@ 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);
> + if (sym) {
> + 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);
> + if (sym) {
> + 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 +3291,18 @@ 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 != 0) {
> + if (machine->traceiter.text_start <= addr && addr < machine->traceiter.text_end)
> + return true;
> + }
> +
> + if (machine->trace.text_start != 0) {
> + 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
>
Now lemme nitpick a bit, and I'll do it myself while processing the
patch, some are from my days sending patches to Ingo and from his
requests it become second nature, others I do to further clarify the
text:
And here is the reason for top posting, the first request is about the
subject line:
Subject: [PATCH v4] perf lock contention: skip traceiter functions
Becomes:
Subject: [PATCH v4] perf lock contention: Trim backtrace by skipping traceiter functions
Please make it so that after the component the one line summary starts
with a capital letter and packs as much info as possible.
On Tue, Mar 19, 2024 at 02:36:26PM +0000, Anne Macedo wrote:
> The perf lock contention program currently shows the caller of the locks
I try to make the sub (sub) command stand out by single quoting it:
The 'perf lock contention' program currently shows the caller of the locks
What follows is great, nice description, before/after.
Thanks, testing it now on x86_64 and aarch64, will apply it then.
- Arnaldo
> 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 v3:
>
> - remove dummy value and assume machine->traceiter and machine->trace
> have zero address
>
> changes since v2:
>
> - add dummy value to machine->traceiter and machine->trace to make
> necessary checks, fixing possible null pointer access
>
> changes since v1:
>
> - consider trace_contention and __traceiter_contention functions as
> optional (i.e. check if sym is null to avoid segfault)
>
> changes since v0:
>
> - skip trace_contention functions
> - use sym->end instead of __traceiter_contention_end for text_end
>
> Signed-off-by: Anne Macedo <[email protected]>
> ---
> tools/perf/util/machine.c | 24 ++++++++++++++++++++++++
> tools/perf/util/machine.h | 2 +-
> 2 files changed, 25 insertions(+), 1 deletion(-)
>
> diff --git a/tools/perf/util/machine.c b/tools/perf/util/machine.c
> index 527517db3182..5eb9044bc223 100644
> --- a/tools/perf/util/machine.c
> +++ b/tools/perf/util/machine.c
> @@ -3266,6 +3266,17 @@ 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);
> + if (sym) {
> + 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);
> + if (sym) {
> + 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 +3291,18 @@ 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 != 0) {
> + if (machine->traceiter.text_start <= addr && addr < machine->traceiter.text_end)
> + return true;
> + }
> +
> + if (machine->trace.text_start != 0) {
> + 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
>
On Thu, Mar 21, 2024 at 04:58:20PM -0300, Arnaldo Carvalho de Melo wrote:
> Thanks, testing it now on x86_64 and aarch64, will apply it then.
Done, applied, on aarch64:
root@roc-rk3399-pc:~# perf lock contention --use-bpf -a find / > /dev/null
contended total wait max wait avg wait type caller
6 6.03 s 6.03 s 1.00 s spinlock __tick_broadcast_oneshot_control+0xc0
19 811.74 ms 621.76 ms 42.72 ms spinlock rcu_core+0xec
2 201.76 ms 201.75 ms 100.88 ms spinlock sugov_update_shared+0x44
6 7.80 ms 2.35 ms 1.30 ms mutex regulator_lock_recursive+0x144
1 702.63 us 702.63 us 702.63 us rwsem:W __btrfs_tree_lock+0x2c
4 62.42 us 18.96 us 15.60 us spinlock tick_do_update_jiffies64+0x44
2 39.96 us 22.17 us 19.98 us spinlock __tick_broadcast_oneshot_control+0xc0
2 33.83 us 18.08 us 16.92 us mutex mmc_blk_rw_wait+0x138
1 21.58 us 21.58 us 21.58 us spinlock sugov_update_shared+0x44
1 16.92 us 16.92 us 16.92 us spinlock cpu_pm_enter+0x34
1 16.04 us 16.04 us 16.04 us mutex clk_prepare_lock+0x4c
root@roc-rk3399-pc:~# uname -a
Linux roc-rk3399-pc 6.1.68-12200-g1c40dda3081e #1 SMP PREEMPT_DYNAMIC Thu Dec 14 04:02:49 EST 2023 aarch64 aarch64 aarch64 GNU/Linux
root@roc-rk3399-pc:~#
its in tmp.perf-tools-next, will move to perf-tools-next in the next batch, after build
tests together with other patches.
Thanks!
- Arnaldo