Question about the ipi_raise filter usage and output

[richard clark]

On Tue, Feb 6, 2024 at 5:39 PM Valentin Schneider <vschneid at 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' :-)