diff mbox series

[v9,perf,bpf,09/15] perf, bpf: save btf information as headers to perf.data

Message ID 20190312053051.2690567-10-songliubraving@fb.com
State Awaiting Upstream
Delegated to: BPF Maintainers
Headers show
Series perf annotation of BPF programs | expand

Commit Message

Song Liu March 12, 2019, 5:30 a.m. UTC 
This patch enables perf-record to save btf information as headers to
perf.data A new header type HEADER_BPF_BTF is introduced for this data.

Signed-off-by: Song Liu <songliubraving@fb.com>
---
 tools/perf/util/header.c | 101 ++++++++++++++++++++++++++++++++++++++-
 tools/perf/util/header.h |   1 +
 2 files changed, 101 insertions(+), 1 deletion(-)

Comments

Arnaldo Carvalho de Melo March 12, 2019, 3:14 p.m. UTC | #1 
Em Mon, Mar 11, 2019 at 10:30:45PM -0700, Song Liu escreveu:
> This patch enables perf-record to save btf information as headers to
> perf.data A new header type HEADER_BPF_BTF is introduced for this data.
> 
> Signed-off-by: Song Liu <songliubraving@fb.com>
> ---
>  tools/perf/util/header.c | 101 ++++++++++++++++++++++++++++++++++++++-
>  tools/perf/util/header.h |   1 +
>  2 files changed, 101 insertions(+), 1 deletion(-)
> 
> diff --git a/tools/perf/util/header.c b/tools/perf/util/header.c
> index a4ef8f657ad0..7decd2d1dbda 100644
> --- a/tools/perf/util/header.c
> +++ b/tools/perf/util/header.c
> @@ -905,6 +905,39 @@ static int write_bpf_prog_info(struct feat_fd *ff,
>  	return ret;
>  }
>  
> +static int write_bpf_btf(struct feat_fd *ff,
> +			 struct perf_evlist *evlist __maybe_unused)
> +{
> +	struct perf_env *env = &ff->ph->env;
> +	struct rb_root *root;
> +	struct rb_node *next;
> +	int ret;
> +
> +	down_read(&env->bpf_progs.lock);
> +
> +	ret = do_write(ff, &env->bpf_progs.btfs_cnt,
> +		       sizeof(env->bpf_progs.btfs_cnt));
> +
> +	if (ret < 0)
> +		goto out;
> +
> +	root = &env->bpf_progs.btfs;
> +	next = rb_first(root);
> +	while (next) {
> +		struct btf_node *node;
> +
> +		node = rb_entry(next, struct btf_node, rb_node);
> +		next = rb_next(&node->rb_node);
> +		ret = do_write(ff, &node->id,
> +			       sizeof(u32) * 2 + node->data_size);
> +		if (ret < 0)
> +			goto out;
> +	}
> +out:
> +	up_read(&env->bpf_progs.lock);
> +	return ret;
> +}
> +
>  static int cpu_cache_level__sort(const void *a, const void *b)
>  {
>  	struct cpu_cache_level *cache_a = (struct cpu_cache_level *)a;
> @@ -1408,6 +1441,28 @@ static void print_bpf_prog_info(struct feat_fd *ff, FILE *fp)
>  	up_read(&env->bpf_progs.lock);
>  }
>  
> +static void print_bpf_btf(struct feat_fd *ff, FILE *fp)
> +{
> +	struct perf_env *env = &ff->ph->env;
> +	struct rb_root *root;
> +	struct rb_node *next;
> +
> +	down_read(&env->bpf_progs.lock);
> +
> +	root = &env->bpf_progs.btfs;
> +	next = rb_first(root);
> +
> +	while (next) {
> +		struct btf_node *node;
> +
> +		node = rb_entry(next, struct btf_node, rb_node);
> +		next = rb_next(&node->rb_node);
> +		fprintf(fp, "# btf info of id %u\n", node->id);

So, I couldn't get this to work right now, and I have BPF programs that
are loaded and that have BTF info:

[root@quaco ~]# bpftool prog | tail -6
208: tracepoint  name sys_enter  tag 819967866022f1e1  gpl
	loaded_at 2019-03-12T11:16:55-0300  uid 0
	xlated 528B  jited 381B  memlock 4096B  map_ids 107,106,105
209: tracepoint  name sys_exit  tag c1bd85c092d6e4aa  gpl
	loaded_at 2019-03-12T11:16:55-0300  uid 0
	xlated 256B  jited 191B  memlock 4096B  map_ids 107,106
[root@quaco ~]#


[root@quaco ~]# bpftool map  | tail -6
105: perf_event_array  name __augmented_sys  flags 0x0
	key 4B  value 4B  max_entries 8  memlock 4096B
106: array  name syscalls  flags 0x0
	key 4B  value 1B  max_entries 512  memlock 8192B
107: hash  name pids_filtered  flags 0x0
	key 4B  value 1B  max_entries 64  memlock 8192B
[root@quaco ~]#

[root@quaco ~]# bpftool map dump id 107
[{
        "key": 8104,
        "value": true
    },{
        "key": 18868,
        "value": true
    }
]
[root@quaco ~]# ps ax|egrep 8104\|18868 | grep -v grep
 8104 pts/8    S+     0:07 trace -e recvmmsg
18868 ?        Ssl   21:21 /usr/libexec/gnome-terminal-server
[root@quaco ~]#

So I was expecting to see those btf lines there :-\

All the patches up to this point I have already merged and tested in my
local branch.

Will continue right after lunch to try to figure out why this BTF info
isn't landing on this new header feature...

- Arnaldo



> +	}
> +
> +	up_read(&env->bpf_progs.lock);
> +}
> +
>  static void free_event_desc(struct perf_evsel *events)
>  {
>  	struct perf_evsel *evsel;
> @@ -2509,6 +2564,49 @@ static int process_bpf_prog_info(struct feat_fd *ff,
>  	return err;
>  }
>  
> +static int process_bpf_btf(struct feat_fd *ff, void *data __maybe_unused)
> +{
> +	struct perf_env *env = &ff->ph->env;
> +	u32 count, i;
> +
> +	if (ff->ph->needs_swap) {
> +		pr_warning("interpreting btf from systems with endianity is not yet supported\n");
> +		return 0;
> +	}
> +
> +	if (do_read_u32(ff, &count))
> +		return -1;
> +
> +	down_write(&env->bpf_progs.lock);
> +
> +	for (i = 0; i < count; ++i) {
> +		struct btf_node *node;
> +		u32 id, data_size;
> +
> +		if (do_read_u32(ff, &id))
> +			return -1;
> +		if (do_read_u32(ff, &data_size))
> +			return -1;
> +
> +		node = malloc(sizeof(struct btf_node) + data_size);
> +		if (!node)
> +			return -1;
> +
> +		node->id = id;
> +		node->data_size = data_size;
> +
> +		if (__do_read(ff, node->data, data_size)) {
> +			free(node);
> +			return -1;
> +		}
> +
> +		perf_env__insert_btf(env, node);
> +	}
> +
> +	up_write(&env->bpf_progs.lock);
> +	return 0;
> +}
> +
>  struct feature_ops {
>  	int (*write)(struct feat_fd *ff, struct perf_evlist *evlist);
>  	void (*print)(struct feat_fd *ff, FILE *fp);
> @@ -2569,7 +2667,8 @@ static const struct feature_ops feat_ops[HEADER_LAST_FEATURE] = {
>  	FEAT_OPR(SAMPLE_TIME,	sample_time,	false),
>  	FEAT_OPR(MEM_TOPOLOGY,	mem_topology,	true),
>  	FEAT_OPR(CLOCKID,       clockid,        false),
> -	FEAT_OPR(BPF_PROG_INFO, bpf_prog_info,  false)
> +	FEAT_OPR(BPF_PROG_INFO, bpf_prog_info,  false),
> +	FEAT_OPR(BPF_BTF,       bpf_btf,        false)
>  };
>  
>  struct header_print_data {
> diff --git a/tools/perf/util/header.h b/tools/perf/util/header.h
> index 0785c91b4c3a..9e7d931f7c0d 100644
> --- a/tools/perf/util/header.h
> +++ b/tools/perf/util/header.h
> @@ -40,6 +40,7 @@ enum {
>  	HEADER_MEM_TOPOLOGY,
>  	HEADER_CLOCKID,
>  	HEADER_BPF_PROG_INFO,
> +	HEADER_BPF_BTF,
>  	HEADER_LAST_FEATURE,
>  	HEADER_FEAT_BITS	= 256,
>  };
> -- 
> 2.17.1
Arnaldo Carvalho de Melo March 12, 2019, 3:16 p.m. UTC | #2 
Em Tue, Mar 12, 2019 at 12:14:05PM -0300, Arnaldo Carvalho de Melo escreveu:
> Em Mon, Mar 11, 2019 at 10:30:45PM -0700, Song Liu escreveu:
> > +static void print_bpf_btf(struct feat_fd *ff, FILE *fp)
> > +{
> > +	struct perf_env *env = &ff->ph->env;
> > +	struct rb_root *root;
> > +	struct rb_node *next;
> > +
> > +	down_read(&env->bpf_progs.lock);
> > +
> > +	root = &env->bpf_progs.btfs;
> > +	next = rb_first(root);
> > +
> > +	while (next) {
> > +		struct btf_node *node;
> > +
> > +		node = rb_entry(next, struct btf_node, rb_node);
> > +		next = rb_next(&node->rb_node);
> > +		fprintf(fp, "# btf info of id %u\n", node->id);
> 
> So, I couldn't get this to work right now, and I have BPF programs that
> are loaded and that have BTF info:
> 
> [root@quaco ~]# bpftool prog | tail -6
> 208: tracepoint  name sys_enter  tag 819967866022f1e1  gpl
> 	loaded_at 2019-03-12T11:16:55-0300  uid 0
> 	xlated 528B  jited 381B  memlock 4096B  map_ids 107,106,105
> 209: tracepoint  name sys_exit  tag c1bd85c092d6e4aa  gpl
> 	loaded_at 2019-03-12T11:16:55-0300  uid 0
> 	xlated 256B  jited 191B  memlock 4096B  map_ids 107,106
> [root@quaco ~]#
> 
> 
> [root@quaco ~]# bpftool map  | tail -6
> 105: perf_event_array  name __augmented_sys  flags 0x0
> 	key 4B  value 4B  max_entries 8  memlock 4096B
> 106: array  name syscalls  flags 0x0
> 	key 4B  value 1B  max_entries 512  memlock 8192B
> 107: hash  name pids_filtered  flags 0x0
> 	key 4B  value 1B  max_entries 64  memlock 8192B
> [root@quaco ~]#
> 
> [root@quaco ~]# bpftool map dump id 107
> [{
>         "key": 8104,
>         "value": true
>     },{
>         "key": 18868,
>         "value": true
>     }
> ]
> [root@quaco ~]# ps ax|egrep 8104\|18868 | grep -v grep
>  8104 pts/8    S+     0:07 trace -e recvmmsg
> 18868 ?        Ssl   21:21 /usr/libexec/gnome-terminal-server
> [root@quaco ~]#
> 
> So I was expecting to see those btf lines there :-\
> 
> All the patches up to this point I have already merged and tested in my
> local branch.
> 
> Will continue right after lunch to try to figure out why this BTF info
> isn't landing on this new header feature...

I've pushed what I have to my git.kernel.org repo, branch
tmp.perf/bpf-annotate.

git://git.kernel.org/pub/scm/linux/kernel/git/acme/linux.git tmp.perf/bpf-annotate

The HEAD is this cset.

- Arnaldo
Song Liu March 12, 2019, 4:26 p.m. UTC | #3 
> On Mar 12, 2019, at 8:16 AM, Arnaldo Carvalho de Melo <arnaldo.melo@gmail.com> wrote:
> 
> Em Tue, Mar 12, 2019 at 12:14:05PM -0300, Arnaldo Carvalho de Melo escreveu:
>> Em Mon, Mar 11, 2019 at 10:30:45PM -0700, Song Liu escreveu:
>>> +static void print_bpf_btf(struct feat_fd *ff, FILE *fp)
>>> +{
>>> +	struct perf_env *env = &ff->ph->env;
>>> +	struct rb_root *root;
>>> +	struct rb_node *next;
>>> +
>>> +	down_read(&env->bpf_progs.lock);
>>> +
>>> +	root = &env->bpf_progs.btfs;
>>> +	next = rb_first(root);
>>> +
>>> +	while (next) {
>>> +		struct btf_node *node;
>>> +
>>> +		node = rb_entry(next, struct btf_node, rb_node);
>>> +		next = rb_next(&node->rb_node);
>>> +		fprintf(fp, "# btf info of id %u\n", node->id);
>> 
>> So, I couldn't get this to work right now, and I have BPF programs that
>> are loaded and that have BTF info:
>> 
>> [root@quaco ~]# bpftool prog | tail -6
>> 208: tracepoint  name sys_enter  tag 819967866022f1e1  gpl
>> 	loaded_at 2019-03-12T11:16:55-0300  uid 0
>> 	xlated 528B  jited 381B  memlock 4096B  map_ids 107,106,105
>> 209: tracepoint  name sys_exit  tag c1bd85c092d6e4aa  gpl
>> 	loaded_at 2019-03-12T11:16:55-0300  uid 0
>> 	xlated 256B  jited 191B  memlock 4096B  map_ids 107,106
>> [root@quaco ~]#
>> 
>> 
>> [root@quaco ~]# bpftool map  | tail -6
>> 105: perf_event_array  name __augmented_sys  flags 0x0
>> 	key 4B  value 4B  max_entries 8  memlock 4096B
>> 106: array  name syscalls  flags 0x0
>> 	key 4B  value 1B  max_entries 512  memlock 8192B
>> 107: hash  name pids_filtered  flags 0x0
>> 	key 4B  value 1B  max_entries 64  memlock 8192B
>> [root@quaco ~]#
>> 
>> [root@quaco ~]# bpftool map dump id 107
>> [{
>>        "key": 8104,
>>        "value": true
>>    },{
>>        "key": 18868,
>>        "value": true
>>    }
>> ]
>> [root@quaco ~]# ps ax|egrep 8104\|18868 | grep -v grep
>> 8104 pts/8    S+     0:07 trace -e recvmmsg
>> 18868 ?        Ssl   21:21 /usr/libexec/gnome-terminal-server
>> [root@quaco ~]#
>> 
>> So I was expecting to see those btf lines there :-\
>> 
>> All the patches up to this point I have already merged and tested in my
>> local branch.
>> 
>> Will continue right after lunch to try to figure out why this BTF info
>> isn't landing on this new header feature...
> 
> I've pushed what I have to my git.kernel.org repo, branch
> tmp.perf/bpf-annotate.
> 
> git://git.kernel.org/pub/scm/linux/kernel/git/acme/linux.git tmp.perf/bpf-annotate
> 
> The HEAD is this cset.
> 
> - Arnaldo

I am not sure I fully understand the problem here. 

I can get BTF information from this version:

# ~/perf report --header-only  | grep btf
# btf info of id 504

Thanks,
Song
Arnaldo Carvalho de Melo March 12, 2019, 5:05 p.m. UTC | #4 
Em Tue, Mar 12, 2019 at 04:26:17PM +0000, Song Liu escreveu:
> 
> 
> > On Mar 12, 2019, at 8:16 AM, Arnaldo Carvalho de Melo <arnaldo.melo@gmail.com> wrote:
> > 
> > Em Tue, Mar 12, 2019 at 12:14:05PM -0300, Arnaldo Carvalho de Melo escreveu:
> >> Em Mon, Mar 11, 2019 at 10:30:45PM -0700, Song Liu escreveu:
> >>> +static void print_bpf_btf(struct feat_fd *ff, FILE *fp)
> >>> +{
> >>> +	struct perf_env *env = &ff->ph->env;
> >>> +	struct rb_root *root;
> >>> +	struct rb_node *next;
> >>> +
> >>> +	down_read(&env->bpf_progs.lock);
> >>> +
> >>> +	root = &env->bpf_progs.btfs;
> >>> +	next = rb_first(root);
> >>> +
> >>> +	while (next) {
> >>> +		struct btf_node *node;
> >>> +
> >>> +		node = rb_entry(next, struct btf_node, rb_node);
> >>> +		next = rb_next(&node->rb_node);
> >>> +		fprintf(fp, "# btf info of id %u\n", node->id);
> >> 
> >> So, I couldn't get this to work right now, and I have BPF programs that
> >> are loaded and that have BTF info:
> >> 
> >> [root@quaco ~]# bpftool prog | tail -6
> >> 208: tracepoint  name sys_enter  tag 819967866022f1e1  gpl
> >> 	loaded_at 2019-03-12T11:16:55-0300  uid 0
> >> 	xlated 528B  jited 381B  memlock 4096B  map_ids 107,106,105
> >> 209: tracepoint  name sys_exit  tag c1bd85c092d6e4aa  gpl
> >> 	loaded_at 2019-03-12T11:16:55-0300  uid 0
> >> 	xlated 256B  jited 191B  memlock 4096B  map_ids 107,106
> >> [root@quaco ~]#
> >> 
> >> 
> >> [root@quaco ~]# bpftool map  | tail -6
> >> 105: perf_event_array  name __augmented_sys  flags 0x0
> >> 	key 4B  value 4B  max_entries 8  memlock 4096B
> >> 106: array  name syscalls  flags 0x0
> >> 	key 4B  value 1B  max_entries 512  memlock 8192B
> >> 107: hash  name pids_filtered  flags 0x0
> >> 	key 4B  value 1B  max_entries 64  memlock 8192B
> >> [root@quaco ~]#
> >> 
> >> [root@quaco ~]# bpftool map dump id 107
> >> [{
> >>        "key": 8104,
> >>        "value": true
> >>    },{
> >>        "key": 18868,
> >>        "value": true
> >>    }
> >> ]
> >> [root@quaco ~]# ps ax|egrep 8104\|18868 | grep -v grep
> >> 8104 pts/8    S+     0:07 trace -e recvmmsg
> >> 18868 ?        Ssl   21:21 /usr/libexec/gnome-terminal-server
> >> [root@quaco ~]#
> >> 
> >> So I was expecting to see those btf lines there :-\
> >> 
> >> All the patches up to this point I have already merged and tested in my
> >> local branch.
> >> 
> >> Will continue right after lunch to try to figure out why this BTF info
> >> isn't landing on this new header feature...
> > 
> > I've pushed what I have to my git.kernel.org repo, branch
> > tmp.perf/bpf-annotate.
> > 
> > git://git.kernel.org/pub/scm/linux/kernel/git/acme/linux.git tmp.perf/bpf-annotate
> > 
> > The HEAD is this cset.

> I am not sure I fully understand the problem here. 

Trying to say it another way, when I start 'perf record', with the
patches in your series up to this one ('[PATCH v9 perf,bpf 09/15] perf,
bpf: save btf information as headers to perf.data'), and while there is
a BPF program running, that has BTF attached to it as can be seen by
using 'bpf map dump', 'perf report --header-only' isn't showing any line
with 'btf' on it.

So, using -v I notice that it is failing to get enable attr.bpf_event
and attr.ksymbol, which makes me go get another coffee to check that the
kernel was built from my 5.1 tree that has those events and not 5.0 that
doesn't ;-\ Sorry for the noise, will get back here after I check all
this :-)

But to recap, the BPF events I was getting were the synthesized ones...

[root@quaco ~]# perf record -vv
Using CPUID GenuineIntel-6-8E-A
intel_pt default config: tsc,mtc,mtc_period=3,psb_period=3,pt,branch
nr_cblocks: 0
affinity: SYS
------------------------------------------------------------
perf_event_attr:
  size                             112
  { sample_period, sample_freq }   4000
  sample_type                      IP|TID|TIME|CPU|PERIOD
  read_format                      ID
  disabled                         1
  inherit                          1
  mmap                             1
  comm                             1
  freq                             1
  task                             1
  precise_ip                       3
  sample_id_all                    1
  exclude_guest                    1
  mmap2                            1
  comm_exec                        1
  ksymbol                          1
  bpf_event                        1
------------------------------------------------------------
sys_perf_event_open: pid -1  cpu 0  group_fd -1  flags 0x8
sys_perf_event_open failed, error -22
switching off bpf_event
------------------------------------------------------------
perf_event_attr:
  size                             112
  { sample_period, sample_freq }   4000
  sample_type                      IP|TID|TIME|CPU|PERIOD
  read_format                      ID
  disabled                         1
  inherit                          1
  mmap                             1
  comm                             1
  freq                             1
  task                             1
  precise_ip                       3
  sample_id_all                    1
  exclude_guest                    1
  mmap2                            1
  comm_exec                        1
  ksymbol                          1
------------------------------------------------------------
sys_perf_event_open: pid -1  cpu 0  group_fd -1  flags 0x8
sys_perf_event_open failed, error -22
switching off ksymbol
------------------------------------------------------------
perf_event_attr:
  size                             112
  { sample_period, sample_freq }   4000
  sample_type                      IP|TID|TIME|CPU|PERIOD
  read_format                      ID
  disabled                         1
  inherit                          1
  mmap                             1
  comm                             1
  freq                             1
  task                             1
  precise_ip                       3
  sample_id_all                    1
  exclude_guest                    1
  mmap2                            1
  comm_exec                        1
------------------------------------------------------------
sys_perf_event_open: pid -1  cpu 0  group_fd -1  flags 0x8 = 4
sys_perf_event_open: pid -1  cpu 1  group_fd -1  flags 0x8 = 5
sys_perf_event_open: pid -1  cpu 2  group_fd -1  flags 0x8 = 6
sys_perf_event_open: pid -1  cpu 3  group_fd -1  flags 0x8 = 7
sys_perf_event_open: pid -1  cpu 4  group_fd -1  flags 0x8 = 8
sys_perf_event_open: pid -1  cpu 5  group_fd -1  flags 0x8 = 9
sys_perf_event_open: pid -1  cpu 6  group_fd -1  flags 0x8 = 10
sys_perf_event_open: pid -1  cpu 7  group_fd -1  flags 0x8 = 11
mmap size 528384B
perf event ring buffer mmapped per cpu
Synthesizing TSC conversion information
Song Liu March 12, 2019, 5:29 p.m. UTC | #5 
> On Mar 12, 2019, at 10:05 AM, Arnaldo Carvalho de Melo <arnaldo.melo@gmail.com> wrote:
> 
> Em Tue, Mar 12, 2019 at 04:26:17PM +0000, Song Liu escreveu:
>> 
>> 
>>> On Mar 12, 2019, at 8:16 AM, Arnaldo Carvalho de Melo <arnaldo.melo@gmail.com> wrote:
>>> 
>>> Em Tue, Mar 12, 2019 at 12:14:05PM -0300, Arnaldo Carvalho de Melo escreveu:
>>>> Em Mon, Mar 11, 2019 at 10:30:45PM -0700, Song Liu escreveu:
>>>>> +static void print_bpf_btf(struct feat_fd *ff, FILE *fp)
>>>>> +{
>>>>> +	struct perf_env *env = &ff->ph->env;
>>>>> +	struct rb_root *root;
>>>>> +	struct rb_node *next;
>>>>> +
>>>>> +	down_read(&env->bpf_progs.lock);
>>>>> +
>>>>> +	root = &env->bpf_progs.btfs;
>>>>> +	next = rb_first(root);
>>>>> +
>>>>> +	while (next) {
>>>>> +		struct btf_node *node;
>>>>> +
>>>>> +		node = rb_entry(next, struct btf_node, rb_node);
>>>>> +		next = rb_next(&node->rb_node);
>>>>> +		fprintf(fp, "# btf info of id %u\n", node->id);
>>>> 
>>>> So, I couldn't get this to work right now, and I have BPF programs that
>>>> are loaded and that have BTF info:
>>>> 
>>>> [root@quaco ~]# bpftool prog | tail -6
>>>> 208: tracepoint  name sys_enter  tag 819967866022f1e1  gpl
>>>> 	loaded_at 2019-03-12T11:16:55-0300  uid 0
>>>> 	xlated 528B  jited 381B  memlock 4096B  map_ids 107,106,105
>>>> 209: tracepoint  name sys_exit  tag c1bd85c092d6e4aa  gpl
>>>> 	loaded_at 2019-03-12T11:16:55-0300  uid 0
>>>> 	xlated 256B  jited 191B  memlock 4096B  map_ids 107,106
>>>> [root@quaco ~]#
>>>> 
>>>> 
>>>> [root@quaco ~]# bpftool map  | tail -6
>>>> 105: perf_event_array  name __augmented_sys  flags 0x0
>>>> 	key 4B  value 4B  max_entries 8  memlock 4096B
>>>> 106: array  name syscalls  flags 0x0
>>>> 	key 4B  value 1B  max_entries 512  memlock 8192B
>>>> 107: hash  name pids_filtered  flags 0x0
>>>> 	key 4B  value 1B  max_entries 64  memlock 8192B
>>>> [root@quaco ~]#
>>>> 
>>>> [root@quaco ~]# bpftool map dump id 107
>>>> [{
>>>>       "key": 8104,
>>>>       "value": true
>>>>   },{
>>>>       "key": 18868,
>>>>       "value": true
>>>>   }
>>>> ]
>>>> [root@quaco ~]# ps ax|egrep 8104\|18868 | grep -v grep
>>>> 8104 pts/8    S+     0:07 trace -e recvmmsg
>>>> 18868 ?        Ssl   21:21 /usr/libexec/gnome-terminal-server
>>>> [root@quaco ~]#
>>>> 
>>>> So I was expecting to see those btf lines there :-\
>>>> 
>>>> All the patches up to this point I have already merged and tested in my
>>>> local branch.
>>>> 
>>>> Will continue right after lunch to try to figure out why this BTF info
>>>> isn't landing on this new header feature...
>>> 
>>> I've pushed what I have to my git.kernel.org repo, branch
>>> tmp.perf/bpf-annotate.
>>> 
>>> git://git.kernel.org/pub/scm/linux/kernel/git/acme/linux.git tmp.perf/bpf-annotate
>>> 
>>> The HEAD is this cset.
> 
>> I am not sure I fully understand the problem here. 
> 
> Trying to say it another way, when I start 'perf record', with the
> patches in your series up to this one ('[PATCH v9 perf,bpf 09/15] perf,
> bpf: save btf information as headers to perf.data'), and while there is
> a BPF program running, that has BTF attached to it as can be seen by
> using 'bpf map dump', 'perf report --header-only' isn't showing any line
> with 'btf' on it.
> 
> So, using -v I notice that it is failing to get enable attr.bpf_event
> and attr.ksymbol, which makes me go get another coffee to check that the
> kernel was built from my 5.1 tree that has those events and not 5.0 that
> doesn't ;-\ Sorry for the noise, will get back here after I check all
> this :-)
> 
> But to recap, the BPF events I was getting were the synthesized ones...

Yeah, to capture the short living BPF/BTF, we need patch 15/15 of the set. 

Thanks,
Song

> 
> [root@quaco ~]# perf record -vv
> Using CPUID GenuineIntel-6-8E-A
> intel_pt default config: tsc,mtc,mtc_period=3,psb_period=3,pt,branch
> nr_cblocks: 0
> affinity: SYS
> ------------------------------------------------------------
> perf_event_attr:
>  size                             112
>  { sample_period, sample_freq }   4000
>  sample_type                      IP|TID|TIME|CPU|PERIOD
>  read_format                      ID
>  disabled                         1
>  inherit                          1
>  mmap                             1
>  comm                             1
>  freq                             1
>  task                             1
>  precise_ip                       3
>  sample_id_all                    1
>  exclude_guest                    1
>  mmap2                            1
>  comm_exec                        1
>  ksymbol                          1
>  bpf_event                        1
> ------------------------------------------------------------
> sys_perf_event_open: pid -1  cpu 0  group_fd -1  flags 0x8
> sys_perf_event_open failed, error -22
> switching off bpf_event
> ------------------------------------------------------------
> perf_event_attr:
>  size                             112
>  { sample_period, sample_freq }   4000
>  sample_type                      IP|TID|TIME|CPU|PERIOD
>  read_format                      ID
>  disabled                         1
>  inherit                          1
>  mmap                             1
>  comm                             1
>  freq                             1
>  task                             1
>  precise_ip                       3
>  sample_id_all                    1
>  exclude_guest                    1
>  mmap2                            1
>  comm_exec                        1
>  ksymbol                          1
> ------------------------------------------------------------
> sys_perf_event_open: pid -1  cpu 0  group_fd -1  flags 0x8
> sys_perf_event_open failed, error -22
> switching off ksymbol
> ------------------------------------------------------------
> perf_event_attr:
>  size                             112
>  { sample_period, sample_freq }   4000
>  sample_type                      IP|TID|TIME|CPU|PERIOD
>  read_format                      ID
>  disabled                         1
>  inherit                          1
>  mmap                             1
>  comm                             1
>  freq                             1
>  task                             1
>  precise_ip                       3
>  sample_id_all                    1
>  exclude_guest                    1
>  mmap2                            1
>  comm_exec                        1
> ------------------------------------------------------------
> sys_perf_event_open: pid -1  cpu 0  group_fd -1  flags 0x8 = 4
> sys_perf_event_open: pid -1  cpu 1  group_fd -1  flags 0x8 = 5
> sys_perf_event_open: pid -1  cpu 2  group_fd -1  flags 0x8 = 6
> sys_perf_event_open: pid -1  cpu 3  group_fd -1  flags 0x8 = 7
> sys_perf_event_open: pid -1  cpu 4  group_fd -1  flags 0x8 = 8
> sys_perf_event_open: pid -1  cpu 5  group_fd -1  flags 0x8 = 9
> sys_perf_event_open: pid -1  cpu 6  group_fd -1  flags 0x8 = 10
> sys_perf_event_open: pid -1  cpu 7  group_fd -1  flags 0x8 = 11
> mmap size 528384B
> perf event ring buffer mmapped per cpu
> Synthesizing TSC conversion information
Arnaldo Carvalho de Melo March 15, 2019, 7:06 p.m. UTC | #6 
Em Tue, Mar 12, 2019 at 05:29:03PM +0000, Song Liu escreveu:
> > On Mar 12, 2019, at 10:05 AM, Arnaldo Carvalho de Melo <arnaldo.melo@gmail.com> wrote:
> > Em Tue, Mar 12, 2019 at 04:26:17PM +0000, Song Liu escreveu:
> >>> On Mar 12, 2019, at 8:16 AM, Arnaldo Carvalho de Melo <arnaldo.melo@gmail.com> wrote:
> >>> Em Tue, Mar 12, 2019 at 12:14:05PM -0300, Arnaldo Carvalho de Melo escreveu:
> >>>> Em Mon, Mar 11, 2019 at 10:30:45PM -0700, Song Liu escreveu:
> >>>>> +static void print_bpf_btf(struct feat_fd *ff, FILE *fp)
> >>>>> +{
> >>>>> +	struct perf_env *env = &ff->ph->env;
> >>>>> +	struct rb_root *root;
> >>>>> +	struct rb_node *next;
> >>>>> +
> >>>>> +	down_read(&env->bpf_progs.lock);
> >>>>> +
> >>>>> +	root = &env->bpf_progs.btfs;
> >>>>> +	next = rb_first(root);
> >>>>> +
> >>>>> +	while (next) {
> >>>>> +		struct btf_node *node;
> >>>>> +
> >>>>> +		node = rb_entry(next, struct btf_node, rb_node);
> >>>>> +		next = rb_next(&node->rb_node);
> >>>>> +		fprintf(fp, "# btf info of id %u\n", node->id);
> >>>> 
> >>>> So, I couldn't get this to work right now, and I have BPF programs that
> >>>> are loaded and that have BTF info:
> >>>> 
> >>>> [root@quaco ~]# bpftool prog | tail -6
> >>>> 208: tracepoint  name sys_enter  tag 819967866022f1e1  gpl
> >>>> 	loaded_at 2019-03-12T11:16:55-0300  uid 0
> >>>> 	xlated 528B  jited 381B  memlock 4096B  map_ids 107,106,105
> >>>> 209: tracepoint  name sys_exit  tag c1bd85c092d6e4aa  gpl
> >>>> 	loaded_at 2019-03-12T11:16:55-0300  uid 0
> >>>> 	xlated 256B  jited 191B  memlock 4096B  map_ids 107,106
> >>>> [root@quaco ~]#
> >>>> 
> >>>> 
> >>>> [root@quaco ~]# bpftool map  | tail -6
> >>>> 105: perf_event_array  name __augmented_sys  flags 0x0
> >>>> 	key 4B  value 4B  max_entries 8  memlock 4096B
> >>>> 106: array  name syscalls  flags 0x0
> >>>> 	key 4B  value 1B  max_entries 512  memlock 8192B
> >>>> 107: hash  name pids_filtered  flags 0x0
> >>>> 	key 4B  value 1B  max_entries 64  memlock 8192B
> >>>> [root@quaco ~]#
> >>>> 
> >>>> [root@quaco ~]# bpftool map dump id 107
> >>>> [{
> >>>>       "key": 8104,
> >>>>       "value": true
> >>>>   },{
> >>>>       "key": 18868,
> >>>>       "value": true
> >>>>   }
> >>>> ]
> >>>> [root@quaco ~]# ps ax|egrep 8104\|18868 | grep -v grep
> >>>> 8104 pts/8    S+     0:07 trace -e recvmmsg
> >>>> 18868 ?        Ssl   21:21 /usr/libexec/gnome-terminal-server
> >>>> [root@quaco ~]#
> >>>> 
> >>>> So I was expecting to see those btf lines there :-\
> >>>> 
> >>>> All the patches up to this point I have already merged and tested in my
> >>>> local branch.
> >>>> 
> >>>> Will continue right after lunch to try to figure out why this BTF info
> >>>> isn't landing on this new header feature...
> >>> 
> >>> I've pushed what I have to my git.kernel.org repo, branch
> >>> tmp.perf/bpf-annotate.
> >>> 
> >>> git://git.kernel.org/pub/scm/linux/kernel/git/acme/linux.git tmp.perf/bpf-annotate
> >>> 
> >>> The HEAD is this cset.
> > 
> >> I am not sure I fully understand the problem here. 
> > 
> > Trying to say it another way, when I start 'perf record', with the
> > patches in your series up to this one ('[PATCH v9 perf,bpf 09/15] perf,
> > bpf: save btf information as headers to perf.data'), and while there is
> > a BPF program running, that has BTF attached to it as can be seen by
> > using 'bpf map dump', 'perf report --header-only' isn't showing any line
> > with 'btf' on it.
> > 
> > So, using -v I notice that it is failing to get enable attr.bpf_event
> > and attr.ksymbol, which makes me go get another coffee to check that the
> > kernel was built from my 5.1 tree that has those events and not 5.0 that
> > doesn't ;-\ Sorry for the noise, will get back here after I check all
> > this :-)
> > 
> > But to recap, the BPF events I was getting were the synthesized ones...
> 
> Yeah, to capture the short living BPF/BTF, we need patch 15/15 of the set. 

So, I continue trying to test this with the patches applied up to the
patch in the subject of this message, i.e. up to:

  09/15 perf, bpf: save btf information as headers to perf.data

While running on a kernel based on tip/perf/core, so it should have what
is needed:

  [root@quaco ~]# egrep 't perf_event_(bpf|ksymbol)_output' /proc/kallsyms
  ffffffff94211a40 t perf_event_bpf_output
  ffffffff94216550 t perf_event_ksymbol_output
  [root@quaco ~]#

But when I debug breakpointing perf_event__synthesize_one_bpf_prog(),
bpf_prog_info->btf_info is always zero, i.e. here:

        /* check BTF func info support */
        if (info->btf_id && info->nr_func_info && info->func_info_rec_size) {
                /* btf func info number should be same as sub_prog_cnt */
                if (sub_prog_cnt != info->nr_func_info) {
                        pr_debug("%s: mismatch in BPF sub program count and BTF function info count, aborting\n", __func__);
                        err = -1;
                        goto out;
                }
                if (btf__get_from_id(info->btf_id, &btf)) {
                        pr_debug("%s: failed to get BTF of id %u, aborting\n", __func__, info->btf_id);
                        err = -1;
                        btf = NULL;
                        goto out;
                }
                has_btf = true;
                perf_env__fetch_btf(env, info->btf_id, btf);
        }

So we never get into this if body and this do not call
perf__env_fetch_btf() and thus don't write BTF info to the perf.data
header.

And yes, there are BPF programs with BTF information associated:

[root@quaco perf]# bpftool map dump pids_filtered
[{
        "key": 2592,
        "value": true
    },{
        "key": 20511,
        "value": true
    }
]
[root@quaco perf]#

I.e. bpftool can find the BTF info and thus is able to show the
'pids_filtered' map keys and values pretty printed, not just as hex raw
data.

I'm trying to find out why 'bpftool map dump' finds the BTF info while
perf_event__synthesize_one_bpf_prog() doesn't.

- Arnaldo
Arnaldo Carvalho de Melo March 15, 2019, 7:26 p.m. UTC | #7 
Em Fri, Mar 15, 2019 at 04:06:51PM -0300, Arnaldo Carvalho de Melo escreveu:
> And yes, there are BPF programs with BTF information associated:
 
> [root@quaco perf]# bpftool map dump pids_filtered
> [{
>         "key": 2592,
>         "value": true
>     },{
>         "key": 20511,
>         "value": true
>     }
> ]
> [root@quaco perf]#
 
> I.e. bpftool can find the BTF info and thus is able to show the
> 'pids_filtered' map keys and values pretty printed, not just as hex raw
> data.
 
> I'm trying to find out why 'bpftool map dump' finds the BTF info while
> perf_event__synthesize_one_bpf_prog() doesn't.

Humm, the BTF info above is for BPF _maps_ not for _programs_, I think
you haven't added BTF info for maps in the perf.data header, right?

- Arnaldo
Song Liu March 15, 2019, 7:31 p.m. UTC | #8 
Sorry for replying from the phone.

Sent from my iPhone

> On Mar 15, 2019, at 12:26 PM, Arnaldo Carvalho de Melo <arnaldo.melo@gmail.com> wrote:
> 
> Em Fri, Mar 15, 2019 at 04:06:51PM -0300, Arnaldo Carvalho de Melo escreveu:
>> And yes, there are BPF programs with BTF information associated:
> 
>> [root@quaco perf]# bpftool map dump pids_filtered
>> [{
>>        "key": 2592,
>>        "value": true
>>    },{
>>        "key": 20511,
>>        "value": true
>>    }
>> ]
>> [root@quaco perf]#
> 
>> I.e. bpftool can find the BTF info and thus is able to show the
>> 'pids_filtered' map keys and values pretty printed, not just as hex raw
>> data.
> 
>> I'm trying to find out why 'bpftool map dump' finds the BTF info while
>> perf_event__synthesize_one_bpf_prog() doesn't.
> 
> Humm, the BTF info above is for BPF _maps_ not for _programs_, I think
> you haven't added BTF info for maps in the perf.data header, right?
> 
> - Arnaldo

That’s right. We iterate all BPF programs, and fetch BTF referred by the programs.

Thanks,
Song
Arnaldo Carvalho de Melo March 15, 2019, 7:42 p.m. UTC | #9 
Em Fri, Mar 15, 2019 at 04:26:10PM -0300, Arnaldo Carvalho de Melo escreveu:
> Em Fri, Mar 15, 2019 at 04:06:51PM -0300, Arnaldo Carvalho de Melo escreveu:
> > And yes, there are BPF programs with BTF information associated:
>  
> > [root@quaco perf]# bpftool map dump pids_filtered
> > [{
> >         "key": 2592,
> >         "value": true
> >     },{
> >         "key": 20511,
> >         "value": true
> >     }
> > ]
> > [root@quaco perf]#
>  
> > I.e. bpftool can find the BTF info and thus is able to show the
> > 'pids_filtered' map keys and values pretty printed, not just as hex raw
> > data.
>  
> > I'm trying to find out why 'bpftool map dump' finds the BTF info while
> > perf_event__synthesize_one_bpf_prog() doesn't.
> 
> Humm, the BTF info above is for BPF _maps_ not for _programs_, I think
> you haven't added BTF info for maps in the perf.data header, right?

And then the BPF program I was using to test this had BTF encoded from
DWARF by pahole, so only associated to BPF maps, not to BPF programs, as
soon as I regenerated that BPF .o with clang 9.0, I got the BTF info for
the BPF programs and all works as expected:

[root@quaco perf]# clang --version
clang version 9.0.0 (https://git.llvm.org/git/clang.git/ 7906282d3afec5dfdc2b27943fd6c0309086c507) (https://git.llvm.org/git/llvm.git/ a1b5de1ff8ae8bc79dc8e86e1f82565229bd0500)
Target: x86_64-unknown-linux-gnu
Thread model: posix
InstalledDir: /opt/llvm/bin
[root@quaco perf]# perf record -e /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.c sleep 1
LLVM: dumping /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.023 MB perf.data ]
[root@quaco perf]# file /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o
/home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o: ELF 64-bit LSB relocatable, eBPF, version 1 (SYSV), with debug_info, not stripped
[root@quaco perf]# readelf -SW /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o | grep BTF
  [22] .BTF              PROGBITS        0000000000000000 000ede 000b0e 00      0   0  1
  [23] .BTF.ext          PROGBITS        0000000000000000 0019ec 0002a0 00      0   0  1
  [24] .rel.BTF.ext      REL             0000000000000000 002fa8 000270 10     30  23  8
[root@quaco perf]# grep examples ~/.perfconfig
	add_events = /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o
[root@quaco perf]# 
[root@quaco perf]# perf trace -e recvmmsg

Then, while this runs, using that augmented_raw_syscalls.o BPF program
generated with clang 9.0 and with proper BTF for BPF programs and not
just for BPF maps:

[root@quaco ~]# bpftool map dump pids_filtered
[{
        "key": 22459,
        "value": true
    },{
        "key": 2592,
        "value": true
    }
]
[root@quaco ~]#

[root@quaco ~]# perf record sleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.020 MB perf.data (7 samples) ]
[root@quaco ~]# perf report --header-only | grep b[pt]f
# event : name = cycles:ppp, , id = { 1116204, 1116205, 1116206, 1116207, 1116208, 1116209, 1116210, 1116211 }, size = 112, { sample_period, sample_freq } = 4000, sample_type = IP|TID|TIME|PERIOD, read_format = ID, disabled = 1, inherit = 1, mmap = 1, comm = 1, freq = 1, enable_on_exec = 1, task = 1, precise_ip = 3, sample_id_all = 1, exclude_guest = 1, mmap2 = 1, comm_exec = 1, ksymbol = 1, bpf_event = 1
# bpf_prog_info of id 13
# bpf_prog_info of id 14
# bpf_prog_info of id 15
# bpf_prog_info of id 16
# bpf_prog_info of id 17
# bpf_prog_info of id 18
# bpf_prog_info of id 21
# bpf_prog_info of id 22
# bpf_prog_info of id 51
# bpf_prog_info of id 52
# btf info of id 8
[root@quaco ~]#

Moving along the patch queue...

- Arnaldo
diff mbox series

Patch

diff --git a/tools/perf/util/header.c b/tools/perf/util/header.c
index a4ef8f657ad0..7decd2d1dbda 100644
--- a/tools/perf/util/header.c
+++ b/tools/perf/util/header.c
@@ -905,6 +905,39 @@  static int write_bpf_prog_info(struct feat_fd *ff,
 	return ret;
 }
 
+static int write_bpf_btf(struct feat_fd *ff,
+			 struct perf_evlist *evlist __maybe_unused)
+{
+	struct perf_env *env = &ff->ph->env;
+	struct rb_root *root;
+	struct rb_node *next;
+	int ret;
+
+	down_read(&env->bpf_progs.lock);
+
+	ret = do_write(ff, &env->bpf_progs.btfs_cnt,
+		       sizeof(env->bpf_progs.btfs_cnt));
+
+	if (ret < 0)
+		goto out;
+
+	root = &env->bpf_progs.btfs;
+	next = rb_first(root);
+	while (next) {
+		struct btf_node *node;
+
+		node = rb_entry(next, struct btf_node, rb_node);
+		next = rb_next(&node->rb_node);
+		ret = do_write(ff, &node->id,
+			       sizeof(u32) * 2 + node->data_size);
+		if (ret < 0)
+			goto out;
+	}
+out:
+	up_read(&env->bpf_progs.lock);
+	return ret;
+}
+
 static int cpu_cache_level__sort(const void *a, const void *b)
 {
 	struct cpu_cache_level *cache_a = (struct cpu_cache_level *)a;
@@ -1408,6 +1441,28 @@  static void print_bpf_prog_info(struct feat_fd *ff, FILE *fp)
 	up_read(&env->bpf_progs.lock);
 }
 
+static void print_bpf_btf(struct feat_fd *ff, FILE *fp)
+{
+	struct perf_env *env = &ff->ph->env;
+	struct rb_root *root;
+	struct rb_node *next;
+
+	down_read(&env->bpf_progs.lock);
+
+	root = &env->bpf_progs.btfs;
+	next = rb_first(root);
+
+	while (next) {
+		struct btf_node *node;
+
+		node = rb_entry(next, struct btf_node, rb_node);
+		next = rb_next(&node->rb_node);
+		fprintf(fp, "# btf info of id %u\n", node->id);
+	}
+
+	up_read(&env->bpf_progs.lock);
+}
+
 static void free_event_desc(struct perf_evsel *events)
 {
 	struct perf_evsel *evsel;
@@ -2509,6 +2564,49 @@  static int process_bpf_prog_info(struct feat_fd *ff,
 	return err;
 }
 
+static int process_bpf_btf(struct feat_fd *ff, void *data __maybe_unused)
+{
+	struct perf_env *env = &ff->ph->env;
+	u32 count, i;
+
+	if (ff->ph->needs_swap) {
+		pr_warning("interpreting btf from systems with endianity is not yet supported\n");
+		return 0;
+	}
+
+	if (do_read_u32(ff, &count))
+		return -1;
+
+	down_write(&env->bpf_progs.lock);
+
+	for (i = 0; i < count; ++i) {
+		struct btf_node *node;
+		u32 id, data_size;
+
+		if (do_read_u32(ff, &id))
+			return -1;
+		if (do_read_u32(ff, &data_size))
+			return -1;
+
+		node = malloc(sizeof(struct btf_node) + data_size);
+		if (!node)
+			return -1;
+
+		node->id = id;
+		node->data_size = data_size;
+
+		if (__do_read(ff, node->data, data_size)) {
+			free(node);
+			return -1;
+		}
+
+		perf_env__insert_btf(env, node);
+	}
+
+	up_write(&env->bpf_progs.lock);
+	return 0;
+}
+
 struct feature_ops {
 	int (*write)(struct feat_fd *ff, struct perf_evlist *evlist);
 	void (*print)(struct feat_fd *ff, FILE *fp);
@@ -2569,7 +2667,8 @@  static const struct feature_ops feat_ops[HEADER_LAST_FEATURE] = {
 	FEAT_OPR(SAMPLE_TIME,	sample_time,	false),
 	FEAT_OPR(MEM_TOPOLOGY,	mem_topology,	true),
 	FEAT_OPR(CLOCKID,       clockid,        false),
-	FEAT_OPR(BPF_PROG_INFO, bpf_prog_info,  false)
+	FEAT_OPR(BPF_PROG_INFO, bpf_prog_info,  false),
+	FEAT_OPR(BPF_BTF,       bpf_btf,        false)
 };
 
 struct header_print_data {
diff --git a/tools/perf/util/header.h b/tools/perf/util/header.h
index 0785c91b4c3a..9e7d931f7c0d 100644
--- a/tools/perf/util/header.h
+++ b/tools/perf/util/header.h
@@ -40,6 +40,7 @@  enum {
 	HEADER_MEM_TOPOLOGY,
 	HEADER_CLOCKID,
 	HEADER_BPF_PROG_INFO,
+	HEADER_BPF_BTF,
 	HEADER_LAST_FEATURE,
 	HEADER_FEAT_BITS	= 256,
 };