* Question about the ipi_raise filter usage and output
@ 2024-02-05 9:57 richard clark
2024-02-05 10:28 ` Mark Rutland
2024-02-05 10:38 ` Steven Rostedt
0 siblings, 2 replies; 11+ messages in thread
From: richard clark @ 2024-02-05 9:57 UTC (permalink / raw)
To: nico, Steven Rostedt, Mark Rutland, mhiramat
Cc: linux-arm-kernel, linux-trace-kernel, linux-kernel, richard clark
Hi guys,
With the ipi_raise event enabled and filtered with:
echo 'reason == "Function call interrupts"' > filter, then the 'cat
trace' output below messages:
...
insmod-3355 [010] ....1.. 24479.230381: ipi_raise:
target_mask=00000000,00000bff (Function call interrupts)
...
The above output is triggered by my kernel module where it will smp
cross call a remote function from cpu#10 to cpu#11, for the
'target_mask' value, what does the '00000000,00000bff' mean?
~~~~~~~~~~~~~~
Another question is for the filter, I'd like to catch the IPI only
happening on cpu#11 *AND* a remote function call, so how to write the
'target_cpus' in the filter expression?
I try to write below:
echo 'target_cpus == 11 && reason == "Function call interrupts"' >
events/ipi/ipi_raise/filter
But the 'cat trace' doesn't show anything about cpu#11 IPI info,
although both the /proc/interrupts and the smp_processor_id() in the
remote function shows there's IPI sent to the cpu#11.
Any suggestions?
Thank you!
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Question about the ipi_raise filter usage and output
2024-02-05 9:57 Question about the ipi_raise filter usage and output richard clark
@ 2024-02-05 10:28 ` Mark Rutland
2024-02-05 13:06 ` Steven Rostedt
2024-02-05 10:38 ` Steven Rostedt
1 sibling, 1 reply; 11+ messages in thread
From: Mark Rutland @ 2024-02-05 10:28 UTC (permalink / raw)
To: richard clark
Cc: nico, Steven Rostedt, mhiramat, linux-arm-kernel,
linux-trace-kernel, linux-kernel
On Mon, Feb 05, 2024 at 05:57:29PM +0800, richard clark wrote:
> Hi guys,
>
> With the ipi_raise event enabled and filtered with:
> echo 'reason == "Function call interrupts"' > filter, then the 'cat
> trace' output below messages:
> ...
> insmod-3355 [010] ....1.. 24479.230381: ipi_raise:
> target_mask=00000000,00000bff (Function call interrupts)
> ...
> The above output is triggered by my kernel module where it will smp
> cross call a remote function from cpu#10 to cpu#11, for the
> 'target_mask' value, what does the '00000000,00000bff' mean?
That's a cpumask bitmap: 0xbff is 0b1011_1111_1111, which is:
,- CPU 10
|
1011_1111_1111
| '__________'
| |
| `- CPUs 9 to 0
|
`- CPU 11
Note that bitmap has CPUs 0-9 and CPU 11 set, but CPU 10 is not set.
I suspect your kernel module has generated the bitmap incorrectly; it looks
like you have a mask for CPUs 0-11 minus a mask for CPU 10?
For CPUs 10 and 11, that should be 0xc00 / 0b1100_0000_0000.
> ~~~~~~~~~~~~~~
>
> Another question is for the filter, I'd like to catch the IPI only
> happening on cpu#11 *AND* a remote function call, so how to write the
> 'target_cpus' in the filter expression?
>
> I try to write below:
> echo 'target_cpus == 11 && reason == "Function call interrupts"' >
> events/ipi/ipi_raise/filter
The '=' checks if the target_cpus bitmap *only* contains CPU 11. If the cpumask
contains other CPUs, the filter will skip the call.
I believe you can use '&' to check whether a cpumask contains a CPU, e.g.
'target_cpus & 11'
Thanks,
Mark.
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Question about the ipi_raise filter usage and output
2024-02-05 9:57 Question about the ipi_raise filter usage and output richard clark
2024-02-05 10:28 ` Mark Rutland
@ 2024-02-05 10:38 ` Steven Rostedt
2024-02-06 2:47 ` richard clark
1 sibling, 1 reply; 11+ messages in thread
From: Steven Rostedt @ 2024-02-05 10:38 UTC (permalink / raw)
To: richard clark
Cc: nico, Mark Rutland, mhiramat, linux-arm-kernel,
linux-trace-kernel, linux-kernel
On Mon, 5 Feb 2024 17:57:29 +0800
richard clark <richard.xnu.clark@gmail.com> wrote:
> Hi guys,
>
> With the ipi_raise event enabled and filtered with:
> echo 'reason == "Function call interrupts"' > filter, then the 'cat
> trace' output below messages:
> ...
> insmod-3355 [010] ....1.. 24479.230381: ipi_raise:
> target_mask=00000000,00000bff (Function call interrupts)
> ...
> The above output is triggered by my kernel module where it will smp
> cross call a remote function from cpu#10 to cpu#11, for the
> 'target_mask' value, what does the '00000000,00000bff' mean?
> ~~~~~~~~~~~~~~
It's the CPU mask. bff is bits 101111111111 or CPUs = 0-9,11.
>
> Another question is for the filter, I'd like to catch the IPI only
> happening on cpu#11 *AND* a remote function call, so how to write the
> 'target_cpus' in the filter expression?
>
> I try to write below:
> echo 'target_cpus == 11 && reason == "Function call interrupts"' >
> events/ipi/ipi_raise/filter
You mean when it is sent only to CPU 11? Not when the event is
happening on CPU 11. Like the above example, the event was triggered on
CPU 10, but the mask was for all the other CPUs.
If you are looking for just CPU 11, you can do:
echo 'target_cpus == 0x800 && reason == "Function call interrupts"'
>
> But the 'cat trace' doesn't show anything about cpu#11 IPI info,
> although both the /proc/interrupts and the smp_processor_id() in the
> remote function shows there's IPI sent to the cpu#11.
>
-- Steve
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Question about the ipi_raise filter usage and output
2024-02-05 10:28 ` Mark Rutland
@ 2024-02-05 13:06 ` Steven Rostedt
2024-02-05 14:39 ` Mark Rutland
0 siblings, 1 reply; 11+ messages in thread
From: Steven Rostedt @ 2024-02-05 13:06 UTC (permalink / raw)
To: Mark Rutland
Cc: richard clark, nico, mhiramat, linux-arm-kernel,
linux-trace-kernel, linux-kernel
On Mon, 5 Feb 2024 10:28:57 +0000
Mark Rutland <mark.rutland@arm.com> wrote:
> > I try to write below:
> > echo 'target_cpus == 11 && reason == "Function call interrupts"' >
> > events/ipi/ipi_raise/filter
>
> The '=' checks if the target_cpus bitmap *only* contains CPU 11. If the cpumask
> contains other CPUs, the filter will skip the call.
>
> I believe you can use '&' to check whether a cpumask contains a CPU, e.g.
>
> 'target_cpus & 11'
11 == 0xb = b1011
So the above would only be true for CPUs 0,1 and 3 ;-)
I think you meant: 'target_cpus & 0x800'
I tried "1 << 11' but it appears to not allow shifts. I wonder if we should add that?
-- Steve
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Question about the ipi_raise filter usage and output
2024-02-05 13:06 ` Steven Rostedt
@ 2024-02-05 14:39 ` Mark Rutland
2024-02-05 16:05 ` Valentin Schneider
0 siblings, 1 reply; 11+ messages in thread
From: Mark Rutland @ 2024-02-05 14:39 UTC (permalink / raw)
To: Steven Rostedt
Cc: richard clark, nico, mhiramat, linux-arm-kernel,
linux-trace-kernel, linux-kernel, Valentin Schneider
[adding Valentin]
On Mon, Feb 05, 2024 at 08:06:09AM -0500, Steven Rostedt wrote:
> On Mon, 5 Feb 2024 10:28:57 +0000
> Mark Rutland <mark.rutland@arm.com> wrote:
>
> > > I try to write below:
> > > echo 'target_cpus == 11 && reason == "Function call interrupts"' >
> > > events/ipi/ipi_raise/filter
> >
> > The '=' checks if the target_cpus bitmap *only* contains CPU 11. If the cpumask
> > contains other CPUs, the filter will skip the call.
> >
> > I believe you can use '&' to check whether a cpumask contains a CPU, e.g.
> >
> > 'target_cpus & 11'
>
> 11 == 0xb = b1011
>
> So the above would only be true for CPUs 0,1 and 3 ;-)
Sorry, I misunderstood the scalar logic and thought that we treated:
'$mask $OP $scalar', e.g. 'target_cpus & 11'
... as a special case meaning a cpumask with that scalar bit set, i.e.
'$mask $OP CPUS{$scalar}', e.g. 'target_cpus & CPUS{11}'
... but evidently I was wrong.
> I think you meant: 'target_cpus & 0x800'
>
> I tried "1 << 11' but it appears to not allow shifts. I wonder if we should add that?
Hmm... shouldn't we make 'CPUS{11}' work for that?
From a quick test (below), that doesn't seem to work, though I think it
probably should?
# cat /sys/devices/system/cpu/online
0-3
# echo 1 > /sys/kernel/tracing/events/ipi/ipi_raise/enable
# echo 'target_cpus & CPUS{3}' > /sys/kernel/tracing/events/ipi/ipi_raise/filter
# grep IPI /proc/interrupts
IPI0: 54 41 32 42 Rescheduling interrupts
IPI1: 1202 1035 893 909 Function call interrupts
IPI2: 0 0 0 0 CPU stop interrupts
IPI3: 0 0 0 0 CPU stop (for crash dump) interrupts
IPI4: 0 0 0 0 Timer broadcast interrupts
IPI5: 0 0 0 0 IRQ work interrupts
# sleep 1
# grep IPI /proc/interrupts
IPI0: 54 42 32 42 Rescheduling interrupts
IPI1: 1209 1037 912 927 Function call interrupts
IPI2: 0 0 0 0 CPU stop interrupts
IPI3: 0 0 0 0 CPU stop (for crash dump) interrupts
IPI4: 0 0 0 0 Timer broadcast interrupts
IPI5: 0 0 0 0 IRQ work interrupts
# cat /sys/devices/system/cpu/online
0-3
# cat /sys/kernel/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 0/0 #P:4
#
# _-----=> irqs-off/BH-disabled
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> migrate-disable
# |||| / delay
# TASK-PID CPU# ||||| TIMESTAMP FUNCTION
# | | | ||||| | |
#
More confusingly, if I use '8', I get events with cpumasks which shouldn't
match AFAICT:
echo 'target_cpus & 8' > /sys/kernel/tracing/events/ipi/ipi_raise/filter
# echo '' > /sys/kernel/tracing/trace
# grep IPI /proc/interrupts
IPI0: 55 46 34 43 Rescheduling interrupts
IPI1: 1358 1155 994 1021 Function call interrupts
IPI2: 0 0 0 0 CPU stop interrupts
IPI3: 0 0 0 0 CPU stop (for crash dump) interrupts
IPI4: 0 0 0 0 Timer broadcast interrupts
IPI5: 0 0 0 0 IRQ work interrupts
# sleep 1
# grep IPI /proc/interrupts
IPI0: 56 46 34 43 Rescheduling interrupts
IPI1: 1366 1158 1005 1038 Function call interrupts
IPI2: 0 0 0 0 CPU stop interrupts
IPI3: 0 0 0 0 CPU stop (for crash dump) interrupts
IPI4: 0 0 0 0 Timer broadcast interrupts
IPI5: 0 0 0 0 IRQ work interrupts
# cat /sys/kernel/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 91/91 #P:4
#
# _-----=> irqs-off/BH-disabled
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> migrate-disable
# |||| / delay
# TASK-PID CPU# ||||| TIMESTAMP FUNCTION
# | | | ||||| | |
<idle>-0 [000] d.h4. 480.720312: ipi_raise: target_mask=00000000,00000004 (Function call interrupts)
kworker/u8:1-37 [002] d..3. 480.720763: ipi_raise: target_mask=00000000,00000008 (Function call interrupts)
sh-144 [003] d.h1. 480.721584: ipi_raise: target_mask=00000000,00000001 (Function call interrupts)
<idle>-0 [000] d.h4. 481.552179: ipi_raise: target_mask=00000000,00000004 (Function call interrupts)
kworker/u8:1-37 [002] d..3. 481.552742: ipi_raise: target_mask=00000000,00000008 (Function call interrupts)
<idle>-0 [000] dNs4. 481.553728: ipi_raise: target_mask=00000000,00000004 (Function call interrupts)
sh-144 [003] d.h1. 481.553742: ipi_raise: target_mask=00000000,00000002 (Function call interrupts)
<idle>-0 [000] d.h4. 481.730502: ipi_raise: target_mask=00000000,00000004 (Function call interrupts)
kworker/u8:1-37 [002] d..3. 481.730917: ipi_raise: target_mask=00000000,00000008 (Function call interrupts)
<idle>-0 [000] d.h4. 481.800820: ipi_raise: target_mask=00000000,00000004 (Function call interrupts)
kworker/u8:1-37 [002] d..3. 481.801249: ipi_raise: target_mask=00000000,00000008 (Function call interrupts)
kworker/u8:1-37 [002] d.h2. 481.801483: ipi_raise: target_mask=00000000,00000001 (Function call interrupts)
<idle>-0 [000] d.h4. 481.916178: ipi_raise: target_mask=00000000,00000004 (Function call interrupts)
kworker/u8:1-37 [002] d..3. 481.916610: ipi_raise: target_mask=00000000,00000008 (Function call interrupts)
sh-144 [003] d.h1. 481.917581: ipi_raise: target_mask=00000000,00000001 (Function call interrupts)
<idle>-0 [000] d.h4. 482.280864: ipi_raise: target_mask=00000000,00000004 (Function call interrupts)
kworker/u8:1-37 [002] d..3. 482.281310: ipi_raise: target_mask=00000000,00000008 (Function call interrupts)
kworker/u8:1-37 [002] d.h2. 482.281514: ipi_raise: target_mask=00000000,00000001 (Function call interrupts)
sh-144 [003] d.h1. 482.285681: ipi_raise: target_mask=00000000,00000001 (Function call interrupts)
sh-144 [003] d..2. 482.287634: ipi_raise: target_mask=00000000,00000001 (Rescheduling interrupts)
sh-144 [003] d.h1. 482.289705: ipi_raise: target_mask=00000000,00000002 (Function call interrupts)
grep-183 [000] d.h1. 482.293649: ipi_raise: target_mask=00000000,00000002 (Function call interrupts)
grep-183 [000] d.s3. 482.301758: ipi_raise: target_mask=00000000,00000008 (Function call interrupts)
grep-183 [000] d.h1. 482.325713: ipi_raise: target_mask=00000000,00000002 (Function call interrupts)
grep-183 [000] d..4. 482.349025: ipi_raise: target_mask=00000000,00000008 (Function call interrupts)
<idle>-0 [000] d.h4. 482.701197: ipi_raise: target_mask=00000000,00000004 (Function call interrupts)
kworker/u8:1-37 [002] d..3. 482.701856: ipi_raise: target_mask=00000000,00000008 (Function call interrupts)
<idle>-0 [000] d.h4. 482.921567: ipi_raise: target_mask=00000000,00000004 (Function call interrupts)
kworker/u8:1-37 [002] d..3. 482.921998: ipi_raise: target_mask=00000000,00000008 (Function call interrupts)
<idle>-0 [000] d.h4. 483.044683: ipi_raise: target_mask=00000000,00000004 (Function call interrupts)
kworker/u8:1-37 [002] d..3. 483.045123: ipi_raise: target_mask=00000000,00000008 (Function call interrupts)
<idle>-0 [000] d.h4. 483.154449: ipi_raise: target_mask=00000000,00000004 (Function call interrupts)
kworker/u8:1-37 [002] d..3. 483.154896: ipi_raise: target_mask=00000000,00000008 (Function call interrupts)
<idle>-0 [000] d.h4. 483.296925: ipi_raise: target_mask=00000000,00000004 (Function call interrupts)
kworker/u8:1-37 [002] d.h2. 483.297455: ipi_raise: target_mask=00000000,00000001 (Function call interrupts)
kworker/u8:1-37 [002] d..3. 483.297719: ipi_raise: target_mask=00000000,00000008 (Function call interrupts)
<idle>-0 [000] d.h4. 483.602777: ipi_raise: target_mask=00000000,00000004 (Function call interrupts)
Have I completely misunderstood how this is supposed to work, or is that a bug?
Mark.
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Question about the ipi_raise filter usage and output
2024-02-05 14:39 ` Mark Rutland
@ 2024-02-05 16:05 ` Valentin Schneider
2024-02-06 8:42 ` richard clark
0 siblings, 1 reply; 11+ messages in thread
From: Valentin Schneider @ 2024-02-05 16:05 UTC (permalink / raw)
To: Mark Rutland, Steven Rostedt
Cc: richard clark, nico, mhiramat, linux-arm-kernel,
linux-trace-kernel, linux-kernel
On 05/02/24 14:39, Mark Rutland wrote:
> [adding Valentin]
>
Thanks!
> On Mon, Feb 05, 2024 at 08:06:09AM -0500, Steven Rostedt wrote:
>> On Mon, 5 Feb 2024 10:28:57 +0000
>> Mark Rutland <mark.rutland@arm.com> wrote:
>>
>> > > I try to write below:
>> > > echo 'target_cpus == 11 && reason == "Function call interrupts"' >
>> > > events/ipi/ipi_raise/filter
>> >
>> > The '=' checks if the target_cpus bitmap *only* contains CPU 11. If the cpumask
>> > contains other CPUs, the filter will skip the call.
>> >
>> > I believe you can use '&' to check whether a cpumask contains a CPU, e.g.
>> >
>> > 'target_cpus & 11'
>>
>> 11 == 0xb = b1011
>>
>> So the above would only be true for CPUs 0,1 and 3 ;-)
>
> Sorry, I misunderstood the scalar logic and thought that we treated:
>
> '$mask $OP $scalar', e.g. 'target_cpus & 11'
>
> .. as a special case meaning a cpumask with that scalar bit set, i.e.
>
> '$mask $OP CPUS{$scalar}', e.g. 'target_cpus & CPUS{11}'
>
> .. but evidently I was wrong.
>
>> I think you meant: 'target_cpus & 0x800'
>>
>> I tried "1 << 11' but it appears to not allow shifts. I wonder if we should add that?
>
> Hmm... shouldn't we make 'CPUS{11}' work for that?
>
It /should/ already be the case, the user input with the curly braces is
parsed as a cpulist. So CPUS{11} really does mean CPU11, not a hex value to
be interpreted as a cpumask.
However...
> From a quick test (below), that doesn't seem to work, though I think it
> probably should?
> Have I completely misunderstood how this is supposed to work, or is that a bug?
>
The CPUS{} thingie only works with an event field that is either declared as a
cpumask (__cpumask) or a scalar. That's not the case for ipi_raise, the
target_cpus event field is saved as a "raw" bitmask.
There /should/ have been a warning about the event filter though, but I
think it's not happening because I'm allowing more than just FILTER_CPUMASK
in parse_pred() to make it work for scalars. I'll go poke around some more.
Generally for this sort of IPI investigation I'd recommend using the newer
trace_ipi_send_cpu() and trace_ipi_send_cpumask() (for which CPUS{}
filtering works).
If it's only the function call interrupts you're interesting in, have a
look at trace_csd_queue_cpu().
> Mark.
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Question about the ipi_raise filter usage and output
2024-02-05 10:38 ` Steven Rostedt
@ 2024-02-06 2:47 ` richard clark
0 siblings, 0 replies; 11+ messages in thread
From: richard clark @ 2024-02-06 2:47 UTC (permalink / raw)
To: Steven Rostedt
Cc: nico, Mark Rutland, mhiramat, linux-arm-kernel,
linux-trace-kernel, linux-kernel
Hi Steve,
On Mon, Feb 5, 2024 at 6:38 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Mon, 5 Feb 2024 17:57:29 +0800
> richard clark <richard.xnu.clark@gmail.com> wrote:
>
> > I try to write below:
> > echo 'target_cpus == 11 && reason == "Function call interrupts"' >
> > events/ipi/ipi_raise/filter
>
> You mean when it is sent only to CPU 11? Not when the event is
> happening on CPU 11. Like the above example, the event was triggered on
> CPU 10, but the mask was for all the other CPUs.
>
> If you are looking for just CPU 11, you can do:
>
> echo 'target_cpus == 0x800 && reason == "Function call interrupts"'
>
Seems both 'target_cpus == 0x800 && reason == "Function call
interrupts"' and 'target_cpus & 0x800 && reason == "Function call
interrupts"' don't work:
# cat events/ipi/ipi_raise/enable
1
# cat events/ipi/ipi_raise/filter
target_cpus == 0x800 && reason == "Function call interrupts"
The kernel module code snippet:
void ipi_func_run_cpu(void *info)
{
pr_info("remote function runs on cpu[%d].\n", smp_processor_id());
}
static int __init ipi_send_init(void)
{
int target = (smp_processor_id() + 1) % nr_cpu_ids;
int ret = smp_call_function_single(target, ipi_func_run_cpu,
NULL, true);
pr_info("ipi cpu[%d --> %d] ret = %d\n", smp_processor_id(),
target, ret);
return 0;
}
...
module_init(ipi_send_init);
module_exit(ipi_send_exit);
$ sudo taskset -c 10 insmod ipi_send.ko
$ dmesg
...
[84931.864273] remote function runs on cpu[11].
[84931.864282] ipi cpu[10 --> 11] ret = 0
The 'cat trace' will output the below message with 'reason ==
"Function call interrupts"' filter:
...
sudo-5726 [007] dn.h1.. 84302.833545: ipi_raise:
target_mask=00000000,00000001 (Function call interrupts)
sudo-5726 [007] dn.h2.. 84302.837544: ipi_raise:
target_mask=00000000,00000001 (Function call interrupts)
insmod-5727 [011] dn.h1.. 84302.841545: ipi_raise:
target_mask=00000000,00000001 (Function call interrupts)
insmod-5727 [010] ....1.. 84302.843966: ipi_raise:
target_mask=00000000,00000bff (Function call interrupts)
insmod-5727 [010] ....1.. 84302.843975: ipi_raise:
target_mask=00000000,00000bff (Function call interrupts)
insmod-5727 [010] ....1.. 84302.844184: ipi_raise:
target_mask=00000000,00000800 (Function call interrupts)
...
I find that 'target_cpus == 0xfff && reason == "Function call
interrupts"' doesn't have output in the buffer, but 'target_cpus &
0xfff && reason == "Function call interrupts"' does. I also tried to
use 'target_cpus & 0xf00 && reason == "Function call interrupts"' in
my case, the trace buffer has nothing after the kmod inserted.
Any comments?
>
>
> -- Steve
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Question about the ipi_raise filter usage and output
2024-02-05 16:05 ` Valentin Schneider
@ 2024-02-06 8:42 ` richard clark
2024-02-06 9:39 ` Valentin Schneider
0 siblings, 1 reply; 11+ messages in thread
From: richard clark @ 2024-02-06 8:42 UTC (permalink / raw)
To: Valentin Schneider
Cc: Mark Rutland, Steven Rostedt, nico, mhiramat, linux-arm-kernel,
linux-trace-kernel, linux-kernel
On Tue, Feb 6, 2024 at 12:05 AM Valentin Schneider <vschneid@redhat.com> wrote:
>
> On 05/02/24 14:39, Mark Rutland wrote:
> > [adding Valentin]
> >
>
> Thanks!
>
> > On Mon, Feb 05, 2024 at 08:06:09AM -0500, Steven Rostedt wrote:
> >> On Mon, 5 Feb 2024 10:28:57 +0000
> >> Mark Rutland <mark.rutland@arm.com> wrote:
> >>
> >> > > I try to write below:
> >> > > echo 'target_cpus == 11 && reason == "Function call interrupts"' >
> >> > > events/ipi/ipi_raise/filter
> >> >
> >> > The '=' checks if the target_cpus bitmap *only* contains CPU 11. If the cpumask
> >> > contains other CPUs, the filter will skip the call.
> >> >
> >> > I believe you can use '&' to check whether a cpumask contains a CPU, e.g.
> >> >
> >> > 'target_cpus & 11'
> >>
> >> 11 == 0xb = b1011
> >>
> >> So the above would only be true for CPUs 0,1 and 3 ;-)
> >
> > Sorry, I misunderstood the scalar logic and thought that we treated:
> >
> > '$mask $OP $scalar', e.g. 'target_cpus & 11'
> >
> > .. as a special case meaning a cpumask with that scalar bit set, i.e.
> >
> > '$mask $OP CPUS{$scalar}', e.g. 'target_cpus & CPUS{11}'
> >
> > .. but evidently I was wrong.
> >
> >> I think you meant: 'target_cpus & 0x800'
> >>
> >> I tried "1 << 11' but it appears to not allow shifts. I wonder if we should add that?
> >
> > Hmm... shouldn't we make 'CPUS{11}' work for that?
> >
>
> It /should/ already be the case, the user input with the curly braces is
> parsed as a cpulist. So CPUS{11} really does mean CPU11, not a hex value to
> be interpreted as a cpumask.
>
> However...
>
> > From a quick test (below), that doesn't seem to work, though I think it
> > probably should?
> > Have I completely misunderstood how this is supposed to work, or is that a bug?
> >
>
> The CPUS{} thingie only works with an event field that is either declared as a
> cpumask (__cpumask) or a scalar. That's not the case for ipi_raise, the
> target_cpus event field is saved as a "raw" bitmask.
>
> There /should/ have been a warning about the event filter though, but I
> think it's not happening because I'm allowing more than just FILTER_CPUMASK
> in parse_pred() to make it work for scalars. I'll go poke around some more.
>
> Generally for this sort of IPI investigation I'd recommend using the newer
> trace_ipi_send_cpu() and trace_ipi_send_cpumask() (for which CPUS{}
> filtering works).
> If it's only the function call interrupts you're interesting in, have a
> look at trace_csd_queue_cpu().
This should be supported by newer version kernels like v6.5, but I am
using v6.1 and this trace event has not been supported yet... so ipi
is more suitable for me. ipi_entry and ipi_exit is ok, but seems the
filter doesn't support a specific cpu, maybe we need to add this?
>
> > Mark.
>
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Question about the ipi_raise filter usage and output
2024-02-06 8:42 ` richard clark
@ 2024-02-06 9:39 ` Valentin Schneider
2024-02-07 2:28 ` richard clark
0 siblings, 1 reply; 11+ messages in thread
From: Valentin Schneider @ 2024-02-06 9:39 UTC (permalink / raw)
To: richard clark
Cc: Mark Rutland, Steven Rostedt, nico, mhiramat, linux-arm-kernel,
linux-trace-kernel, linux-kernel
On 06/02/24 16:42, richard clark wrote:
> On Tue, Feb 6, 2024 at 12:05 AM Valentin Schneider <vschneid@redhat.com> wrote:
>>
>> The CPUS{} thingie only works with an event field that is either declared as a
>> cpumask (__cpumask) or a scalar. That's not the case for ipi_raise, the
>> target_cpus event field is saved as a "raw" bitmask.
>>
>> There /should/ have been a warning about the event filter though, but I
>> think it's not happening because I'm allowing more than just FILTER_CPUMASK
>> in parse_pred() to make it work for scalars. I'll go poke around some more.
>>
>> Generally for this sort of IPI investigation I'd recommend using the newer
>> trace_ipi_send_cpu() and trace_ipi_send_cpumask() (for which CPUS{}
>> filtering works).
>> If it's only the function call interrupts you're interesting in, have a
>> look at trace_csd_queue_cpu().
>
> This should be supported by newer version kernels like v6.5, but I am
> using v6.1 and this trace event has not been supported yet... so ipi
> is more suitable for me. ipi_entry and ipi_exit is ok, but seems the
> filter doesn't support a specific cpu, maybe we need to add this?
>>
You should have access to the generic fields which include the CPU from
which the event happens. Any of "CPU", "cpu" or "common_cpu" would match
this.
So if you're on a recent enough kernel (v6.6 or above AFAICT), you should
be able to do something like so:
trace-cmd record -e 'ipi_raise' -f 'CPU & CPUS{7-42}' ./foo.sh
If you just want to match a single CPU, or are on an older kernel, this
should work as well:
trace-cmd record -e 'ipi_raise' -f 'CPU == 42' ./foo.sh
For example on a QEMU x86 environment:
# trace-cmd record -e 'call_function*' -f 'CPU & CPUS{3}' hackbench
Running in process mode with 10 groups using 40 file descriptors each (== 400 tasks)
Each sender will pass 100 messages of 100 bytes
Time: 0.396
CPU0 data recorded at offset=0x738000
0 bytes in size
CPU1 data recorded at offset=0x738000
0 bytes in size
CPU2 data recorded at offset=0x738000
0 bytes in size
CPU3 data recorded at offset=0x738000
4096 bytes in size
# trace-cmd report
CPU 0 is empty
CPU 1 is empty
CPU 2 is empty
cpus=4
<idle>-0 [003] 29.704387: call_function_single_entry: vector=251
<idle>-0 [003] 29.704388: call_function_single_exit: vector=251
<idle>-0 [003] 29.705950: call_function_single_entry: vector=251
<idle>-0 [003] 29.705951: call_function_single_exit: vector=251
<idle>-0 [003] 29.706462: call_function_single_entry: vector=251
<idle>-0 [003] 29.706463: call_function_single_exit: vector=251
hackbench-962 [003] 29.706501: call_function_single_entry: vector=251
hackbench-962 [003] 29.706502: call_function_single_exit: vector=251
hackbench-955 [003] 29.706521: call_function_single_entry: vector=251
hackbench-955 [003] 29.706522: call_function_single_exit: vector=251
<idle>-0 [003] 30.101812: call_function_single_entry: vector=251
<idle>-0 [003] 30.101814: call_function_single_exit: vector=251
<idle>-0 [003] 30.101897: call_function_single_entry: vector=251
<idle>-0 [003] 30.101898: call_function_single_exit: vector=251
<idle>-0 [003] 30.101985: call_function_single_entry: vector=251
<idle>-0 [003] 30.101986: call_function_single_exit: vector=251
<idle>-0 [003] 30.102072: call_function_single_entry: vector=251
<idle>-0 [003] 30.102072: call_function_single_exit: vector=251
<idle>-0 [003] 30.102161: call_function_single_entry: vector=251
<idle>-0 [003] 30.102161: call_function_single_exit: vector=251
<idle>-0 [003] 30.102250: call_function_single_entry: vector=251
<idle>-0 [003] 30.102251: call_function_single_exit: vector=251
<idle>-0 [003] 30.102372: call_function_single_entry: vector=251
<idle>-0 [003] 30.102372: call_function_single_exit: vector=251
CPU 0 is empty
CPU 1 is empty
CPU 2 is empty
cpus=4
<idle>-0 [003] 1067.718304: call_function_single_entry: vector=251
<idle>-0 [003] 1067.718309: call_function_single_exit: vector=251
and that behaves the same as
trace-cmd record -e 'call_function*' -f 'CPU == 3' hackbench
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Question about the ipi_raise filter usage and output
2024-02-06 9:39 ` Valentin Schneider
@ 2024-02-07 2:28 ` richard clark
2024-02-07 2:33 ` richard clark
0 siblings, 1 reply; 11+ messages in thread
From: richard clark @ 2024-02-07 2:28 UTC (permalink / raw)
To: Valentin Schneider
Cc: Mark Rutland, Steven Rostedt, nico, mhiramat, linux-arm-kernel,
linux-trace-kernel, linux-kernel
On Tue, Feb 6, 2024 at 5:39 PM Valentin Schneider <vschneid@redhat.com> wrote:
>
> You should have access to the generic fields which include the CPU from
> which the event happens. Any of "CPU", "cpu" or "common_cpu" would match
> this.
>
> So if you're on a recent enough kernel (v6.6 or above AFAICT), you should
> be able to do something like so:
>
> trace-cmd record -e 'ipi_raise' -f 'CPU & CPUS{7-42}' ./foo.sh
>
> If you just want to match a single CPU, or are on an older kernel, this
> should work as well:
>
> trace-cmd record -e 'ipi_raise' -f 'CPU == 42' ./foo.sh
>
> For example on a QEMU x86 environment:
>
> # trace-cmd record -e 'call_function*' -f 'CPU & CPUS{3}' hackbench
> Running in process mode with 10 groups using 40 file descriptors each (== 400 tasks)
> Each sender will pass 100 messages of 100 bytes
> Time: 0.396
> CPU0 data recorded at offset=0x738000
> 0 bytes in size
> CPU1 data recorded at offset=0x738000
> 0 bytes in size
> CPU2 data recorded at offset=0x738000
> 0 bytes in size
> CPU3 data recorded at offset=0x738000
> 4096 bytes in size
>
> # trace-cmd report
> CPU 0 is empty
> CPU 1 is empty
> CPU 2 is empty
> cpus=4
> <idle>-0 [003] 29.704387: call_function_single_entry: vector=251
> <idle>-0 [003] 29.704388: call_function_single_exit: vector=251
> <idle>-0 [003] 29.705950: call_function_single_entry: vector=251
> <idle>-0 [003] 29.705951: call_function_single_exit: vector=251
> <idle>-0 [003] 29.706462: call_function_single_entry: vector=251
> <idle>-0 [003] 29.706463: call_function_single_exit: vector=251
> hackbench-962 [003] 29.706501: call_function_single_entry: vector=251
> hackbench-962 [003] 29.706502: call_function_single_exit: vector=251
> hackbench-955 [003] 29.706521: call_function_single_entry: vector=251
> hackbench-955 [003] 29.706522: call_function_single_exit: vector=251
> <idle>-0 [003] 30.101812: call_function_single_entry: vector=251
> <idle>-0 [003] 30.101814: call_function_single_exit: vector=251
> <idle>-0 [003] 30.101897: call_function_single_entry: vector=251
> <idle>-0 [003] 30.101898: call_function_single_exit: vector=251
> <idle>-0 [003] 30.101985: call_function_single_entry: vector=251
> <idle>-0 [003] 30.101986: call_function_single_exit: vector=251
> <idle>-0 [003] 30.102072: call_function_single_entry: vector=251
> <idle>-0 [003] 30.102072: call_function_single_exit: vector=251
> <idle>-0 [003] 30.102161: call_function_single_entry: vector=251
> <idle>-0 [003] 30.102161: call_function_single_exit: vector=251
> <idle>-0 [003] 30.102250: call_function_single_entry: vector=251
> <idle>-0 [003] 30.102251: call_function_single_exit: vector=251
> <idle>-0 [003] 30.102372: call_function_single_entry: vector=251
> <idle>-0 [003] 30.102372: call_function_single_exit: vector=251
>
>
> CPU 0 is empty
> CPU 1 is empty
> CPU 2 is empty
> cpus=4
> <idle>-0 [003] 1067.718304: call_function_single_entry: vector=251
> <idle>-0 [003] 1067.718309: call_function_single_exit: vector=251
>
> and that behaves the same as
>
> trace-cmd record -e 'call_function*' -f 'CPU == 3' hackbench
>
Thanks, # trace-cmd record -e 'ipi' -f 'CPU==10 || CPU==11' -f
'reason=="Function call interrupts"' works:
CPU0 data recorded at offset=0x336000
0 bytes in size
CPU1 data recorded at offset=0x336000
0 bytes in size
CPU2 data recorded at offset=0x336000
0 bytes in size
CPU3 data recorded at offset=0x336000
0 bytes in size
CPU4 data recorded at offset=0x336000
0 bytes in size
CPU5 data recorded at offset=0x336000
0 bytes in size
CPU6 data recorded at offset=0x336000
0 bytes in size
CPU7 data recorded at offset=0x336000
0 bytes in size
CPU8 data recorded at offset=0x336000
0 bytes in size
CPU9 data recorded at offset=0x336000
0 bytes in size
CPU10 data recorded at offset=0x336000
4096 bytes in size
CPU11 data recorded at offset=0x337000
4096 bytes in size
# trace-cmd report
CPU 0 is empty
CPU 1 is empty
CPU 2 is empty
CPU 3 is empty
CPU 4 is empty
CPU 5 is empty
CPU 6 is empty
CPU 7 is empty
CPU 8 is empty
CPU 9 is empty
cpus=12
insmod-8519 [010] 170847.580062: ipi_raise:
target_mask=00000000,00000bff (Function call interrupts)
<idle>-0 [011] 170847.580070: ipi_entry:
(Function call interrupts)
<idle>-0 [011] 170847.580071: ipi_exit:
(Function call interrupts)
insmod-8519 [010] 170847.580078: ipi_raise:
target_mask=00000000,00000bff (Function call interrupts)
<idle>-0 [011] 170847.580080: ipi_entry:
(Function call interrupts)
<idle>-0 [011] 170847.580080: ipi_exit:
(Function call interrupts)
insmod-8519 [010] 170847.580282: ipi_raise:
target_mask=00000000,00000002 (Function call interrupts)
insmod-8519 [010] 170847.580329: ipi_raise:
target_mask=00000000,00000800 (Function call interrupts)
<idle>-0 [011] 170847.580331: ipi_entry:
(Function call interrupts)
<idle>-0 [011] 170847.580343: ipi_exit:
(Function call interrupts)
BTW: where does 12 come from in 'cpus=12' :-)
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Question about the ipi_raise filter usage and output
2024-02-07 2:28 ` richard clark
@ 2024-02-07 2:33 ` richard clark
0 siblings, 0 replies; 11+ messages in thread
From: richard clark @ 2024-02-07 2:33 UTC (permalink / raw)
To: Valentin Schneider
Cc: Mark Rutland, Steven Rostedt, nico, mhiramat, linux-arm-kernel,
linux-trace-kernel, linux-kernel
On Wed, Feb 7, 2024 at 10:28 AM richard clark
<richard.xnu.clark@gmail.com> wrote:
>
> On Tue, Feb 6, 2024 at 5:39 PM Valentin Schneider <vschneid@redhat.com> wrote:
> >
> > You should have access to the generic fields which include the CPU from
> > which the event happens. Any of "CPU", "cpu" or "common_cpu" would match
> > this.
> >
> > So if you're on a recent enough kernel (v6.6 or above AFAICT), you should
> > be able to do something like so:
> >
> > trace-cmd record -e 'ipi_raise' -f 'CPU & CPUS{7-42}' ./foo.sh
> >
> > If you just want to match a single CPU, or are on an older kernel, this
> > should work as well:
> >
> > trace-cmd record -e 'ipi_raise' -f 'CPU == 42' ./foo.sh
> >
> > For example on a QEMU x86 environment:
> >
> > # trace-cmd record -e 'call_function*' -f 'CPU & CPUS{3}' hackbench
> > Running in process mode with 10 groups using 40 file descriptors each (== 400 tasks)
> > Each sender will pass 100 messages of 100 bytes
> > Time: 0.396
> > CPU0 data recorded at offset=0x738000
> > 0 bytes in size
> > CPU1 data recorded at offset=0x738000
> > 0 bytes in size
> > CPU2 data recorded at offset=0x738000
> > 0 bytes in size
> > CPU3 data recorded at offset=0x738000
> > 4096 bytes in size
> >
> > # trace-cmd report
> > CPU 0 is empty
> > CPU 1 is empty
> > CPU 2 is empty
> > cpus=4
> > <idle>-0 [003] 29.704387: call_function_single_entry: vector=251
> > <idle>-0 [003] 29.704388: call_function_single_exit: vector=251
> > <idle>-0 [003] 29.705950: call_function_single_entry: vector=251
> > <idle>-0 [003] 29.705951: call_function_single_exit: vector=251
> > <idle>-0 [003] 29.706462: call_function_single_entry: vector=251
> > <idle>-0 [003] 29.706463: call_function_single_exit: vector=251
> > hackbench-962 [003] 29.706501: call_function_single_entry: vector=251
> > hackbench-962 [003] 29.706502: call_function_single_exit: vector=251
> > hackbench-955 [003] 29.706521: call_function_single_entry: vector=251
> > hackbench-955 [003] 29.706522: call_function_single_exit: vector=251
> > <idle>-0 [003] 30.101812: call_function_single_entry: vector=251
> > <idle>-0 [003] 30.101814: call_function_single_exit: vector=251
> > <idle>-0 [003] 30.101897: call_function_single_entry: vector=251
> > <idle>-0 [003] 30.101898: call_function_single_exit: vector=251
> > <idle>-0 [003] 30.101985: call_function_single_entry: vector=251
> > <idle>-0 [003] 30.101986: call_function_single_exit: vector=251
> > <idle>-0 [003] 30.102072: call_function_single_entry: vector=251
> > <idle>-0 [003] 30.102072: call_function_single_exit: vector=251
> > <idle>-0 [003] 30.102161: call_function_single_entry: vector=251
> > <idle>-0 [003] 30.102161: call_function_single_exit: vector=251
> > <idle>-0 [003] 30.102250: call_function_single_entry: vector=251
> > <idle>-0 [003] 30.102251: call_function_single_exit: vector=251
> > <idle>-0 [003] 30.102372: call_function_single_entry: vector=251
> > <idle>-0 [003] 30.102372: call_function_single_exit: vector=251
> >
> >
> > CPU 0 is empty
> > CPU 1 is empty
> > CPU 2 is empty
> > cpus=4
> > <idle>-0 [003] 1067.718304: call_function_single_entry: vector=251
> > <idle>-0 [003] 1067.718309: call_function_single_exit: vector=251
> >
> > and that behaves the same as
> >
> > trace-cmd record -e 'call_function*' -f 'CPU == 3' hackbench
> >
> Thanks, # trace-cmd record -e 'ipi' -f 'CPU==10 || CPU==11' -f
> 'reason=="Function call interrupts"' works:
> CPU0 data recorded at offset=0x336000
> 0 bytes in size
> CPU1 data recorded at offset=0x336000
> 0 bytes in size
> CPU2 data recorded at offset=0x336000
> 0 bytes in size
> CPU3 data recorded at offset=0x336000
> 0 bytes in size
> CPU4 data recorded at offset=0x336000
> 0 bytes in size
> CPU5 data recorded at offset=0x336000
> 0 bytes in size
> CPU6 data recorded at offset=0x336000
> 0 bytes in size
> CPU7 data recorded at offset=0x336000
> 0 bytes in size
> CPU8 data recorded at offset=0x336000
> 0 bytes in size
> CPU9 data recorded at offset=0x336000
> 0 bytes in size
> CPU10 data recorded at offset=0x336000
> 4096 bytes in size
> CPU11 data recorded at offset=0x337000
> 4096 bytes in size
>
> # trace-cmd report
> CPU 0 is empty
> CPU 1 is empty
> CPU 2 is empty
> CPU 3 is empty
> CPU 4 is empty
> CPU 5 is empty
> CPU 6 is empty
> CPU 7 is empty
> CPU 8 is empty
> CPU 9 is empty
> cpus=12
> insmod-8519 [010] 170847.580062: ipi_raise:
> target_mask=00000000,00000bff (Function call interrupts)
> <idle>-0 [011] 170847.580070: ipi_entry:
> (Function call interrupts)
> <idle>-0 [011] 170847.580071: ipi_exit:
> (Function call interrupts)
> insmod-8519 [010] 170847.580078: ipi_raise:
> target_mask=00000000,00000bff (Function call interrupts)
> <idle>-0 [011] 170847.580080: ipi_entry:
> (Function call interrupts)
> <idle>-0 [011] 170847.580080: ipi_exit:
> (Function call interrupts)
> insmod-8519 [010] 170847.580282: ipi_raise:
> target_mask=00000000,00000002 (Function call interrupts)
> insmod-8519 [010] 170847.580329: ipi_raise:
> target_mask=00000000,00000800 (Function call interrupts)
> <idle>-0 [011] 170847.580331: ipi_entry:
> (Function call interrupts)
> <idle>-0 [011] 170847.580343: ipi_exit:
> (Function call interrupts)
>
> BTW: where does 12 come from in 'cpus=12' :-)
Hmmm, please ignore the BTW, it should be the cpu total number in the system...
^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2024-02-07 2:33 UTC | newest]
Thread overview: 11+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2024-02-05 9:57 Question about the ipi_raise filter usage and output richard clark
2024-02-05 10:28 ` Mark Rutland
2024-02-05 13:06 ` Steven Rostedt
2024-02-05 14:39 ` Mark Rutland
2024-02-05 16:05 ` Valentin Schneider
2024-02-06 8:42 ` richard clark
2024-02-06 9:39 ` Valentin Schneider
2024-02-07 2:28 ` richard clark
2024-02-07 2:33 ` richard clark
2024-02-05 10:38 ` Steven Rostedt
2024-02-06 2:47 ` richard clark
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).