Received-SPF: pass (google.com: domain of linux-kernel+bounces-97689-linux.lists.archive=gmail.com@vger.kernel.org designates 2604:1380:4601:e00::3 as permitted sender) client-ip=2604:1380:4601:e00::3;
Precedence: bulk
MIME-Version: 1.0
References: <20240308120332.372810-1-retpolanne@posteo.net>
 <Zeto8ShG406K6cnD@x1> <m2jzmc318b.fsf@posteo.net>
In-Reply-To: <m2jzmc318b.fsf@posteo.net>
From: Namhyung Kim <namhyung@kernel.org>
Date: Fri, 8 Mar 2024 15:24:29 -0800
Message-ID: <CAM9d7cjxNsOcGYAY4mi8-4+0w6YCAmQJCBdUFwW8q7_wh33EpQ@mail.gmail.com>
Subject: Re: [PATCH v0] perf lock contention: skip traceiter functions
To: Anne Macedo <retpolanne@posteo.net>
Cc: Arnaldo Carvalho de Melo <acme@kernel.org>, Peter Zijlstra <peterz@infradead.org>, 
	Ingo Molnar <mingo@redhat.com>, Mark Rutland <mark.rutland@arm.com>, 
	Alexander Shishkin <alexander.shishkin@linux.intel.com>, Jiri Olsa <jolsa@kernel.org>, 
	Ian Rogers <irogers@google.com>, Adrian Hunter <adrian.hunter@intel.com>, 
	linux-perf-users@vger.kernel.org, linux-kernel@vger.kernel.org
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

On Fri, Mar 8, 2024 at 12:42=E2=80=AFPM Anne Macedo <retpolanne@posteo.net>=
 wrote:
>
> Arnaldo Carvalho de Melo <acme@kernel.org> writes:
>
> > On Fri, Mar 08, 2024 at 12:03:31PM +0000, Anne Macedo wrote:
> >> The perf lock contention program currently shows the caller of the loc=
ks
> >> as __traceiter_contention_begin+0x??. This caller can be ignored, as i=
t is
> >> from the traceiter itself. Instead, it should show the real callers fo=
r
> >> 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 symbol=
s
> >> 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   calle=
r
> >>
> >>          8      2.33 s       2.28 s     291.18 ms     rwlock:W   __tra=
ceiter_contention_begin+0x44
> >>          4      2.33 s       2.28 s     582.35 ms     rwlock:W   __tra=
ceiter_contention_begin+0x44
> >>          7    140.30 ms     46.77 ms     20.04 ms     rwlock:W   __tra=
ceiter_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   __tra=
ceiter_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   __tra=
ceiter_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   calle=
r
> >>
> >>          2      2.24 s       2.24 s       1.12 s      rwlock:W   do_ep=
oll_wait+0x5a0
> >>          4      1.65 s     824.21 ms    412.08 ms     rwlock:W   do_ex=
it+0x338
> >>          2    824.35 ms    824.29 ms    412.17 ms     spinlock   get_s=
ignal+0x108
> >>          2    824.14 ms    824.14 ms    412.07 ms     rwlock:W   relea=
se_task+0x68
> >>          1     25.22 ms     25.22 ms     25.22 ms        mutex   cgrou=
p_kn_lock_live+0x58
> >>          1     24.71 us     24.71 us     24.71 us     spinlock   do_ex=
it+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   calle=
r
> >>
> >>          6      5.27 s       1.76 s     878.55 ms     rwlock:W   relea=
se_task+0x68
> >>          2      2.99 s       2.99 s       1.50 s      spinlock   do_se=
nd_sig_info+0x3c
> >>          2      1.77 s       1.77 s     884.39 ms     spinlock   sigpr=
ocmask+0x98
> >>          2      1.76 s       1.76 s     878.56 ms     rwlock:W   do_ex=
it+0x338
> >>          2      1.76 s       1.76 s     878.55 ms     rwlock:W   relea=
se_task+0x68
> >>          5      1.76 s       1.76 s     351.41 ms     rwlock:W   do_ex=
it+0x338
> >>          1     48.10 ms     48.10 ms     48.10 ms        mutex   trace=
_contention_begin+0x84
> >>          4    257.80 us    119.34 us     64.45 us     spinlock   get_s=
ignal+0x108
> >>          1      9.33 us      9.33 us      9.33 us     rwlock:W   do_ex=
it+0x338
> >
> > Testing it on the ARM64 board sometimes also show that
> > trace_contention_begin+0x84, maybe we need to skip that one as well?
> >
> I can skip trace_contention_begin and trace_contention_end as well.
>
> Question: I have 1409 __traceiter symbols on my kernel build, should we
> ignore them all? Or is __traceiter_contention_begin and
> __traceiter_contention_end the only ones that concern the lock contention=
?
>
> cat /proc/kallsyms | grep -P '\b__traceiter*' | wc -l
> 1409

Currently it's only __traceiter_contention_begin, we don't collect
stacktrace at contention_end for now.  Also we cannot guarantee
if __traceiter_contention_end is right after the contention_begin
so I think you should use sym->end of the contention_begin for
text_end.

And, traceiter functions don't belong to their own section so the
comment should be removed.  But I hope we can move them to
a section to make things clearer. :)

Thanks,
Namhyung