Re: Question about the ipi_raise filter usage and output

From: Mark Rutland
Date: Mon Feb 05 2024 - 09:41:09 EST

[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@xxxxxxx> 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.