* 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! _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel ^ 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. _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel ^ 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 _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel ^ 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. _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel ^ 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. _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel ^ 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. > _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel ^ 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 _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel ^ 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' :-) _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel ^ 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... _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel ^ 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 _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel ^ 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 _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel ^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2024-02-07 2:34 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