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 CSD
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:
$ echo 'hist:keys=cpu,csd.hex:ts=common_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=common_cpu,csd.hex:'\
'time=common_timestamp.usecs-$ts:'\
'onmatch(smp.csd_queue_cpu).trace(csd_latency,common_cpu,csd,$time)' >\
/sys/kernel/tracing/events/smp/csd_function_entry/trigger
$ trace-cmd record -e 'synthetic:csd_latency' hackbench
$ trace-cmd report
<...>-467 [001] 21.824263: csd_queue_cpu: cpu=0 callsite=try_to_wake_up+0x2ea func=sched_ttwu_pending csd=0xffff8880076148b8
<...>-467 [001] 21.824280: ipi_send_cpu: cpu=0 callsite=try_to_wake_up+0x2ea callback=generic_smp_call_function_single_interrupt+0x0
<...>-489 [000] 21.824299: csd_function_entry: func=sched_ttwu_pending csd=0xffff8880076148b8
<...>-489 [000] 21.824320: csd_latency: dst_cpu=0, csd=18446612682193848504, time=36
Suggested-by: Valentin Schneider <[email protected]>
Signed-off-by: Leonardo Bras <[email protected]>
---
include/trace/events/csd.h | 27 +++++++++++++++++++++++++++
kernel/smp.c | 16 +++++-----------
2 files changed, 32 insertions(+), 11 deletions(-)
diff --git a/include/trace/events/csd.h b/include/trace/events/csd.h
index af1df5200ae6..67e9d01f80c2 100644
--- a/include/trace/events/csd.h
+++ b/include/trace/events/csd.h
@@ -7,6 +7,33 @@
#include <linux/tracepoint.h>
+TRACE_EVENT(csd_queue_cpu,
+
+ TP_PROTO(const unsigned int cpu,
+ unsigned long callsite,
+ smp_call_func_t func,
+ struct __call_single_data *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 = cpu;
+ __entry->callsite = (void *)callsite;
+ __entry->func = func;
+ __entry->csd = csd;
+ ),
+
+ TP_printk("cpu=%u callsite=%pS func=%ps csd=%p",
+ __entry->cpu, __entry->callsite, __entry->func, __entry->csd)
+ );
+
/*
* Tracepoints for a function which is called as an effect of smp_call_function.*
*/
diff --git a/kernel/smp.c b/kernel/smp.c
index 7199b5a22043..692dbb400701 100644
--- a/kernel/smp.c
+++ b/kernel/smp.c
@@ -340,7 +340,7 @@ void __smp_call_single_queue(int cpu, struct llist_node *node)
* even if we haven't sent the smp_call IPI yet (e.g. the stopper
* executes migration_cpu_stop() on the remote CPU).
*/
- if (trace_ipi_send_cpu_enabled()) {
+ if (trace_csd_queue_cpu_enabled()) {
call_single_data_t *csd;
smp_call_func_t func;
@@ -348,7 +348,7 @@ void __smp_call_single_queue(int cpu, struct llist_node *node)
func = CSD_TYPE(csd) == CSD_TYPE_TTWU ?
sched_ttwu_pending : csd->func;
- trace_ipi_send_cpu(cpu, _RET_IP_, func);
+ trace_csd_queue_cpu(cpu, _RET_IP_, func, csd);
}
/*
@@ -741,7 +741,7 @@ static void smp_call_function_many_cond(const struct cpumask *mask,
int cpu, last_cpu, this_cpu = smp_processor_id();
struct call_function_data *cfd;
bool wait = scf_flags & SCF_WAIT;
- int nr_cpus = 0, nr_queued = 0;
+ int nr_cpus = 0;
bool run_remote = false;
bool run_local = false;
@@ -799,21 +799,15 @@ static void smp_call_function_many_cond(const struct cpumask *mask,
csd->node.src = smp_processor_id();
csd->node.dst = cpu;
#endif
+ trace_csd_queue_cpu(cpu, _RET_IP_, func, csd);
+
if (llist_add(&csd->node.llist, &per_cpu(call_single_queue, cpu))) {
__cpumask_set_cpu(cpu, cfd->cpumask_ipi);
nr_cpus++;
last_cpu = cpu;
}
- nr_queued++;
}
- /*
- * Trace each smp_function_call_*() as an IPI, actual IPIs
- * will be traced with func==generic_smp_call_function_single_ipi().
- */
- if (nr_queued)
- trace_ipi_send_cpumask(cfd->cpumask, _RET_IP_, func);
-
/*
* Choose the most efficient way to send an IPI. Note that the
* number of CPUs might be zero due to concurrent changes to the
--
2.41.0
On 15/06/23 03:59, Leonardo Bras wrote:
> 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 CSD
> 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:
>
> $ echo 'hist:keys=cpu,csd.hex:ts=common_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=common_cpu,csd.hex:'\
> 'time=common_timestamp.usecs-$ts:'\
> 'onmatch(smp.csd_queue_cpu).trace(csd_latency,common_cpu,csd,$time)' >\
> /sys/kernel/tracing/events/smp/csd_function_entry/trigger
>
> $ trace-cmd record -e 'synthetic:csd_latency' hackbench
> $ trace-cmd report
> <...>-467 [001] 21.824263: csd_queue_cpu: cpu=0 callsite=try_to_wake_up+0x2ea func=sched_ttwu_pending csd=0xffff8880076148b8
> <...>-467 [001] 21.824280: ipi_send_cpu: cpu=0 callsite=try_to_wake_up+0x2ea callback=generic_smp_call_function_single_interrupt+0x0
> <...>-489 [000] 21.824299: csd_function_entry: func=sched_ttwu_pending csd=0xffff8880076148b8
> <...>-489 [000] 21.824320: csd_latency: dst_cpu=0, csd=18446612682193848504, time=36
>
Nit: these commands now need a s/smp/csd/.
I played with those a little more and found out how to record the src CPU,
so feel free to update the changelog with this:
$ echo 'hist:keys=cpu,csd.hex:ts=common_timestamp.usecs:src=common_cpu' >\
/sys/kernel/tracing/events/csd/csd_queue_cpu/trigger
$ echo 'csd_latency unsigned int src_cpu; '\
'unsigned int dst_cpu; '\
'unsigned long csd; u64 time' >\
/sys/kernel/tracing/synthetic_events
$ echo 'hist:keys=common_cpu,csd.hex:
time=common_timestamp.usecs-$ts:
onmatch(csd.csd_queue_cpu).trace(csd_latency,$src,common_cpu,csd,$time)' >\
/sys/kernel/tracing/events/csd/csd_function_entry/trigger
$ trace-cmd record -e 'synthetic:csd_latency' hackbench
$ trace-cmd report
<idle>-0 [001] 115.236810: csd_latency: src_cpu=7, dst_cpu=1, csd=18446612682588476192, time=134
<idle>-0 [000] 115.240676: csd_latency: src_cpu=7, dst_cpu=0, csd=18446612682588214048, time=103
<idle>-0 [009] 115.241320: csd_latency: src_cpu=7, dst_cpu=9, csd=18446612682143963384, time=83
<idle>-0 [007] 115.242817: csd_latency: src_cpu=8, dst_cpu=7, csd=18446612682150759032, time=93
<idle>-0 [005] 115.247802: csd_latency: src_cpu=7, dst_cpu=5, csd=18446612682144441144, time=114
<idle>-0 [005] 115.271775: csd_latency: src_cpu=7, dst_cpu=5, csd=18446612682144441144, time=151
<idle>-0 [000] 115.279620: csd_latency: src_cpu=7, dst_cpu=0, csd=18446612682588214048, time=87
<idle>-0 [000] 115.281727: csd_latency: src_cpu=7, dst_cpu=0, csd=18446612682588214048, time=101
> Suggested-by: Valentin Schneider <[email protected]>
> Signed-off-by: Leonardo Bras <[email protected]>
Other than that:
Tested-and-reviewed-by: Valentin Schneider <[email protected]>
The following commit has been merged into the smp/core branch of tip:
Commit-ID: bf5a8c26ad7caf0772a1cd48c8a0924e48bdbaf0
Gitweb: https://git.kernel.org/tip/bf5a8c26ad7caf0772a1cd48c8a0924e48bdbaf0
Author: Leonardo Bras <[email protected]>
AuthorDate: Thu, 15 Jun 2023 03:59:47 -03:00
Committer: Peter Zijlstra <[email protected]>
CommitterDate: Fri, 16 Jun 2023 22:08:09 +02:00
trace,smp: Add tracepoints for scheduling remotelly called functions
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 CSD
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:
$ echo 'hist:keys=cpu,csd.hex:ts=common_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=common_cpu,csd.hex:'\
'time=common_timestamp.usecs-$ts:'\
'onmatch(smp.csd_queue_cpu).trace(csd_latency,common_cpu,csd,$time)' >\
/sys/kernel/tracing/events/smp/csd_function_entry/trigger
$ trace-cmd record -e 'synthetic:csd_latency' hackbench
$ trace-cmd report
<...>-467 [001] 21.824263: csd_queue_cpu: cpu=0 callsite=try_to_wake_up+0x2ea func=sched_ttwu_pending csd=0xffff8880076148b8
<...>-467 [001] 21.824280: ipi_send_cpu: cpu=0 callsite=try_to_wake_up+0x2ea callback=generic_smp_call_function_single_interrupt+0x0
<...>-489 [000] 21.824299: csd_function_entry: func=sched_ttwu_pending csd=0xffff8880076148b8
<...>-489 [000] 21.824320: csd_latency: dst_cpu=0, csd=18446612682193848504, time=36
Suggested-by: Valentin Schneider <[email protected]>
Signed-off-by: Leonardo Bras <[email protected]>
Tested-and-reviewed-by: Valentin Schneider <[email protected]>
Signed-off-by: Peter Zijlstra (Intel) <[email protected]>
Link: https://lore.kernel.org/r/[email protected]
---
include/trace/events/csd.h | 27 +++++++++++++++++++++++++++
kernel/smp.c | 16 +++++-----------
2 files changed, 32 insertions(+), 11 deletions(-)
diff --git a/include/trace/events/csd.h b/include/trace/events/csd.h
index af1df52..67e9d01 100644
--- a/include/trace/events/csd.h
+++ b/include/trace/events/csd.h
@@ -7,6 +7,33 @@
#include <linux/tracepoint.h>
+TRACE_EVENT(csd_queue_cpu,
+
+ TP_PROTO(const unsigned int cpu,
+ unsigned long callsite,
+ smp_call_func_t func,
+ struct __call_single_data *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 = cpu;
+ __entry->callsite = (void *)callsite;
+ __entry->func = func;
+ __entry->csd = csd;
+ ),
+
+ TP_printk("cpu=%u callsite=%pS func=%ps csd=%p",
+ __entry->cpu, __entry->callsite, __entry->func, __entry->csd)
+ );
+
/*
* Tracepoints for a function which is called as an effect of smp_call_function.*
*/
diff --git a/kernel/smp.c b/kernel/smp.c
index 1fa01a8..385179d 100644
--- a/kernel/smp.c
+++ b/kernel/smp.c
@@ -340,7 +340,7 @@ void __smp_call_single_queue(int cpu, struct llist_node *node)
* even if we haven't sent the smp_call IPI yet (e.g. the stopper
* executes migration_cpu_stop() on the remote CPU).
*/
- if (trace_ipi_send_cpu_enabled()) {
+ if (trace_csd_queue_cpu_enabled()) {
call_single_data_t *csd;
smp_call_func_t func;
@@ -348,7 +348,7 @@ void __smp_call_single_queue(int cpu, struct llist_node *node)
func = CSD_TYPE(csd) == CSD_TYPE_TTWU ?
sched_ttwu_pending : csd->func;
- trace_ipi_send_cpu(cpu, _RET_IP_, func);
+ trace_csd_queue_cpu(cpu, _RET_IP_, func, csd);
}
/*
@@ -741,7 +741,7 @@ static void smp_call_function_many_cond(const struct cpumask *mask,
int cpu, last_cpu, this_cpu = smp_processor_id();
struct call_function_data *cfd;
bool wait = scf_flags & SCF_WAIT;
- int nr_cpus = 0, nr_queued = 0;
+ int nr_cpus = 0;
bool run_remote = false;
bool run_local = false;
@@ -799,22 +799,16 @@ static void smp_call_function_many_cond(const struct cpumask *mask,
csd->node.src = smp_processor_id();
csd->node.dst = cpu;
#endif
+ trace_csd_queue_cpu(cpu, _RET_IP_, func, csd);
+
if (llist_add(&csd->node.llist, &per_cpu(call_single_queue, cpu))) {
__cpumask_set_cpu(cpu, cfd->cpumask_ipi);
nr_cpus++;
last_cpu = cpu;
}
- nr_queued++;
}
/*
- * Trace each smp_function_call_*() as an IPI, actual IPIs
- * will be traced with func==generic_smp_call_function_single_ipi().
- */
- if (nr_queued)
- trace_ipi_send_cpumask(cfd->cpumask, _RET_IP_, func);
-
- /*
* Choose the most efficient way to send an IPI. Note that the
* number of CPUs might be zero due to concurrent changes to the
* provided mask.