Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
Message-ID: <27e4a2b4557ae24e673b6fb85b34fe0e32efa06f.camel@redhat.com>
Subject: Re: [RFC PATCH v3 1/1] trace,smp: Add tracepoints around remotelly
 called functions
From:   Leonardo =?ISO-8859-1?Q?Br=E1s?= <leobras@redhat.com>
To:     Valentin Schneider <vschneid@redhat.com>,
        Steven Rostedt <rostedt@goodmis.org>,
        Masami Hiramatsu <mhiramat@kernel.org>,
        Peter Zijlstra <peterz@infradead.org>,
        "Paul E. McKenney" <paulmck@kernel.org>,
        Juergen Gross <jgross@suse.com>,
        Yury Norov <yury.norov@gmail.com>,
        Chen Zhongjin <chenzhongjin@huawei.com>,
        Zhen Lei <thunder.leizhen@huawei.com>,
        Marcelo Tosatti <mtosatti@redhat.com>,
        Thomas Gleixner <tglx@linutronix.de>,
        Sebastian Andrzej Siewior <bigeasy@linutronix.de>,
        Nadav Amit <namit@vmware.com>,
        Daniel Bristot de Oliveira <bristot@kernel.org>
Cc:     linux-kernel@vger.kernel.org, linux-trace-kernel@vger.kernel.org
Date:   Mon, 15 May 2023 14:56:53 -0300
In-Reply-To: <xhsmhsfc3i1bc.mognet@vschneid.remote.csb>
References: <20230510230128.150384-1-leobras@redhat.com>
         <xhsmhsfc3i1bc.mognet@vschneid.remote.csb>
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
User-Agent: Evolution 3.48.1 
MIME-Version: 1.0
Precedence: bulk

On Thu, 2023-05-11 at 11:56 +0100, Valentin Schneider wrote:
> On 10/05/23 20:01, Leonardo Bras wrote:
> > When running RT workloads in isolated CPUs, many cases of deadline miss=
es
> > are caused by remote CPU requests such as smp_call_function*().
> >=20
> > For those cases, having the names of those functions running around the
> > deadline miss moment could help (a lot) finding a target for the next
> > improvements.
> >=20
> > Add tracepoints for acquiring the function name & csd before entry and
> > after returning from the remote-cpu requested function.
> >=20
> > Also, add tracepoints on the remote cpus requesting them.
>=20
> Per the v1 thread, I got some context as to why we want this, but this
> changelog is quite sparse on the subject. How about:
>=20
> """
> The recently added ipi_send_{cpu,cpumask} tracepoints allow finding sourc=
es
> of IPIs targeting CPUs running latency-sensitive applications.
>=20
> For NOHZ_FULL CPUs, all IPIs are interference, and those tracepoints are
> sufficient to find them and work on getting rid of them. In some setups
> however, not *all* IPIs are to be suppressed, but long-running IPI
> callbacks can still be problematic.
>=20
> Add a pair of tracepoints to mark the start and end of processing a CSD I=
PI
> callback, similar to what exists for softirq, workqueue or timer callback=
s.
> """
>=20
> And you can probably split the csd_queue_cpu TP into a separate commit,
> with something along the lines of:
>=20
> """
> Add a tracepoint for when a CSD is queued to a remote CPU's
> call_single_queue. This allows finding exactly which CPU queued a given C=
SD
> when looking at a csd_function_{entry,exit} event, and also enables us to
> accurately measure IPI delivery time with e.g. a synthetic event:
>=20
>   $ echo 'hist:keys=3Dcpu,csd.hex:ts=3Dcommon_timestamp.usecs' >\
>       /sys/kernel/tracing/events/smp/csd_queue_cpu/trigger
>   $ echo 'csd_latency unsigned int dst_cpu; unsigned long csd; u64 time' =
>\
>       /sys/kernel/tracing/synthetic_events
>   $ echo \
>   'hist:keys=3Dcommon_cpu,csd.hex:'\
>   'time=3Dcommon_timestamp.usecs-$ts:'\
>   'onmatch(smp.csd_queue_cpu).trace(csd_latency,common_cpu,csd,$time)' >\
>       /sys/kernel/tracing/events/smp/csd_function_entry/trigger
>=20
>   $ trace-cmd record -e 'synthetic:csd_latency' hackbench
>   $ trace-cmd report
>   <...>-467   [001]    21.824263: csd_queue_cpu:        cpu=3D0 callsite=
=3Dtry_to_wake_up+0x2ea func=3Dsched_ttwu_pending csd=3D0xffff8880076148b8
>   <...>-467   [001]    21.824280: ipi_send_cpu:         cpu=3D0 callsite=
=3Dtry_to_wake_up+0x2ea callback=3Dgeneric_smp_call_function_single_interru=
pt+0x0
>   <...>-489   [000]    21.824299: csd_function_entry:   func=3Dsched_ttwu=
_pending csd=3D0xffff8880076148b8
>   <...>-489   [000]    21.824320: csd_latency:          dst_cpu=3D0, csd=
=3D18446612682193848504, time=3D36
> """

