Re: [PATCH 10/48] perf tools: Introduce bpf-output event

[Arnaldo Carvalho de Melo]

Em Mon, Feb 22, 2016 at 09:10:37AM +0000, Wang Nan escreveu:
> Commit a43eec304259a6c637f4014a6d4767159b6a3aa3 (bpf: introduce
> bpf_perf_event_output() helper) add a helper to enable BPF program
> output data to perf ring buffer through a new type of perf event
> PERF_COUNT_SW_BPF_OUTPUT. This patch enable perf to create perf
> event of that type. Now perf user can use following cmdline to
> receive output data from BPF programs:
> 
>  # ./perf record -a -e bpf-output/no-inherit,name=evt/ \
>                     -e ./test_bpf_output.c/map:channel.event=evt/ ls /
>  # ./perf script
>             perf  1560 [004] 347747.086295:                       evt:  ffffffff811fd201 sys_write ...
>             perf  1560 [004] 347747.086300:                       evt:  ffffffff811fd201 sys_write ...
>             perf  1560 [004] 347747.086315:                       evt:  ffffffff811fd201 sys_write ...
>             ...
> 
> Test result:
>  # cat ./test_bpf_output.c
>  /************************ BEGIN **************************/
>  #include <uapi/linux/bpf.h>
>  struct bpf_map_def {
>  	unsigned int type;
>  	unsigned int key_size;
>  	unsigned int value_size;
>  	unsigned int max_entries;
>  };
> 
>  #define SEC(NAME) __attribute__((section(NAME), used))
>  static u64 (*ktime_get_ns)(void) =
>  	(void *)BPF_FUNC_ktime_get_ns;
>  static int (*trace_printk)(const char *fmt, int fmt_size, ...) =
>  	(void *)BPF_FUNC_trace_printk;
>  static int (*get_smp_processor_id)(void) =
>  	(void *)BPF_FUNC_get_smp_processor_id;
>  static int (*perf_event_output)(void *, struct bpf_map_def *, int, void *, unsigned long) =
>  	(void *)BPF_FUNC_perf_event_output;
> 
>  struct bpf_map_def SEC("maps") channel = {
>  	.type = BPF_MAP_TYPE_PERF_EVENT_ARRAY,
>  	.key_size = sizeof(int),
>  	.value_size = sizeof(u32),
>  	.max_entries = __NR_CPUS__,
>  };
> 
>  SEC("func_write=sys_write")
>  int func_write(void *ctx)
>  {
>  	struct {
>  		u64 ktime;
>  		int cpuid;
>  	} __attribute__((packed)) output_data;
>  	char error_data[] = "Error: failed to output: %d\n";
> 
>  	output_data.cpuid = get_smp_processor_id();
>  	output_data.ktime = ktime_get_ns();
>  	int err = perf_event_output(ctx, &channel, get_smp_processor_id(),
>  				    &output_data, sizeof(output_data));
>  	if (err)
>  		trace_printk(error_data, sizeof(error_data), err);
>  	return 0;
>  }
>  char _license[] SEC("license") = "GPL";
>  int _version SEC("version") = LINUX_VERSION_CODE;
>  /************************ END ***************************/
> 
>  # ./perf record -a -e bpf-output/no-inherit,name=evt/ \
>                     -e ./test_bpf_output.c/map:channel.event=evt/ ls /
>  # ./perf script | grep ls
>           ls  2242 [003] 347851.557563:                       evt:  ffffffff811fd201 sys_write ...
>           ls  2242 [003] 347851.557571:                       evt:  ffffffff811fd201 sys_write ...

So, there is something strange here:

        if (unlikely(event->oncpu != smp_processor_id()))
                return -EOPNOTSUPP;

This is where I am hitting, with:

[acme@jouet linux]$ uname -r
4.5.0-rc4

        int err = perf_event_output(ctx, &channel, get_smp_processor_id(),
                                    &output_data, sizeof(output_data));
        if (err)
                trace_printk(error_data, sizeof(error_data), err);

And then:

[root@jouet bpf]# tail /sys/kernel/debug/tracing/trace
            perf-13040 [003] d... 12062.807729: : Error: failed to output: -95
            perf-13040 [003] d... 12062.807731: : Error: failed to output: -95
            perf-13040 [003] d... 12062.807732: : Error: failed to output: -95
            perf-13040 [003] d... 12062.807735: : Error: failed to output: -95
            perf-13040 [003] d... 12062.807737: : Error: failed to output: -95
            perf-13040 [003] d... 12062.807744: : Error: failed to output: -95
 gnome-terminal--3091  [001] d... 12062.807773: : Error: failed to output: -95
 gnome-terminal--3091  [001] d... 12062.807784: : Error: failed to output: -95
           gmain-2830  [002] d... 12062.811791: : Error: failed to output: -95
           gmain-2830  [002] d... 12062.811810: : Error: failed to output: -95
[root@jouet bpf]# 

Ideas? AFK for a while, will continue investigating.

This already was submitted to Ingo, BTW.

I used, as in the changeset comment tests:

perf record -a -e bpf-output/no-inherit,name=evt/ -e ./test_bpf_output.c/map:channel.event=evt/ ls /

And perf script told me:

[root@jouet bpf]# perf script | tail
    perf 13040 [003] 12062.708337:  evt:  ffffffff81234eb1 sys_write (/lib/modules/4.5.0-rc4/build/vmlinux)
    perf 13040 [003] 12062.708339:  evt:  ffffffff81234eb1 sys_write (/lib/modules/4.5.0-rc4/build/vmlinux)
    perf 13040 [003] 12062.708340:  evt:  ffffffff81234eb1 sys_write (/lib/modules/4.5.0-rc4/build/vmlinux)
    perf 13040 [003] 12062.708341:  evt:  ffffffff81234eb1 sys_write (/lib/modules/4.5.0-rc4/build/vmlinux)
    perf 13040 [003] 12062.708343:  evt:  ffffffff81234eb1 sys_write (/lib/modules/4.5.0-rc4/build/vmlinux)
    perf 13040 [003] 12062.708344:  evt:  ffffffff81234eb1 sys_write (/lib/modules/4.5.0-rc4/build/vmlinux)
    perf 13040 [003] 12062.708346:  evt:  ffffffff81234eb1 sys_write (/lib/modules/4.5.0-rc4/build/vmlinux)
    perf 13040 [003] 12062.708347:  evt:  ffffffff81234eb1 sys_write (/lib/modules/4.5.0-rc4/build/vmlinux)
    perf 13040 [003] 12062.708348:  evt:  ffffffff81234eb1 sys_write (/lib/modules/4.5.0-rc4/build/vmlinux)
    perf 13040 [003] 12062.708350:  evt:  ffffffff81234eb1 sys_write (/lib/modules/4.5.0-rc4/build/vmlinux)
[root@jouet bpf]#

Wonder where that /lib/modules/4.5.0-rc4/build/vmlinux came from...

[root@jouet bpf]# perf script | cut -d'(' -f2 | sort | uniq -c
   1141 /lib/modules/4.5.0-rc4/build/vmlinux)

- Arnaldo