[RFC PATCH 0/2] perf tools: Print bpf-output events in 'perf script'

[RFC PATCH 0/2] perf tools: Print bpf-output events in 'perf script'

[Wang Nan]

Hi Arnaldo and Jiri,

   Glad to see the progress we made today.

   Before you trying libbaleltrace, please consider these two patches,
which allows print BPF output data directly through 'perf script'.
I think it would be useful for people don't have libbabeltrace ready.
With these two patch they can write scripts by their own:

 # ./perf script
          usleep  4882 21384.532523:                       evt:  ffffffff810e97d1 sys_nanosleep ([kernel.kallsyms])
      BPF output: 0000: 52 61 69 73 65 20 61 20  Raise a
                  0008: 42 50 46 20 65 76 65 6e  BPF even
                  0010: 74 21 00 00              t!..
      BPF string: "Raise a BPF event!"

          usleep  4882 21384.632606:                       evt:  ffffffff8105c609 kretprobe_trampoline_holder ([kernel.kallsyms
      BPF output: 0000: 52 61 69 73 65 20 61 20  Raise a
                  0008: 42 50 46 20 65 76 65 6e  BPF even
                  0010: 74 21 00 00              t!..
      BPF string: "Raise a BPF event!"

Thank you.

Wang Nan (2):
  perf tools: Make binary data printer code in trace_event public
    available
  perf script: Print bpf-output events in 'perf script'

 tools/perf/builtin-script.c | 93 ++++++++++++++++++++++++++++++++++++++++++---
 tools/perf/util/debug.c     | 75 +++++++++++++++++++++++-------------
 tools/perf/util/util.c      | 37 ++++++++++++++++++
 tools/perf/util/util.h      | 20 ++++++++++
 4 files changed, 193 insertions(+), 32 deletions(-)

Signed-off-by: Wang Nan <wangnan0@huawei.com>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Brendan Gregg <brendan.d.gregg@gmail.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Li Zefan <lizefan@huawei.com>
Cc: pi3orama@163.com

-- 
1.8.3.4

[RFC PATCH 1/2] perf tools: Make binary data printer code in trace_event public available

[Wang Nan]

Move code printing binray data from trace_event() to utils.c and allows
passing different printer. Further commits will use this logic to print
bpf output event.

Signed-off-by: Wang Nan <wangnan0@huawei.com>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Brendan Gregg <brendan.d.gregg@gmail.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Li Zefan <lizefan@huawei.com>
Cc: pi3orama@163.com
---
 tools/perf/util/debug.c | 75 +++++++++++++++++++++++++++++++------------------
 tools/perf/util/util.c  | 37 ++++++++++++++++++++++++
 tools/perf/util/util.h  | 20 +++++++++++++
 3 files changed, 105 insertions(+), 27 deletions(-)

diff --git a/tools/perf/util/debug.c b/tools/perf/util/debug.c
index ff7e86a..8c4212a 100644
--- a/tools/perf/util/debug.c
+++ b/tools/perf/util/debug.c
@@ -106,40 +106,61 @@ int dump_printf(const char *fmt, ...)
 	return ret;
 }
 
+static void trace_event_printer(enum binary_printer_ops op,
+				unsigned int val, void *extra)
+{
+	const char *color = PERF_COLOR_BLUE;
+	union perf_event *event = (union perf_event *)extra;
+	unsigned char ch = (unsigned char)val;
+
+	switch (op) {
+	case BINARY_PRINT_DATA_BEGIN:
+		printf(".");
+		color_fprintf(stdout, color, "\n. ... raw event: size %d bytes\n",
+				event->header.size);
+		break;
+	case BINARY_PRINT_LINE_BEGIN:
+		printf(".");
+		break;
+	case BINARY_PRINT_ADDR:
+		color_fprintf(stdout, color, "  %04x: ", val);
+		break;
+	case BINARY_PRINT_NUM_DATA:
+		color_fprintf(stdout, color, " %02x", val);
+		break;
+	case BINARY_PRINT_NUM_PAD:
+		color_fprintf(stdout, color, "   ");
+		break;
+	case BINARY_PRINT_SEP:
+		color_fprintf(stdout, color, "  ");
+		break;
+	case BINARY_PRINT_CHAR_DATA:
+		color_fprintf(stdout, color, "%c",
+			      isprint(ch) ? ch : '.');
+		break;
+	case BINARY_PRINT_CHAR_PAD:
+		color_fprintf(stdout, color, " ");
+		break;
+	case BINARY_PRINT_LINE_END:
+		color_fprintf(stdout, color, "\n");
+		break;
+	case BINARY_PRINT_DATA_END:
+		printf("\n");
+		break;
+	default:
+		break;
+	}
+}
+
 void trace_event(union perf_event *event)
 {
 	unsigned char *raw_event = (void *)event;
-	const char *color = PERF_COLOR_BLUE;
-	int i, j;
 
 	if (!dump_trace)
 		return;
 
-	printf(".");
-	color_fprintf(stdout, color, "\n. ... raw event: size %d bytes\n",
-		      event->header.size);
-
-	for (i = 0; i < event->header.size; i++) {
-		if ((i & 15) == 0) {
-			printf(".");
-			color_fprintf(stdout, color, "  %04x: ", i);
-		}
-
-		color_fprintf(stdout, color, " %02x", raw_event[i]);
-
-		if (((i & 15) == 15) || i == event->header.size-1) {
-			color_fprintf(stdout, color, "  ");
-			for (j = 0; j < 15-(i & 15); j++)
-				color_fprintf(stdout, color, "   ");
-			for (j = i & ~15; j <= i; j++) {
-				color_fprintf(stdout, color, "%c",
-					      isprint(raw_event[j]) ?
-					      raw_event[j] : '.');
-			}
-			color_fprintf(stdout, color, "\n");
-		}
-	}
-	printf(".\n");
+	print_binary(raw_event, event->header.size, 16,
+		     trace_event_printer, event);
 }
 
 static struct debug_variable {
diff --git a/tools/perf/util/util.c b/tools/perf/util/util.c
index 35b20dd..b7766c5 100644
--- a/tools/perf/util/util.c
+++ b/tools/perf/util/util.c
@@ -14,6 +14,7 @@
 #include <limits.h>
 #include <byteswap.h>
 #include <linux/kernel.h>
+#include <linux/log2.h>
 #include <unistd.h>
 #include "callchain.h"
 #include "strlist.h"
@@ -670,3 +671,39 @@ int fetch_current_timestamp(char *buf, size_t sz)
 
 	return 0;
 }
+
+void print_binary(unsigned char *data, size_t len,
+		  size_t bytes_per_line, print_binary_t printer,
+		  void *extra)
+{
+	size_t i, j, mask;
+
+	if (!printer)
+		return;
+
+	bytes_per_line = roundup_pow_of_two(bytes_per_line);
+	mask = bytes_per_line - 1;
+
+	printer(BINARY_PRINT_DATA_BEGIN, 0, extra);
+	for (i = 0; i < len; i++) {
+		if ((i & mask) == 0) {
+			printer(BINARY_PRINT_LINE_BEGIN, -1, extra);
+			printer(BINARY_PRINT_ADDR, i, extra);
+		}
+
+		printer(BINARY_PRINT_NUM_DATA, data[i], extra);
+
+		if (((i & mask) == mask) || i == len - 1) {
+			for (j = 0; j < mask-(i & mask); j++)
+				printer(BINARY_PRINT_NUM_PAD, -1, extra);
+
+			printer(BINARY_PRINT_SEP, i, extra);
+			for (j = i & ~mask; j <= i; j++)
+				printer(BINARY_PRINT_CHAR_DATA, data[j], extra);
+			for (j = 0; j < mask-(i & mask); j++)
+				printer(BINARY_PRINT_CHAR_PAD, i, extra);
+			printer(BINARY_PRINT_LINE_END, -1, extra);
+		}
+	}
+	printer(BINARY_PRINT_DATA_END, -1, extra);
+}
diff --git a/tools/perf/util/util.h b/tools/perf/util/util.h
index 3dd0408..7015019 100644
--- a/tools/perf/util/util.h
+++ b/tools/perf/util/util.h
@@ -345,4 +345,24 @@ const char *perf_tip(const char *dirpath);
 bool is_regular_file(const char *file);
 int fetch_current_timestamp(char *buf, size_t sz);
 
+enum binary_printer_ops {
+	BINARY_PRINT_DATA_BEGIN,
+	BINARY_PRINT_LINE_BEGIN,
+	BINARY_PRINT_ADDR,
+	BINARY_PRINT_NUM_DATA,
+	BINARY_PRINT_NUM_PAD,
+	BINARY_PRINT_SEP,
+	BINARY_PRINT_CHAR_DATA,
+	BINARY_PRINT_CHAR_PAD,
+	BINARY_PRINT_LINE_END,
+	BINARY_PRINT_DATA_END,
+};
+
+typedef void (*print_binary_t)(enum binary_printer_ops,
+			       unsigned int val,
+			       void *extra);
+
+void print_binary(unsigned char *data, size_t len,
+		  size_t bytes_per_line, print_binary_t printer,
+		  void *extra);
 #endif /* GIT_COMPAT_UTIL_H */
-- 
1.8.3.4

[RFC PATCH 2/2] perf script: Print bpf-output events in 'perf script'

[Wang Nan]

This patch allows 'perf script' output messages from BPF program.
For example, use test_bpf_output_3.c at the end of this commit
message,

 # ./perf record -e bpf-output/no-inherit,name=evt/ \
                 -e ./test_bpf_output_3.c/map:channel.event=evt/ \
                 usleep 100000

 # ./perf script
          usleep  4882 21384.532523:                       evt:  ffffffff810e97d1 sys_nanosleep ([kernel.kallsyms])
      BPF output: 0000: 52 61 69 73 65 20 61 20  Raise a
                  0008: 42 50 46 20 65 76 65 6e  BPF even
                  0010: 74 21 00 00              t!..
      BPF string: "Raise a BPF event!"

          usleep  4882 21384.632606:                       evt:  ffffffff8105c609 kretprobe_trampoline_holder ([kernel.kallsyms
      BPF output: 0000: 52 61 69 73 65 20 61 20  Raise a
                  0008: 42 50 46 20 65 76 65 6e  BPF even
                  0010: 74 21 00 00              t!..
      BPF string: "Raise a BPF event!"

Two samples from BPF output are printed by both binary and string
format.

If BPF program output something unprintable, string format is
suppressed.

 /************************ 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__,
 };

 static inline int __attribute__((always_inline))
 func(void *ctx, int type)
 {
	char output_str[] = "Raise a BPF event!";

        perf_event_output(ctx, &channel, get_smp_processor_id(),
			  &output_str, sizeof(output_str));
        return 0;
 }
 SEC("func_begin=sys_nanosleep")
 int func_begin(void *ctx) {return func(ctx, 1);}
 SEC("func_end=sys_nanosleep%return")
 int func_end(void *ctx) { return func(ctx, 2);}
 char _license[] SEC("license") = "GPL";
 int _version SEC("version") = LINUX_VERSION_CODE;
 /************************* END ***************************/

Signed-off-by: Wang Nan <wangnan0@huawei.com>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Brendan Gregg <brendan.d.gregg@gmail.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Li Zefan <lizefan@huawei.com>
Cc: pi3orama@163.com
---
 tools/perf/builtin-script.c | 93 ++++++++++++++++++++++++++++++++++++++++++---
 1 file changed, 88 insertions(+), 5 deletions(-)

diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c
index f4caf48..e52f55c 100644
--- a/tools/perf/builtin-script.c
+++ b/tools/perf/builtin-script.c
@@ -60,6 +60,7 @@ enum perf_output_field {
 	PERF_OUTPUT_BRSTACKSYM	    = 1U << 16,
 	PERF_OUTPUT_DATA_SRC	    = 1U << 17,
 	PERF_OUTPUT_WEIGHT	    = 1U << 18,
+	PERF_OUTPUT_BPF_OUTPUT	    = 1U << 19,
 };
 
 struct output_option {
@@ -85,6 +86,7 @@ struct output_option {
 	{.str = "brstacksym", .field = PERF_OUTPUT_BRSTACKSYM},
 	{.str = "data_src", .field = PERF_OUTPUT_DATA_SRC},
 	{.str = "weight",   .field = PERF_OUTPUT_WEIGHT},
+	{.str = "bpf-output",   .field = PERF_OUTPUT_BPF_OUTPUT},
 };
 
 /* default set to maintain compatibility with current format */
@@ -105,7 +107,7 @@ static struct {
 			      PERF_OUTPUT_SYM | PERF_OUTPUT_DSO |
 			      PERF_OUTPUT_PERIOD,
 
-		.invalid_fields = PERF_OUTPUT_TRACE,
+		.invalid_fields = PERF_OUTPUT_TRACE | PERF_OUTPUT_BPF_OUTPUT,
 	},
 
 	[PERF_TYPE_SOFTWARE] = {
@@ -115,7 +117,7 @@ static struct {
 			      PERF_OUTPUT_CPU | PERF_OUTPUT_TIME |
 			      PERF_OUTPUT_EVNAME | PERF_OUTPUT_IP |
 			      PERF_OUTPUT_SYM | PERF_OUTPUT_DSO |
-			      PERF_OUTPUT_PERIOD,
+			      PERF_OUTPUT_PERIOD | PERF_OUTPUT_BPF_OUTPUT,
 
 		.invalid_fields = PERF_OUTPUT_TRACE,
 	},
@@ -125,7 +127,7 @@ static struct {
 
 		.fields = PERF_OUTPUT_COMM | PERF_OUTPUT_TID |
 				  PERF_OUTPUT_CPU | PERF_OUTPUT_TIME |
-				  PERF_OUTPUT_EVNAME | PERF_OUTPUT_TRACE,
+				  PERF_OUTPUT_EVNAME | PERF_OUTPUT_TRACE
 	},
 
 	[PERF_TYPE_RAW] = {
@@ -138,7 +140,7 @@ static struct {
 			      PERF_OUTPUT_PERIOD |  PERF_OUTPUT_ADDR |
 			      PERF_OUTPUT_DATA_SRC | PERF_OUTPUT_WEIGHT,
 
-		.invalid_fields = PERF_OUTPUT_TRACE,
+		.invalid_fields = PERF_OUTPUT_TRACE | PERF_OUTPUT_BPF_OUTPUT,
 	},
 
 	[PERF_TYPE_BREAKPOINT] = {
@@ -150,7 +152,7 @@ static struct {
 			      PERF_OUTPUT_SYM | PERF_OUTPUT_DSO |
 			      PERF_OUTPUT_PERIOD,
 
-		.invalid_fields = PERF_OUTPUT_TRACE,
+		.invalid_fields = PERF_OUTPUT_TRACE | PERF_OUTPUT_BPF_OUTPUT,
 	},
 };
 
@@ -623,6 +625,84 @@ static void print_sample_flags(u32 flags)
 	printf("  %-4s ", str);
 }
 
+struct printer_data {
+	int line_no;
+	bool hit_nul;
+	bool is_printable;
+};
+
+static void
+print_sample_bpf_output_printer(enum binary_printer_ops op,
+				unsigned int val,
+				void *extra)
+{
+	unsigned char ch = (unsigned char)val;
+	struct printer_data *printer_data = extra;
+
+	switch (op) {
+	case BINARY_PRINT_DATA_BEGIN:
+		printf("\n");
+		break;
+	case BINARY_PRINT_LINE_BEGIN:
+		printf("%17s", !printer_data->line_no ? "BPF output:" :
+						        "           ");
+		break;
+	case BINARY_PRINT_ADDR:
+		printf(" %04x:", val);
+		break;
+	case BINARY_PRINT_NUM_DATA:
+		printf(" %02x", val);
+		break;
+	case BINARY_PRINT_NUM_PAD:
+		printf("   ");
+		break;
+	case BINARY_PRINT_SEP:
+		printf("  ");
+		break;
+	case BINARY_PRINT_CHAR_DATA:
+		if (printer_data->hit_nul && ch)
+			printer_data->is_printable = false;
+
+		if (!isprint(ch)) {
+			printf("%c", '.');
+
+			if (!printer_data->is_printable)
+				break;
+
+			if (ch == '\0')
+				printer_data->hit_nul = true;
+			else
+				printer_data->is_printable = false;
+		} else {
+			printf("%c", ch);
+		}
+		break;
+	case BINARY_PRINT_CHAR_PAD:
+		printf(" ");
+		break;
+	case BINARY_PRINT_LINE_END:
+		printf("\n");
+		printer_data->line_no++;
+		break;
+	case BINARY_PRINT_DATA_END:
+	default:
+		break;
+	}
+}
+
+static void print_sample_bpf_output(struct perf_sample *sample)
+{
+	unsigned int nr_bytes = sample->raw_size;
+	struct printer_data printer_data = {0, false, true};
+
+	print_binary(sample->raw_data, nr_bytes, 8,
+		     print_sample_bpf_output_printer, &printer_data);
+
+	if (printer_data.is_printable && printer_data.hit_nul)
+		printf("%17s \"%s\"\n", "BPF string:",
+		       (char *)(sample->raw_data));
+}
+
 struct perf_script {
 	struct perf_tool	tool;
 	struct perf_session	*session;
@@ -713,6 +793,9 @@ static void process_event(struct perf_script *script, union perf_event *event,
 	else if (PRINT_FIELD(BRSTACKSYM))
 		print_sample_brstacksym(event, sample, thread, attr);
 
+	if (perf_evsel__is_bpf_output(evsel) && PRINT_FIELD(BPF_OUTPUT))
+		print_sample_bpf_output(sample);
+
 	printf("\n");
 }
 
-- 
1.8.3.4

Re: [RFC PATCH 0/2] perf tools: Print bpf-output events in 'perf script'

[Arnaldo Carvalho de Melo]

Em Wed, Feb 24, 2016 at 11:20:43AM +0000, Wang Nan escreveu:
> Hi Arnaldo and Jiri,
> 
>    Glad to see the progress we made today.

Indeed, thanks, tested and applied both of these patches,

- Arnaldo

Re: [RFC PATCH 2/2] perf script: Print bpf-output events in 'perf script'

[Arnaldo Carvalho de Melo]

Em Wed, Feb 24, 2016 at 11:20:45AM +0000, Wang Nan escreveu:
> This patch allows 'perf script' output messages from BPF program.
> For example, use test_bpf_output_3.c at the end of this commit
> message,
> 
>  # ./perf record -e bpf-output/no-inherit,name=evt/ \
>                  -e ./test_bpf_output_3.c/map:channel.event=evt/ \
>                  usleep 100000

Trying to test this with 'perf trace', i.e. to shortcircuit record +
analysis:

[root@jouet bpf]# perf trace -a --ev bpf-output/no-inherit,name=evt/ --ev ./test_bpf_output_3.c/map:channel.event=evt/ --ev 'perf_bpf_probe:*' usleep 100000
Failed to set filter "common_pid != 23954" on event evt with 22 (Invalid argument)

Can't we set tracepoint filters on these events?

- Arnaldo

Re: [RFC PATCH 2/2] perf script: Print bpf-output events in 'perf script'

[Wangnan (F)]

On 2016/2/24 23:19, Arnaldo Carvalho de Melo wrote:
> Em Wed, Feb 24, 2016 at 11:20:45AM +0000, Wang Nan escreveu:
>> This patch allows 'perf script' output messages from BPF program.
>> For example, use test_bpf_output_3.c at the end of this commit
>> message,
>>
>>   # ./perf record -e bpf-output/no-inherit,name=evt/ \
>>                   -e ./test_bpf_output_3.c/map:channel.event=evt/ \
>>                   usleep 100000
> Trying to test this with 'perf trace', i.e. to shortcircuit record +
> analysis:
>
> [root@jouet bpf]# perf trace -a --ev bpf-output/no-inherit,name=evt/ --ev ./test_bpf_output_3.c/map:channel.event=evt/ --ev 'perf_bpf_probe:*' usleep 100000
> Failed to set filter "common_pid != 23954" on event evt with 22 (Invalid argument)
>
> Can't we set tracepoint filters on these events?

No we can't. filters can only be set to tracepoint events, but 
bpf-output is a
software event.

In addition, you don't need
   ... --ev 'perf_bpf_probe:*' ...

because they should be already collected by '--ev ./test_bpf_output_3.c'.

You don't see them because the two kprobe events are filtered out by BPF 
program.
See 'return 0' in func.

Thank you.

[tip:perf/core] perf tools: Make binary data printer code in trace_event public available

[tip-bot for Wang Nan]

Commit-ID:  c339b1a90e6cd638a1d99cbbf49d870ce233198e
Gitweb:     http://git.kernel.org/tip/c339b1a90e6cd638a1d99cbbf49d870ce233198e
Author:     Wang Nan <wangnan0@huawei.com>
AuthorDate: Wed, 24 Feb 2016 11:20:44 +0000
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Wed, 24 Feb 2016 11:38:01 -0300

perf tools: Make binary data printer code in trace_event public available

Move code printing binray data from trace_event() to utils.c and allows
passing different printer. Further commits will use this logic to print
bpf output event.

Signed-off-by: Wang Nan <wangnan0@huawei.com>
Cc: Brendan Gregg <brendan.d.gregg@gmail.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Li Zefan <lizefan@huawei.com>
Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: pi3orama@163.com
Link: http://lkml.kernel.org/r/1456312845-111583-2-git-send-email-wangnan0@huawei.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/util/debug.c | 75 +++++++++++++++++++++++++++++++------------------
 tools/perf/util/util.c  | 37 ++++++++++++++++++++++++
 tools/perf/util/util.h  | 20 +++++++++++++
 3 files changed, 105 insertions(+), 27 deletions(-)

diff --git a/tools/perf/util/debug.c b/tools/perf/util/debug.c
index ff7e86a..8c4212a 100644
--- a/tools/perf/util/debug.c
+++ b/tools/perf/util/debug.c
@@ -106,40 +106,61 @@ int dump_printf(const char *fmt, ...)
 	return ret;
 }
 
+static void trace_event_printer(enum binary_printer_ops op,
+				unsigned int val, void *extra)
+{
+	const char *color = PERF_COLOR_BLUE;
+	union perf_event *event = (union perf_event *)extra;
+	unsigned char ch = (unsigned char)val;
+
+	switch (op) {
+	case BINARY_PRINT_DATA_BEGIN:
+		printf(".");
+		color_fprintf(stdout, color, "\n. ... raw event: size %d bytes\n",
+				event->header.size);
+		break;
+	case BINARY_PRINT_LINE_BEGIN:
+		printf(".");
+		break;
+	case BINARY_PRINT_ADDR:
+		color_fprintf(stdout, color, "  %04x: ", val);
+		break;
+	case BINARY_PRINT_NUM_DATA:
+		color_fprintf(stdout, color, " %02x", val);
+		break;
+	case BINARY_PRINT_NUM_PAD:
+		color_fprintf(stdout, color, "   ");
+		break;
+	case BINARY_PRINT_SEP:
+		color_fprintf(stdout, color, "  ");
+		break;
+	case BINARY_PRINT_CHAR_DATA:
+		color_fprintf(stdout, color, "%c",
+			      isprint(ch) ? ch : '.');
+		break;
+	case BINARY_PRINT_CHAR_PAD:
+		color_fprintf(stdout, color, " ");
+		break;
+	case BINARY_PRINT_LINE_END:
+		color_fprintf(stdout, color, "\n");
+		break;
+	case BINARY_PRINT_DATA_END:
+		printf("\n");
+		break;
+	default:
+		break;
+	}
+}
+
 void trace_event(union perf_event *event)
 {
 	unsigned char *raw_event = (void *)event;
-	const char *color = PERF_COLOR_BLUE;
-	int i, j;
 
 	if (!dump_trace)
 		return;
 
-	printf(".");
-	color_fprintf(stdout, color, "\n. ... raw event: size %d bytes\n",
-		      event->header.size);
-
-	for (i = 0; i < event->header.size; i++) {
-		if ((i & 15) == 0) {
-			printf(".");
-			color_fprintf(stdout, color, "  %04x: ", i);
-		}
-
-		color_fprintf(stdout, color, " %02x", raw_event[i]);
-
-		if (((i & 15) == 15) || i == event->header.size-1) {
-			color_fprintf(stdout, color, "  ");
-			for (j = 0; j < 15-(i & 15); j++)
-				color_fprintf(stdout, color, "   ");
-			for (j = i & ~15; j <= i; j++) {
-				color_fprintf(stdout, color, "%c",
-					      isprint(raw_event[j]) ?
-					      raw_event[j] : '.');
-			}
-			color_fprintf(stdout, color, "\n");
-		}
-	}
-	printf(".\n");
+	print_binary(raw_event, event->header.size, 16,
+		     trace_event_printer, event);
 }
 
 static struct debug_variable {
diff --git a/tools/perf/util/util.c b/tools/perf/util/util.c
index 35b20dd..b7766c5 100644
--- a/tools/perf/util/util.c
+++ b/tools/perf/util/util.c
@@ -14,6 +14,7 @@
 #include <limits.h>
 #include <byteswap.h>
 #include <linux/kernel.h>
+#include <linux/log2.h>
 #include <unistd.h>
 #include "callchain.h"
 #include "strlist.h"
@@ -670,3 +671,39 @@ int fetch_current_timestamp(char *buf, size_t sz)
 
 	return 0;
 }
+
+void print_binary(unsigned char *data, size_t len,
+		  size_t bytes_per_line, print_binary_t printer,
+		  void *extra)
+{
+	size_t i, j, mask;
+
+	if (!printer)
+		return;
+
+	bytes_per_line = roundup_pow_of_two(bytes_per_line);
+	mask = bytes_per_line - 1;
+
+	printer(BINARY_PRINT_DATA_BEGIN, 0, extra);
+	for (i = 0; i < len; i++) {
+		if ((i & mask) == 0) {
+			printer(BINARY_PRINT_LINE_BEGIN, -1, extra);
+			printer(BINARY_PRINT_ADDR, i, extra);
+		}
+
+		printer(BINARY_PRINT_NUM_DATA, data[i], extra);
+
+		if (((i & mask) == mask) || i == len - 1) {
+			for (j = 0; j < mask-(i & mask); j++)
+				printer(BINARY_PRINT_NUM_PAD, -1, extra);
+
+			printer(BINARY_PRINT_SEP, i, extra);
+			for (j = i & ~mask; j <= i; j++)
+				printer(BINARY_PRINT_CHAR_DATA, data[j], extra);
+			for (j = 0; j < mask-(i & mask); j++)
+				printer(BINARY_PRINT_CHAR_PAD, i, extra);
+			printer(BINARY_PRINT_LINE_END, -1, extra);
+		}
+	}
+	printer(BINARY_PRINT_DATA_END, -1, extra);
+}
diff --git a/tools/perf/util/util.h b/tools/perf/util/util.h
index 3dd0408..7015019 100644
--- a/tools/perf/util/util.h
+++ b/tools/perf/util/util.h
@@ -345,4 +345,24 @@ const char *perf_tip(const char *dirpath);
 bool is_regular_file(const char *file);
 int fetch_current_timestamp(char *buf, size_t sz);
 
+enum binary_printer_ops {
+	BINARY_PRINT_DATA_BEGIN,
+	BINARY_PRINT_LINE_BEGIN,
+	BINARY_PRINT_ADDR,
+	BINARY_PRINT_NUM_DATA,
+	BINARY_PRINT_NUM_PAD,
+	BINARY_PRINT_SEP,
+	BINARY_PRINT_CHAR_DATA,
+	BINARY_PRINT_CHAR_PAD,
+	BINARY_PRINT_LINE_END,
+	BINARY_PRINT_DATA_END,
+};
+
+typedef void (*print_binary_t)(enum binary_printer_ops,
+			       unsigned int val,
+			       void *extra);
+
+void print_binary(unsigned char *data, size_t len,
+		  size_t bytes_per_line, print_binary_t printer,
+		  void *extra);
 #endif /* GIT_COMPAT_UTIL_H */

[tip:perf/core] perf script: Print bpf-output events in 'perf script'

[tip-bot for Wang Nan]

Commit-ID:  30372f04c9dc159f99f1f09c61e5e0dbe4c91251
Gitweb:     http://git.kernel.org/tip/30372f04c9dc159f99f1f09c61e5e0dbe4c91251
Author:     Wang Nan <wangnan0@huawei.com>
AuthorDate: Wed, 24 Feb 2016 11:20:45 +0000
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Wed, 24 Feb 2016 12:09:24 -0300

perf script: Print bpf-output events in 'perf script'

This patch allows 'perf script' output messages from BPF program.  For
example, use test_bpf_output_3.c at the end of this commit message,

  # ./perf record -e bpf-output/no-inherit,name=evt/ \
                 -e ./test_bpf_output_3.c/map:channel.event=evt/ \
                 usleep 100000

  # ./perf script
          usleep  4882 21384.532523:                       evt:  ffffffff810e97d1 sys_nanosleep ([kernel.kallsyms])
      BPF output: 0000: 52 61 69 73 65 20 61 20  Raise a
                  0008: 42 50 46 20 65 76 65 6e  BPF even
                  0010: 74 21 00 00              t!..
      BPF string: "Raise a BPF event!"

          usleep  4882 21384.632606:                       evt:  ffffffff8105c609 kretprobe_trampoline_holder ([kernel.kallsyms
      BPF output: 0000: 52 61 69 73 65 20 61 20  Raise a
                  0008: 42 50 46 20 65 76 65 6e  BPF even
                  0010: 74 21 00 00              t!..
      BPF string: "Raise a BPF event!"

Two samples from BPF output are printed by both binary and string
format.

If BPF program output something unprintable, string format is
suppressed.

  /************************ 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__,
  };

  static inline int __attribute__((always_inline))
  func(void *ctx, int type)
  {
         char output_str[] = "Raise a BPF event!";

         perf_event_output(ctx, &channel, get_smp_processor_id(),
                           &output_str, sizeof(output_str));
         return 0;
  }
  SEC("func_begin=sys_nanosleep")
  int func_begin(void *ctx) {return func(ctx, 1);}
  SEC("func_end=sys_nanosleep%return")
  int func_end(void *ctx) { return func(ctx, 2);}
  char _license[] SEC("license") = "GPL";
  int _version SEC("version") = LINUX_VERSION_CODE;
  /************************* END ***************************/

Signed-off-by: Wang Nan <wangnan0@huawei.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Brendan Gregg <brendan.d.gregg@gmail.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Li Zefan <lizefan@huawei.com>
Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: pi3orama@163.com
Link: http://lkml.kernel.org/r/1456312845-111583-3-git-send-email-wangnan0@huawei.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/builtin-script.c | 93 ++++++++++++++++++++++++++++++++++++++++++---
 1 file changed, 88 insertions(+), 5 deletions(-)

diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c
index 8ff5ff0..ec4fbd4 100644
--- a/tools/perf/builtin-script.c
+++ b/tools/perf/builtin-script.c
@@ -61,6 +61,7 @@ enum perf_output_field {
 	PERF_OUTPUT_BRSTACKSYM	    = 1U << 16,
 	PERF_OUTPUT_DATA_SRC	    = 1U << 17,
 	PERF_OUTPUT_WEIGHT	    = 1U << 18,
+	PERF_OUTPUT_BPF_OUTPUT	    = 1U << 19,
 };
 
 struct output_option {
@@ -86,6 +87,7 @@ struct output_option {
 	{.str = "brstacksym", .field = PERF_OUTPUT_BRSTACKSYM},
 	{.str = "data_src", .field = PERF_OUTPUT_DATA_SRC},
 	{.str = "weight",   .field = PERF_OUTPUT_WEIGHT},
+	{.str = "bpf-output",   .field = PERF_OUTPUT_BPF_OUTPUT},
 };
 
 /* default set to maintain compatibility with current format */
@@ -106,7 +108,7 @@ static struct {
 			      PERF_OUTPUT_SYM | PERF_OUTPUT_DSO |
 			      PERF_OUTPUT_PERIOD,
 
-		.invalid_fields = PERF_OUTPUT_TRACE,
+		.invalid_fields = PERF_OUTPUT_TRACE | PERF_OUTPUT_BPF_OUTPUT,
 	},
 
 	[PERF_TYPE_SOFTWARE] = {
@@ -116,7 +118,7 @@ static struct {
 			      PERF_OUTPUT_CPU | PERF_OUTPUT_TIME |
 			      PERF_OUTPUT_EVNAME | PERF_OUTPUT_IP |
 			      PERF_OUTPUT_SYM | PERF_OUTPUT_DSO |
-			      PERF_OUTPUT_PERIOD,
+			      PERF_OUTPUT_PERIOD | PERF_OUTPUT_BPF_OUTPUT,
 
 		.invalid_fields = PERF_OUTPUT_TRACE,
 	},
@@ -126,7 +128,7 @@ static struct {
 
 		.fields = PERF_OUTPUT_COMM | PERF_OUTPUT_TID |
 				  PERF_OUTPUT_CPU | PERF_OUTPUT_TIME |
-				  PERF_OUTPUT_EVNAME | PERF_OUTPUT_TRACE,
+				  PERF_OUTPUT_EVNAME | PERF_OUTPUT_TRACE
 	},
 
 	[PERF_TYPE_RAW] = {
@@ -139,7 +141,7 @@ static struct {
 			      PERF_OUTPUT_PERIOD |  PERF_OUTPUT_ADDR |
 			      PERF_OUTPUT_DATA_SRC | PERF_OUTPUT_WEIGHT,
 
-		.invalid_fields = PERF_OUTPUT_TRACE,
+		.invalid_fields = PERF_OUTPUT_TRACE | PERF_OUTPUT_BPF_OUTPUT,
 	},
 
 	[PERF_TYPE_BREAKPOINT] = {
@@ -151,7 +153,7 @@ static struct {
 			      PERF_OUTPUT_SYM | PERF_OUTPUT_DSO |
 			      PERF_OUTPUT_PERIOD,
 
-		.invalid_fields = PERF_OUTPUT_TRACE,
+		.invalid_fields = PERF_OUTPUT_TRACE | PERF_OUTPUT_BPF_OUTPUT,
 	},
 };
 
@@ -624,6 +626,84 @@ static void print_sample_flags(u32 flags)
 	printf("  %-4s ", str);
 }
 
+struct printer_data {
+	int line_no;
+	bool hit_nul;
+	bool is_printable;
+};
+
+static void
+print_sample_bpf_output_printer(enum binary_printer_ops op,
+				unsigned int val,
+				void *extra)
+{
+	unsigned char ch = (unsigned char)val;
+	struct printer_data *printer_data = extra;
+
+	switch (op) {
+	case BINARY_PRINT_DATA_BEGIN:
+		printf("\n");
+		break;
+	case BINARY_PRINT_LINE_BEGIN:
+		printf("%17s", !printer_data->line_no ? "BPF output:" :
+						        "           ");
+		break;
+	case BINARY_PRINT_ADDR:
+		printf(" %04x:", val);
+		break;
+	case BINARY_PRINT_NUM_DATA:
+		printf(" %02x", val);
+		break;
+	case BINARY_PRINT_NUM_PAD:
+		printf("   ");
+		break;
+	case BINARY_PRINT_SEP:
+		printf("  ");
+		break;
+	case BINARY_PRINT_CHAR_DATA:
+		if (printer_data->hit_nul && ch)
+			printer_data->is_printable = false;
+
+		if (!isprint(ch)) {
+			printf("%c", '.');
+
+			if (!printer_data->is_printable)
+				break;
+
+			if (ch == '\0')
+				printer_data->hit_nul = true;
+			else
+				printer_data->is_printable = false;
+		} else {
+			printf("%c", ch);
+		}
+		break;
+	case BINARY_PRINT_CHAR_PAD:
+		printf(" ");
+		break;
+	case BINARY_PRINT_LINE_END:
+		printf("\n");
+		printer_data->line_no++;
+		break;
+	case BINARY_PRINT_DATA_END:
+	default:
+		break;
+	}
+}
+
+static void print_sample_bpf_output(struct perf_sample *sample)
+{
+	unsigned int nr_bytes = sample->raw_size;
+	struct printer_data printer_data = {0, false, true};
+
+	print_binary(sample->raw_data, nr_bytes, 8,
+		     print_sample_bpf_output_printer, &printer_data);
+
+	if (printer_data.is_printable && printer_data.hit_nul)
+		printf("%17s \"%s\"\n", "BPF string:",
+		       (char *)(sample->raw_data));
+}
+
 struct perf_script {
 	struct perf_tool	tool;
 	struct perf_session	*session;
@@ -731,6 +811,9 @@ static void process_event(struct perf_script *script, union perf_event *event,
 	else if (PRINT_FIELD(BRSTACKSYM))
 		print_sample_brstacksym(event, sample, thread, attr);
 
+	if (perf_evsel__is_bpf_output(evsel) && PRINT_FIELD(BPF_OUTPUT))
+		print_sample_bpf_output(sample);
+
 	printf("\n");
 }
 

Re: [RFC PATCH 2/2] perf script: Print bpf-output events in 'perf script'

[Arnaldo Carvalho de Melo]

Em Thu, Feb 25, 2016 at 12:11:11PM +0800, Wangnan (F) escreveu:
> 
> 
> On 2016/2/24 23:19, Arnaldo Carvalho de Melo wrote:
> >Em Wed, Feb 24, 2016 at 11:20:45AM +0000, Wang Nan escreveu:
> >>This patch allows 'perf script' output messages from BPF program.
> >>For example, use test_bpf_output_3.c at the end of this commit
> >>message,
> >>
> >>  # ./perf record -e bpf-output/no-inherit,name=evt/ \
> >>                  -e ./test_bpf_output_3.c/map:channel.event=evt/ \
> >>                  usleep 100000
> >Trying to test this with 'perf trace', i.e. to shortcircuit record +
> >analysis:
> >
> >[root@jouet bpf]# perf trace -a --ev bpf-output/no-inherit,name=evt/ --ev ./test_bpf_output_3.c/map:channel.event=evt/ --ev 'perf_bpf_probe:*' usleep 100000
> >Failed to set filter "common_pid != 23954" on event evt with 22 (Invalid argument)
> >
> >Can't we set tracepoint filters on these events?
 
> No we can't. filters can only be set to tracepoint events, but
> bpf-output is a software event.

Gack, should've checked that, I somehow thought that it was a tracepoint
event of some sort.
 
> In addition, you don't need
>   ... --ev 'perf_bpf_probe:*' ...
> 
> because they should be already collected by '--ev ./test_bpf_output_3.c'.

Right, that was me trying to be clever 8-)
 
> You don't see them because the two kprobe events are filtered out by
> BPF program.  See 'return 0' in func.

Thanks for reminding about this part...
 
> Thank you.