Sure, I will split the patch and add the commit msg as suggested.


>=20
> >=20
> > Signed-off-by: Leonardo Bras <leobras@redhat.com>
>=20
> Overall I like the CSD vs IPI split, it's a saner approach than logging i=
t
> all as IPIs, even if it does generate more events as we have to emit an
> event for every csd queued (i.e. no _cpumask() variant is possible).
>=20
> Some nitpicks below, and one other thing: are we happy with the smp event
> namespace, and with the new TP names? Should the namespace be csd instead=
,
> to match the trace_<namespace>_* nomenclature?

I selected "smp.h" filename because those tracepoints are getting used on s=
mp.c.

I think keeping a generic name is good for any future tracepoints people en=
d up
designing for smp.c, but I am open to discussion.

>=20
> > ---
> >=20
> > Changes since RFCv2:
> > - Fixed some spacing issues and trace calls
> >=20
> > Changes since RFCv1:
> > - Implemented trace_csd_queue_cpu() as suggested by Valentin Schneider
> > - Using EVENT_CLASS in order to avoid duplication
> > - Introduced new helper: csd_do_func()
> > - Name change from smp_call_function_* to csd_function_*
> > - Rebased on top of torvalds/master
> >=20
> >  include/trace/events/smp.h | 72 ++++++++++++++++++++++++++++++++++++++
> >  kernel/smp.c               | 41 +++++++++++++---------
> >  2 files changed, 96 insertions(+), 17 deletions(-)
> >  create mode 100644 include/trace/events/smp.h
> >=20
> > diff --git a/include/trace/events/smp.h b/include/trace/events/smp.h
> > new file mode 100644
> > index 000000000000..c304318a0203
> > --- /dev/null
> > +++ b/include/trace/events/smp.h
> > @@ -0,0 +1,72 @@
> > +/* SPDX-License-Identifier: GPL-2.0 */
> > +#undef TRACE_SYSTEM
> > +#define TRACE_SYSTEM smp
> > +
> > +#if !defined(_TRACE_SMP_H) || defined(TRACE_HEADER_MULTI_READ)
> > +#define _TRACE_SMP_H
> > +
> > +#include <linux/tracepoint.h>
> > +
> > +TRACE_EVENT(csd_queue_cpu,
> > +
> > +	TP_PROTO(const unsigned int cpu,
> > +		 unsigned long callsite,
> > +		 smp_call_func_t func,
> > +		 call_single_data_t *csd),
> > +
> > +	TP_ARGS(cpu, callsite, func, csd),
> > +
> > +	TP_STRUCT__entry(
> > +		__field(unsigned int, cpu)
> > +		__field(void *, callsite)
> > +		__field(void *, func)
> > +		__field(void *, csd)
> > +	),
> > +
> > +	TP_fast_assign(
> > +		__entry->cpu =3D cpu;
> > +		__entry->callsite =3D (void *)callsite;
> > +		__entry->func =3D func;
> > +		__entry->csd  =3D csd;
> > +	),
> > +
> > +	TP_printk("cpu=3D%u callsite=3D%pS func=3D%pS csd=3D%p",
>                                        ^^^^^^^^
> This can be func=3D%ps, offsets should always be 0 so not very useful (I =
know
> I put %pS for the IPI TPs, that's a force of habit...)
>=20

I agree, let's do as suggested.

> > +		  __entry->cpu, __entry->callsite, __entry->func, __entry->csd)
> > +);
>=20
> > +
> > +/*
> > + * Tracepoints for a function which is called as an effect of smp_call=
_function.*
> > + */
> > +DECLARE_EVENT_CLASS(csd_function,
> > +
> > +	TP_PROTO(smp_call_func_t func, call_single_data_t *csd),
> > +
> > +	TP_ARGS(func, csd),
> > +
> > +	TP_STRUCT__entry(
> > +		__field(void *,	func)
> > +		__field(void *,	csd)
> > +	),
> > +
> > +	TP_fast_assign(
> > +		__entry->func	=3D func;
> > +		__entry->csd	=3D csd;
> > +	),
> > +
> > +	TP_printk("function %ps, csd =3D %p", __entry->func, __entry->csd)
>=20
> To match the style of the other TPs, that should be:
>=20
>         TP_printk("func=3D%ps csd=3D%p", __entry->func, __entry->csd)
>=20

Done!


Thanks for reviewing!
Leo