perf/core improvements and fixes

Hi Ingo,

Please consider pulling,

- Arnaldo

The following changes since commit 675965b00d734c985e4285f5bec7e524d15fc4e1:

perf: Export perf_event_sysfs_show() (2016-02-29 09:35:27 +0100)

are available in the git repository at:

git://git.kernel.org/pub/scm/linux/kernel/git/acme/linux.git tags/perf-core-for-mingo-20160229

for you to fetch changes up to 575a02e00b11eecbbabcb1eb22eab4c68e91ae77:

perf record: Ensure return non-zero rc when mmap fail (2016-02-29 12:44:15 -0300)

----------------------------------------------------------------
perf/core improvements and fixes:

User visible:

- Check existence of frontend/backed stalled cycles in 'perf stat' (Andi Kleen)

- Avoid installing .o files from tools/lib/ into the python extension (Jiri Olsa)

- Rename the tracepoint '/format' field that carries the syscall ID from 'nr', that is also the name of some syscalls arguments, to "__syscall_nr", to avoid having multiple fields with the same name, that was breaking the python script skeleton generator from perf.data files (Taeung Song)

- Support converting data from bpf events in 'perf data' (Wang Nan)

Infrastructure:

- Split libtraceevent's pevent_print_event() (Steven Rostedt)

- Librarize some 'perf record' bits to allow handling multiple perf.data files per session (Wang Nan)

- Ensure return non-zero rc when mmap fail in 'perf record' (Wang Nan)

----------------------------------------------------------------
Andi Kleen (1):
perf stat: Check existence of frontend/backed stalled cycles

Jiri Olsa (1):
perf tools: Fix python extension build

Steven Rostedt (1):
tools lib traceevent: Split pevent_print_event() into specific functionality functions

Taeung Song (2):
perf trace: Check and discard not only 'nr' but also '__syscall_nr' tracing/syscalls: Rename "/format" tracepoint field name "nr" to "__syscall_nr:

Wang Nan (6):
perf data: Support converting data from bpf_perf_event_output() perf data: Explicitly set byte order for integer types perf record: Use WARN_ONCE to replace 'if' condition perf record: Extract synthesize code to record__synthesize() perf record: Introduce record__finish_output() to finish a perf.data perf record: Ensure return non-zero rc when mmap fail

 kernel/trace/trace_syscalls.c      |  16 ++--
 tools/lib/traceevent/event-parse.c | 136 +++++++++++++++++++++++-------
 tools/lib/traceevent/event-parse.h |  13 +++
 tools/perf/builtin-record.c        | 168 ++++++++++++++++++++++---------------
 tools/perf/builtin-stat.c          |  22 ++++-
 tools/perf/builtin-trace.c         |   8 +-
 tools/perf/util/data-convert-bt.c  | 118 +++++++++++++++++++++++++-
 tools/perf/util/setup.py           |   4 +
 8 files changed, 372 insertions(+), 113 deletions(-)

From: Jiri Olsa <[email protected]>

The util/python-ext-sources file contains source files required to build the python extension relative to $(srctree)/tools/perf,

Such a file path $(FILE).c is handed over to the python extension build system, which builds the final object in the $(PYTHON_EXTBUILD)/tmp/$(FILE).o path.

After the build is done all files from $(PYTHON_EXTBUILD)lib/ are carried as the result binaries.

Above system fails when we add source file relative to ../lib, which we do for:

../lib/bitmap.c
../lib/find_bit.c
../lib/hweight.c
../lib/rbtree.c

All above objects will be built like:

  $(PYTHON_EXTBUILD)/tmp/../lib/bitmap.c
  $(PYTHON_EXTBUILD)/tmp/../lib/find_bit.c
  $(PYTHON_EXTBUILD)/tmp/../lib/hweight.c
  $(PYTHON_EXTBUILD)/tmp/../lib/rbtree.c

which accidentally happens to be final library path:

  $(PYTHON_EXTBUILD)/lib/

Changing setup.py to pass full paths of source files to Extension build class and thus keep all built objects under $(PYTHON_EXTBUILD)tmp directory.

---
 tools/perf/util/setup.py | 4 ++++
 1 file changed, 4 insertions(+)

index 1833103768cb..c8680984d2d6 100644
@@ -22,6 +22,7 @@ cflags = getenv('CFLAGS', '').split()
 # switch off several checks (need to be at the end of cflags list)
 cflags += ['-fno-strict-aliasing', '-Wno-write-strings', '-Wno-unused-parameter' ]
 
+src_perf  = getenv('srctree') + '/tools/perf'
 build_lib = getenv('PYTHON_EXTBUILD_LIB')
 build_tmp = getenv('PYTHON_EXTBUILD_TMP')
 libtraceevent = getenv('LIBTRACEEVENT')

@@ -30,6 +31,9 @@ libapikfs = getenv('LIBAPI')
 ext_sources = [f.strip() for f in file('util/python-ext-sources')
 				if len(f.strip()) > 0 and f[0] != '#']
 
+# use full paths with source files
+ext_sources = map(lambda x: '%s/%s' % (src_perf, x) , ext_sources)
+
 perf = Extension('perf',
 		  sources = ext_sources,
 		  include_dirs = ['util/include'],

2.5.0

From: Taeung Song <[email protected]>

Format fields of a syscall have the first variable '__syscall_nr' or 'nr' that mean the syscall number. But it isn't relevant here so drop it.

'nr' among fields of syscall was renamed '__syscall_nr'. So add exception handling to drop '__syscall_nr' and modify the comment for this excpetion handling.

---
 tools/perf/builtin-trace.c | 8 ++++++--
 1 file changed, 6 insertions(+), 2 deletions(-)

index 26a337f939d8..8dc98c598b1a 100644
@@ -1725,8 +1725,12 @@ static int trace__read_syscall_info(struct trace *trace, int id)
 
 	sc->args = sc->tp_format->format.fields;
 	sc->nr_args = sc->tp_format->format.nr_fields;
-	/* drop nr field - not relevant here; does not exist on older kernels */
-	if (sc->args && strcmp(sc->args->name, "nr") == 0) {
+	/*
+	 * We need to check and discard the first variable '__syscall_nr'
+	 * or 'nr' that mean the syscall number. It is needless here.
+	 * So drop '__syscall_nr' or 'nr' field but does not exist on older kernels.
+	 */
+	if (sc->args && (!strcmp(sc->args->name, "__syscall_nr") || !strcmp(sc->args->name, "nr"))) {
 		sc->args = sc->args->next;
 		--sc->nr_args;
 	}

2.5.0

From: Taeung Song <[email protected]>

Some tracepoint have multiple fields with the same name, "nr", the first one is a unique syscall ID, the other is a syscall argument:

  # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_io_getevents/format
  name: sys_enter_io_getevents
  ID: 747
  format:
 	field:unsigned short common_type;	offset:0;	size:2;	signed:0;
 	field:unsigned char common_flags;	offset:2;	size:1;	signed:0;
 	field:unsigned char common_preempt_count;	offset:3;	size:1;	signed:0;
 	field:int common_pid;	offset:4;	size:4;	signed:1;

field:int nr; offset:8; size:4; signed:1;
field:aio_context_t ctx_id; offset:16; size:8; signed:0;
field:long min_nr; offset:24; size:8; signed:0;
field:long nr; offset:32; size:8; signed:0;
field:struct io_event * events; offset:40; size:8; signed:0;
field:struct timespec * timeout; offset:48; size:8; signed:0;

print fmt: "ctx_id: 0x%08lx, min_nr: 0x%08lx, nr: 0x%08lx, events: 0x%08lx, timeout: 0x%08lx", ((unsigned long)(REC->ctx_id)), ((unsigned long)(REC->min_nr)), ((unsigned long)(REC->nr)), ((unsigned long)(REC->events)), ((unsigned long)(REC->timeout)) #

Fix it by renaming the "/format" common tracepoint field "nr" to "__syscall_nr".

---
 kernel/trace/trace_syscalls.c | 16 +++++++++-------
 1 file changed, 9 insertions(+), 7 deletions(-)

index 0655afbea83f..d1663083d903 100644
@@ -186,11 +186,11 @@ print_syscall_exit(struct trace_iterator *iter, int flags,
 
 extern char *__bad_type_size(void);
 
-#define SYSCALL_FIELD(type, name)					\
-	sizeof(type) != sizeof(trace.name) ?				\
+#define SYSCALL_FIELD(type, field, name)				\
+	sizeof(type) != sizeof(trace.field) ?				\
 		__bad_type_size() :					\
-		#type, #name, offsetof(typeof(trace), name),		\
-		sizeof(trace.name), is_signed_type(type)
+		#type, #name, offsetof(typeof(trace), field),		\
+		sizeof(trace.field), is_signed_type(type)
 
 static int __init
 __set_enter_print_fmt(struct syscall_metadata *entry, char *buf, int len)

@@ -261,7 +261,8 @@ static int __init syscall_enter_define_fields(struct trace_event_call *call)
 	int i;
 	int offset = offsetof(typeof(trace), args);
 
-	ret = trace_define_field(call, SYSCALL_FIELD(int, nr), FILTER_OTHER);
+	ret = trace_define_field(call, SYSCALL_FIELD(int, nr, __syscall_nr),
+				 FILTER_OTHER);
 	if (ret)
 		return ret;
 

@@ -281,11 +282,12 @@ static int __init syscall_exit_define_fields(struct trace_event_call *call)
 	struct syscall_trace_exit trace;
 	int ret;
 
-	ret = trace_define_field(call, SYSCALL_FIELD(int, nr), FILTER_OTHER);
+	ret = trace_define_field(call, SYSCALL_FIELD(int, nr, __syscall_nr),
+				 FILTER_OTHER);
 	if (ret)
 		return ret;
 
-	ret = trace_define_field(call, SYSCALL_FIELD(long, ret),
+	ret = trace_define_field(call, SYSCALL_FIELD(long, ret, ret),
 				 FILTER_OTHER);
 
 	return ret;

2.5.0

From: Steven Rostedt <[email protected]>

Currently there's a single function that is used to display a record's data in human readable format. That's pevent_print_event(). Unfortunately, this gives little room for adding other output within the line without updating that function call.

I've decided to split that function into 3 parts.

pevent_print_event_task() which prints the task comm, pid and the CPU pevent_print_event_time() which outputs the record's timestamp pevent_print_event_data() which outputs the rest of the event data.

pevent_print_event() now simply calls these three functions.

To save time from doing the search for event from the record's type, I created a new helper function called pevent_find_event_by_record(), which returns the record's event, and this event has to be passed to the above functions.

---
 tools/lib/traceevent/event-parse.c | 136 ++++++++++++++++++++++++++++---------
 tools/lib/traceevent/event-parse.h |  13 ++++
 2 files changed, 117 insertions(+), 32 deletions(-)

index 575e75174087..9a1e48afcf89 100644
@@ -5339,41 +5339,45 @@ static bool is_timestamp_in_us(char *trace_clock, bool use_trace_clock)
 	return false;
 }
 
-void pevent_print_event(struct pevent *pevent, struct trace_seq *s,
-			struct pevent_record *record, bool use_trace_clock)
+/**
+ * pevent_find_event_by_record - return the event from a given record
+ * @pevent: a handle to the pevent
+ * @record: The record to get the event from
+ *
+ * Returns the associated event for a given record, or NULL if non is
+ * is found.
+ */
+struct event_format *
+pevent_find_event_by_record(struct pevent *pevent, struct pevent_record *record)
 {
-	static const char *spaces = "                    "; /* 20 spaces */
-	struct event_format *event;
-	unsigned long secs;
-	unsigned long usecs;
-	unsigned long nsecs;
-	const char *comm;
-	void *data = record->data;
 	int type;
-	int pid;
-	int len;
-	int p;
-	bool use_usec_format;
-
-	use_usec_format = is_timestamp_in_us(pevent->trace_clock,
-							use_trace_clock);
-	if (use_usec_format) {
-		secs = record->ts / NSECS_PER_SEC;
-		nsecs = record->ts - secs * NSECS_PER_SEC;
-	}
 
 	if (record->size < 0) {
 		do_warning("ug! negative record size %d", record->size);
-		return;
+		return NULL;
 	}
 
-	type = trace_parse_common_type(pevent, data);
+	type = trace_parse_common_type(pevent, record->data);
 
-	event = pevent_find_event(pevent, type);
-	if (!event) {
-		do_warning("ug! no event found for type %d", type);
-		return;
-	}
+	return pevent_find_event(pevent, type);
+}
+
+/**
+ * pevent_print_event_task - Write the event task comm, pid and CPU
+ * @pevent: a handle to the pevent
+ * @s: the trace_seq to write to
+ * @event: the handle to the record's event
+ * @record: The record to get the event from
+ *
+ * Writes the tasks comm, pid and CPU to @s.
+ */
+void pevent_print_event_task(struct pevent *pevent, struct trace_seq *s,
+			     struct event_format *event,
+			     struct pevent_record *record)
+{
+	void *data = record->data;
+	const char *comm;
+	int pid;
 
 	pid = parse_common_pid(pevent, data);
 	comm = find_cmdline(pevent, pid);

@@ -5381,9 +5385,43 @@ void pevent_print_event(struct pevent *pevent, struct trace_seq *s,
 	if (pevent->latency_format) {
 		trace_seq_printf(s, "%8.8s-%-5d %3d",
 		       comm, pid, record->cpu);
-		pevent_data_lat_fmt(pevent, s, record);
 	} else
 		trace_seq_printf(s, "%16s-%-5d [%03d]", comm, pid, record->cpu);
+}
+
+/**
+ * pevent_print_event_time - Write the event timestamp
+ * @pevent: a handle to the pevent
+ * @s: the trace_seq to write to
+ * @event: the handle to the record's event
+ * @record: The record to get the event from
+ * @use_trace_clock: Set to parse according to the @pevent->trace_clock
+ *
+ * Writes the timestamp of the record into @s.
+ */
+void pevent_print_event_time(struct pevent *pevent, struct trace_seq *s,
+			     struct event_format *event,
+			     struct pevent_record *record,
+			     bool use_trace_clock)
+{
+	unsigned long secs;
+	unsigned long usecs;
+	unsigned long nsecs;
+	int p;
+	bool use_usec_format;
+
+	use_usec_format = is_timestamp_in_us(pevent->trace_clock,
+							use_trace_clock);
+	if (use_usec_format) {
+		secs = record->ts / NSECS_PER_SEC;
+		nsecs = record->ts - secs * NSECS_PER_SEC;
+	}
+
+	if (pevent->latency_format) {
+		trace_seq_printf(s, " %3d", record->cpu);
+		pevent_data_lat_fmt(pevent, s, record);
+	} else
+		trace_seq_printf(s, " [%03d]", record->cpu);
 
 	if (use_usec_format) {
 		if (pevent->flags & PEVENT_NSEC_OUTPUT) {

@@ -5394,11 +5432,28 @@ void pevent_print_event(struct pevent *pevent, struct trace_seq *s,
 			p = 6;
 		}
 
-		trace_seq_printf(s, " %5lu.%0*lu: %s: ",
-					secs, p, usecs, event->name);
+		trace_seq_printf(s, " %5lu.%0*lu:", secs, p, usecs);
 	} else
-		trace_seq_printf(s, " %12llu: %s: ",
-					record->ts, event->name);
+		trace_seq_printf(s, " %12llu:", record->ts);
+}
+
+/**
+ * pevent_print_event_data - Write the event data section
+ * @pevent: a handle to the pevent
+ * @s: the trace_seq to write to
+ * @event: the handle to the record's event
+ * @record: The record to get the event from
+ *
+ * Writes the parsing of the record's data to @s.
+ */
+void pevent_print_event_data(struct pevent *pevent, struct trace_seq *s,
+			     struct event_format *event,
+			     struct pevent_record *record)
+{
+	static const char *spaces = "                    "; /* 20 spaces */
+	int len;
+
+	trace_seq_printf(s, " %s: ", event->name);
 
 	/* Space out the event names evenly. */
 	len = strlen(event->name);

@@ -5408,6 +5463,23 @@ void pevent_print_event(struct pevent *pevent, struct trace_seq *s,
 	pevent_event_info(s, event, record);
 }
 
+void pevent_print_event(struct pevent *pevent, struct trace_seq *s,
+			struct pevent_record *record, bool use_trace_clock)
+{
+	struct event_format *event;
+
+	event = pevent_find_event_by_record(pevent, record);
+	if (!event) {
+		do_warning("ug! no event found for type %d",
+			   trace_parse_common_type(pevent, record->data));
+		return;
+	}
+
+	pevent_print_event_task(pevent, s, event, record);
+	pevent_print_event_time(pevent, s, event, record, use_trace_clock);
+	pevent_print_event_data(pevent, s, event, record);
+}
+
 static int events_id_cmp(const void *a, const void *b)
 {
 	struct event_format * const * ea = a;

index 706d9bc24066..9ffde377e89d 100644
@@ -628,6 +628,16 @@ int pevent_register_print_string(struct pevent *pevent, const char *fmt,
 				 unsigned long long addr);
 int pevent_pid_is_registered(struct pevent *pevent, int pid);
 
+void pevent_print_event_task(struct pevent *pevent, struct trace_seq *s,
+			     struct event_format *event,
+			     struct pevent_record *record);
+void pevent_print_event_time(struct pevent *pevent, struct trace_seq *s,
+			     struct event_format *event,
+			     struct pevent_record *record,
+			     bool use_trace_clock);
+void pevent_print_event_data(struct pevent *pevent, struct trace_seq *s,
+			     struct event_format *event,
+			     struct pevent_record *record);
 void pevent_print_event(struct pevent *pevent, struct trace_seq *s,
 			struct pevent_record *record, bool use_trace_clock);
 

@@ -694,6 +704,9 @@ struct event_format *pevent_find_event(struct pevent *pevent, int id);
 struct event_format *
 pevent_find_event_by_name(struct pevent *pevent, const char *sys, const char *name);
 
+struct event_format *
+pevent_find_event_by_record(struct pevent *pevent, struct pevent_record *record);
+
 void pevent_data_lat_fmt(struct pevent *pevent,
 			 struct trace_seq *s, struct pevent_record *record);
 int pevent_data_type(struct pevent *pevent, struct pevent_record *rec);

2.5.0

From: Andi Kleen <[email protected]>

Only put the frontend/backend stalled cycles into the default perf stat events when the CPU actually supports them.

This avoids empty columns with --metric-only on newer Intel CPUs.

Committer note:

Before:

  $ perf stat ls
  a.patch

Performance counter stats for 'ls':

         0.822067 task-clock (msec)   #   0.873 CPUs utilized   (82.26%)
                0 context-switches    #   0.000 K/sec           (82.26%)
                0 cpu-migrations      #   0.000 K/sec           (82.26%)
              125 page-faults         #   0.152 M/sec           (82.26%)
        2,516,127 cycles              #   3.061 GHz             (82.84%)
  <not supported> stalled-cycles-frontend
  <not supported> stalled-cycles-backend
        2,430,467 instructions        #   0.97  insn per cycle  (82.84%)
          486,235 branches            # 591.479 M/sec           (82.84%)
           18,389 branch-misses       #   3.78% of all branches (82.84%)

      0.000941536 seconds time elapsed

$

After:

  $ perf stat ls
  a.patch

Performance counter stats for 'ls':

         0.824919 task-clock (msec)   #   0.893 CPUs utilized   (85.47%)
                0 context-switches    #   0.000 K/sec           (85.47%)
                0 cpu-migrations      #   0.000 K/sec           (85.47%)
              124 page-faults         #   0.150 M/sec           (85.47%)
          2521790 cycles              #   3.057 GHz             (86.15%)
          2364913 instructions        #   0.94  insn per cycle  (86.15%)
           471970 branches            # 572.141 M/sec           (86.15%)
            16935 branch-misses       #   3.59% of all branches (86.15%)

      0.000923397 seconds time elapsed

$

---
 tools/perf/builtin-stat.c | 22 ++++++++++++++++++++--
 1 file changed, 20 insertions(+), 2 deletions(-)

index 8c0bc0fe5179..24f222dd2a8a 100644
@@ -1441,7 +1441,7 @@ static int perf_stat_init_aggr_mode_file(struct perf_stat *st)
  */
 static int add_default_attributes(void)
 {
-	struct perf_event_attr default_attrs[] = {
+	struct perf_event_attr default_attrs0[] = {
 
   { .type = PERF_TYPE_SOFTWARE, .config = PERF_COUNT_SW_TASK_CLOCK		},
   { .type = PERF_TYPE_SOFTWARE, .config = PERF_COUNT_SW_CONTEXT_SWITCHES	},

@@ -1449,8 +1449,14 @@ static int add_default_attributes(void)
   { .type = PERF_TYPE_SOFTWARE, .config = PERF_COUNT_SW_PAGE_FAULTS		},
 
   { .type = PERF_TYPE_HARDWARE, .config = PERF_COUNT_HW_CPU_CYCLES		},
+};
+	struct perf_event_attr frontend_attrs[] = {
   { .type = PERF_TYPE_HARDWARE, .config = PERF_COUNT_HW_STALLED_CYCLES_FRONTEND	},
+};
+	struct perf_event_attr backend_attrs[] = {
   { .type = PERF_TYPE_HARDWARE, .config = PERF_COUNT_HW_STALLED_CYCLES_BACKEND	},
+};
+	struct perf_event_attr default_attrs1[] = {
   { .type = PERF_TYPE_HARDWARE, .config = PERF_COUNT_HW_INSTRUCTIONS		},
   { .type = PERF_TYPE_HARDWARE, .config = PERF_COUNT_HW_BRANCH_INSTRUCTIONS	},
   { .type = PERF_TYPE_HARDWARE, .config = PERF_COUNT_HW_BRANCH_MISSES		},

@@ -1567,7 +1573,19 @@ static int add_default_attributes(void)
 	}
 
 	if (!evsel_list->nr_entries) {
-		if (perf_evlist__add_default_attrs(evsel_list, default_attrs) < 0)
+		if (perf_evlist__add_default_attrs(evsel_list, default_attrs0) < 0)
+			return -1;
+		if (pmu_have_event("cpu", "stalled-cycles-frontend")) {
+			if (perf_evlist__add_default_attrs(evsel_list,
+						frontend_attrs) < 0)
+				return -1;
+		}
+		if (pmu_have_event("cpu", "stalled-cycles-backend")) {
+			if (perf_evlist__add_default_attrs(evsel_list,
+						backend_attrs) < 0)
+				return -1;
+		}
+		if (perf_evlist__add_default_attrs(evsel_list, default_attrs1) < 0)
 			return -1;
 	}
 

2.5.0

Btw., the output format regression is visible in this changelog already...

Thanks,

Ingo

Em Thu, Mar 03, 2016 at 09:28:18AM +0100, Ingo Molnar escreveu:

Right, uf, should've pick this up at this point :-\

Will go back and fix it up, so that we don't introduce a regression.

- Arnaldo

Em Thu, Mar 03, 2016 at 09:49:00AM -0300, Arnaldo Carvalho de Melo escreveu:

Well, in this case its not a matter of fixing the patch, but making sure that Jiri's locale pmu parsing fix comes before this patch, so inserting a patch, will do.

- Arnaldo

From: Wang Nan <[email protected]>

bpf_perf_event_output() outputs data through sample->raw_data. This patch adds support to convert those data into CTF. A python script then can be used to process output data from BPF programs.

Test result:

  # cat ./test_bpf_output_2.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__,
};

static inline int __attribute__((always_inline)) func(void *ctx, int type)
{
struct {
u64 ktime;
int type;
} __attribute__((packed)) output_data; char error_data[] = "Error: failed to output\n"; int err;

output_data.type = type;
output_data.ktime = ktime_get_ns();
err = perf_event_output(ctx, &channel, get_smp_processor_id(),
&output_data, sizeof(output_data));
if (err)
trace_printk(error_data, sizeof(error_data));
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 ***************************/

  # ./perf record -e bpf-output/no-inherit,name=evt/ \
                 -e ./test_bpf_output_2.c/map:channel.event=evt/ \
                 usleep 100000
  [ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 0.012 MB perf.data (2 samples) ]

  # ./perf script
          usleep 14942 92503.198504: evt:  ffffffff810e0ba1 sys_nanosleep (/lib/modules/4.3.0....
          usleep 14942 92503.298562: evt:  ffffffff810585e9 kretprobe_trampoline_holder (/lib....

  # ./perf data convert --to-ctf ./out.ctf
  [ perf data convert: Converted 'perf.data' into CTF data './out.ctf' ]
  [ perf data convert: Converted and wrote 0.000 MB (2 samples) ]

  # babeltrace ./out.ctf
  [01:41:43.198504134] (+?.?????????) evt: { cpu_id = 0 }, { perf_ip = 0xFFFFFFFF810E0BA1, perf_tid = 14942, perf_pid = 14942, perf_id = 1044, raw_len = 3, raw_data = [ [0] = 0x32C0C07B, [1] = 0x5421, [2] = 0x1 ] }
  [01:41:43.298562257] (+0.100058123) evt: { cpu_id = 0 }, { perf_ip = 0xFFFFFFFF810585E9, perf_tid = 14942, perf_pid = 14942, perf_id = 1044, raw_len = 3, raw_data = [ [0] = 0x38B77FAA, [1] = 0x5421, [2] = 0x2 ] }

  # cat ./test_bpf_output_2.py
  from babeltrace import TraceCollection
  tc = TraceCollection()
  tc.add_trace('./out.ctf', 'ctf')
  d = {1:[], 2:[]}
  for event in tc.events:
     if not event.name.startswith('evt'):
         continue
     raw_data = event['raw_data']
     (time, type) = ((raw_data[0] + (raw_data[1] << 32)), raw_data[2])
     d[type].append(time)
  print(list(map(lambda i: d[2][i] - d[1][i], range(len(d[1])))));

  # python3 ./test_bpf_output_2.py
  [100056879]

Committer note:

Make sure you have python3-devel installed, not python-devel, which may be for python2, which will lead to some "PyInstance_Type" errors. Also make sure that you use the right libbabeltrace, because it is shipped in Fedora, for instance, but an older version.

To build libbabeltrace's python binding one also needs to use:

./configure --enable-python-bindings

And then set PYTHONPATH=/usr/local/lib64/python3.4/site-packages/.

---
 tools/perf/util/data-convert-bt.c | 112 +++++++++++++++++++++++++++++++++++++-
 1 file changed, 111 insertions(+), 1 deletion(-)

index 6729f4d9df7c..1f608a6e2c14 100644
@@ -352,6 +352,84 @@ static int add_tracepoint_values(struct ctf_writer *cw,
 	return ret;
 }
 
+static int
+add_bpf_output_values(struct bt_ctf_event_class *event_class,
+		      struct bt_ctf_event *event,
+		      struct perf_sample *sample)
+{
+	struct bt_ctf_field_type *len_type, *seq_type;
+	struct bt_ctf_field *len_field, *seq_field;
+	unsigned int raw_size = sample->raw_size;
+	unsigned int nr_elements = raw_size / sizeof(u32);
+	unsigned int i;
+	int ret;
+
+	if (nr_elements * sizeof(u32) != raw_size)
+		pr_warning("Incorrect raw_size (%u) in bpf output event, skip %lu bytes\n",
+			   raw_size, nr_elements * sizeof(u32) - raw_size);
+
+	len_type = bt_ctf_event_class_get_field_by_name(event_class, "raw_len");
+	len_field = bt_ctf_field_create(len_type);
+	if (!len_field) {
+		pr_err("failed to create 'raw_len' for bpf output event\n");
+		ret = -1;
+		goto put_len_type;
+	}
+
+	ret = bt_ctf_field_unsigned_integer_set_value(len_field, nr_elements);
+	if (ret) {
+		pr_err("failed to set field value for raw_len\n");
+		goto put_len_field;
+	}
+	ret = bt_ctf_event_set_payload(event, "raw_len", len_field);
+	if (ret) {
+		pr_err("failed to set payload to raw_len\n");
+		goto put_len_field;
+	}
+
+	seq_type = bt_ctf_event_class_get_field_by_name(event_class, "raw_data");
+	seq_field = bt_ctf_field_create(seq_type);
+	if (!seq_field) {
+		pr_err("failed to create 'raw_data' for bpf output event\n");
+		ret = -1;
+		goto put_seq_type;
+	}
+
+	ret = bt_ctf_field_sequence_set_length(seq_field, len_field);
+	if (ret) {
+		pr_err("failed to set length of 'raw_data'\n");
+		goto put_seq_field;
+	}
+
+	for (i = 0; i < nr_elements; i++) {
+		struct bt_ctf_field *elem_field =
+			bt_ctf_field_sequence_get_field(seq_field, i);
+
+		ret = bt_ctf_field_unsigned_integer_set_value(elem_field,
+				((u32 *)(sample->raw_data))[i]);
+
+		bt_ctf_field_put(elem_field);
+		if (ret) {
+			pr_err("failed to set raw_data[%d]\n", i);
+			goto put_seq_field;
+		}
+	}
+
+	ret = bt_ctf_event_set_payload(event, "raw_data", seq_field);
+	if (ret)
+		pr_err("failed to set payload for raw_data\n");
+
+put_seq_field:
+	bt_ctf_field_put(seq_field);
+put_seq_type:
+	bt_ctf_field_type_put(seq_type);
+put_len_field:
+	bt_ctf_field_put(len_field);
+put_len_type:
+	bt_ctf_field_type_put(len_type);
+	return ret;
+}
+
 static int add_generic_values(struct ctf_writer *cw,
 			      struct bt_ctf_event *event,
 			      struct perf_evsel *evsel,

@@ -597,6 +675,12 @@ static int process_sample_event(struct perf_tool *tool,
 			return -1;
 	}
 
+	if (perf_evsel__is_bpf_output(evsel)) {
+		ret = add_bpf_output_values(event_class, event, sample);
+		if (ret)
+			return -1;
+	}
+
 	cs = ctf_stream(cw, get_sample_cpu(cw, sample, evsel));
 	if (cs) {
 		if (is_flush_needed(cs))

@@ -744,6 +828,25 @@ static int add_tracepoint_types(struct ctf_writer *cw,
 	return ret;
 }
 
+static int add_bpf_output_types(struct ctf_writer *cw,
+				struct bt_ctf_event_class *class)
+{
+	struct bt_ctf_field_type *len_type = cw->data.u32;
+	struct bt_ctf_field_type *seq_base_type = cw->data.u32_hex;
+	struct bt_ctf_field_type *seq_type;
+	int ret;
+
+	ret = bt_ctf_event_class_add_field(class, len_type, "raw_len");
+	if (ret)
+		return ret;
+
+	seq_type = bt_ctf_field_type_sequence_create(seq_base_type, "raw_len");
+	if (!seq_type)
+		return -1;
+
+	return bt_ctf_event_class_add_field(class, seq_type, "raw_data");
+}
+
 static int add_generic_types(struct ctf_writer *cw, struct perf_evsel *evsel,
 			     struct bt_ctf_event_class *event_class)
 {

@@ -755,7 +858,8 @@ static int add_generic_types(struct ctf_writer *cw, struct perf_evsel *evsel,
 	 *                              ctf event header
 	 *   PERF_SAMPLE_READ         - TODO
 	 *   PERF_SAMPLE_CALLCHAIN    - TODO
-	 *   PERF_SAMPLE_RAW          - tracepoint fields are handled separately
+	 *   PERF_SAMPLE_RAW          - tracepoint fields and BPF output
+	 *                              are handled separately
 	 *   PERF_SAMPLE_BRANCH_STACK - TODO
 	 *   PERF_SAMPLE_REGS_USER    - TODO
 	 *   PERF_SAMPLE_STACK_USER   - TODO

@@ -824,6 +928,12 @@ static int add_event(struct ctf_writer *cw, struct perf_evsel *evsel)
 			goto err;
 	}
 
+	if (perf_evsel__is_bpf_output(evsel)) {
+		ret = add_bpf_output_types(cw, event_class);
+		if (ret)
+			goto err;
+	}
+
 	ret = bt_ctf_stream_class_add_event_class(cw->stream_class, event_class);
 	if (ret) {
 		pr("Failed to add event class into stream.\n");

2.5.0

From: Wang Nan <[email protected]>

After babeltrace commit 5cec03e402aa ("ir: copy variants and sequences when setting a field path"), 'perf data convert' gets incorrect result if there's bpf output data. For example:

 # perf data convert --to-ctf ./out.ctf
 # babeltrace ./out.ctf
 [10:44:31.186045346] (+?.?????????) evt: { cpu_id = 0 }, { perf_ip = 0xFFFFFFFF810E7DD1, perf_tid = 23819, perf_pid = 23819, perf_id = 518, raw_len = 3, raw_data = [ [0] = 0xC028E32F, [1] = 0x815D0100, [2] = 0x1000000 ] }
 [10:44:31.286101003] (+0.100055657) evt: { cpu_id = 0 }, { perf_ip = 0xFFFFFFFF8105B609, perf_tid = 23819, perf_pid = 23819, perf_id = 518, raw_len = 3, raw_data = [ [0] = 0x35D9F1EB, [1] = 0x15D81, [2] = 0x2 ] }

The expected result of the first sample should be:

raw_data = [ [0] = 0x2FE328C0, [1] = 0x15D81, [2] = 0x1 ] }

however, 'perf data convert' output big endian value to resuling CTF file.

The reason is a internal change (or a bug?) of babeltrace.

Before this patch, at the first add_bpf_output_values(), byte order of all integer type is uncertain (is 0, neither 1234 (le) nor 4321 (be)). It would be fixed by:

perf_evlist__deliver_sample
-> process_sample_event
-> ctf_stream

      ...
      ->bt_ctf_trace_add_stream_class
        ->bt_ctf_field_type_structure_set_byte_order
          ->bt_ctf_field_type_integer_set_byte_order

during creating the stream.

However, the babeltrace commit mentioned above duplicates types in sequence to prevent potential conflict in following call stack and link the newly allocated type into the 'raw_data' sequence:

perf_evlist__deliver_sample
-> process_sample_event
-> ctf_stream

      ...
      -> bt_ctf_trace_add_stream_class
        -> bt_ctf_stream_class_resolve_types
           ...
           -> bt_ctf_field_type_sequence_copy
             ->bt_ctf_field_type_integer_copy

This happens before byte order setting, so only the newly allocated type is initialized, the byte order of original type perf choose to create the first raw_data is still uncertain.

Byte order in CTF output is not related to byte order in perf.data. Setting it to anything other than BT_CTF_BYTE_ORDER_NATIVE solves this problem (only BT_CTF_BYTE_ORDER_NATIVE needs to be fixed). To reduce behavior changing, set byte order according to compiling options.

---
 tools/perf/util/data-convert-bt.c | 6 ++++++
 1 file changed, 6 insertions(+)

index 1f608a6e2c14..811af89ce0bb 100644
@@ -1080,6 +1080,12 @@ static struct bt_ctf_field_type *create_int_type(int size, bool sign, bool hex)
 	    bt_ctf_field_type_integer_set_base(type, BT_CTF_INTEGER_BASE_HEXADECIMAL))
 		goto err;
 
+#if __BYTE_ORDER == __BIG_ENDIAN
+	bt_ctf_field_type_set_byte_order(type, BT_CTF_BYTE_ORDER_BIG_ENDIAN);
+#else
+	bt_ctf_field_type_set_byte_order(type, BT_CTF_BYTE_ORDER_LITTLE_ENDIAN);
+#endif
+
 	pr2("Created type: INTEGER %d-bit %ssigned %s\n",
 	    size, sign ? "un" : "", hex ? "hex" : "");
 	return type;

2.5.0

From: Wang Nan <[email protected]>

Commits in a BPF patchkit will extract kernel and module synthesizing code into a separated function and call it multiple times. This patch replace 'if (err < 0)' using WARN_ONCE, makes sure the error message show one time.

---
 tools/perf/builtin-record.c | 15 +++++++--------
 1 file changed, 7 insertions(+), 8 deletions(-)

index 7d11162b6c41..9dec7e529832 100644
@@ -33,6 +33,7 @@
 #include "util/parse-regs-options.h"
 #include "util/llvm-utils.h"
 #include "util/bpf-loader.h"
+#include "asm/bug.h"
 
 #include <unistd.h>
 #include <sched.h>

@@ -615,17 +616,15 @@ static int __cmd_record(struct record *rec, int argc, const char **argv)
 
 	err = perf_event__synthesize_kernel_mmap(tool, process_synthesized_event,
 						 machine);
-	if (err < 0)
-		pr_err("Couldn't record kernel reference relocation symbol\n"
-		       "Symbol resolution may be skewed if relocation was used (e.g. kexec).\n"
-		       "Check /proc/kallsyms permission or run as root.\n");
+	WARN_ONCE(err < 0, "Couldn't record kernel reference relocation symbol\n"
+			   "Symbol resolution may be skewed if relocation was used (e.g. kexec).\n"
+			   "Check /proc/kallsyms permission or run as root.\n");
 
 	err = perf_event__synthesize_modules(tool, process_synthesized_event,
 					     machine);
-	if (err < 0)
-		pr_err("Couldn't record kernel module information.\n"
-		       "Symbol resolution may be skewed if relocation was used (e.g. kexec).\n"
-		       "Check /proc/modules permission or run as root.\n");
+	WARN_ONCE(err < 0, "Couldn't record kernel module information.\n"
+			   "Symbol resolution may be skewed if relocation was used (e.g. kexec).\n"
+			   "Check /proc/modules permission or run as root.\n");
 
 	if (perf_guest) {
 		machines__process_guests(&session->machines,

2.5.0

From: Wang Nan <[email protected]>

Create record__synthesize(). It can be used to create tracking events for each perf.data after perf supporting splitting into multiple outputs.

---
 tools/perf/builtin-record.c | 125 +++++++++++++++++++++++++-------------------
 1 file changed, 70 insertions(+), 55 deletions(-)

index 9dec7e529832..cb583b49a175 100644
@@ -486,6 +486,74 @@ static void workload_exec_failed_signal(int signo __maybe_unused,
 
 static void snapshot_sig_handler(int sig);
 
+static int record__synthesize(struct record *rec)
+{
+	struct perf_session *session = rec->session;
+	struct machine *machine = &session->machines.host;
+	struct perf_data_file *file = &rec->file;
+	struct record_opts *opts = &rec->opts;
+	struct perf_tool *tool = &rec->tool;
+	int fd = perf_data_file__fd(file);
+	int err = 0;
+
+	if (file->is_pipe) {
+		err = perf_event__synthesize_attrs(tool, session,
+						   process_synthesized_event);
+		if (err < 0) {
+			pr_err("Couldn't synthesize attrs.\n");
+			goto out;
+		}
+
+		if (have_tracepoints(&rec->evlist->entries)) {
+			/*
+			 * FIXME err <= 0 here actually means that
+			 * there were no tracepoints so its not really
+			 * an error, just that we don't need to
+			 * synthesize anything.  We really have to
+			 * return this more properly and also
+			 * propagate errors that now are calling die()
+			 */
+			err = perf_event__synthesize_tracing_data(tool,	fd, rec->evlist,
+								  process_synthesized_event);
+			if (err <= 0) {
+				pr_err("Couldn't record tracing data.\n");
+				goto out;
+			}
+			rec->bytes_written += err;
+		}
+	}
+
+	if (rec->opts.full_auxtrace) {
+		err = perf_event__synthesize_auxtrace_info(rec->itr, tool,
+					session, process_synthesized_event);
+		if (err)
+			goto out;
+	}
+
+	err = perf_event__synthesize_kernel_mmap(tool, process_synthesized_event,
+						 machine);
+	WARN_ONCE(err < 0, "Couldn't record kernel reference relocation symbol\n"
+			   "Symbol resolution may be skewed if relocation was used (e.g. kexec).\n"
+			   "Check /proc/kallsyms permission or run as root.\n");
+
+	err = perf_event__synthesize_modules(tool, process_synthesized_event,
+					     machine);
+	WARN_ONCE(err < 0, "Couldn't record kernel module information.\n"
+			   "Symbol resolution may be skewed if relocation was used (e.g. kexec).\n"
+			   "Check /proc/modules permission or run as root.\n");
+
+	if (perf_guest) {
+		machines__process_guests(&session->machines,
+					 perf_event__synthesize_guest_os, tool);
+	}
+
+	err = __machine__synthesize_threads(machine, tool, &opts->target, rec->evlist->threads,
+					    process_synthesized_event, opts->sample_address,
+					    opts->proc_map_timeout);
+out:
+	return err;
+}
+
 static int __cmd_record(struct record *rec, int argc, const char **argv)
 {
 	int err;

@@ -580,61 +648,8 @@ static int __cmd_record(struct record *rec, int argc, const char **argv)
 
 	machine = &session->machines.host;
 
-	if (file->is_pipe) {
-		err = perf_event__synthesize_attrs(tool, session,
-						   process_synthesized_event);
-		if (err < 0) {
-			pr_err("Couldn't synthesize attrs.\n");
-			goto out_child;
-		}
-
-		if (have_tracepoints(&rec->evlist->entries)) {
-			/*
-			 * FIXME err <= 0 here actually means that
-			 * there were no tracepoints so its not really
-			 * an error, just that we don't need to
-			 * synthesize anything.  We really have to
-			 * return this more properly and also
-			 * propagate errors that now are calling die()
-			 */
-			err = perf_event__synthesize_tracing_data(tool,	fd, rec->evlist,
-								  process_synthesized_event);
-			if (err <= 0) {
-				pr_err("Couldn't record tracing data.\n");
-				goto out_child;
-			}
-			rec->bytes_written += err;
-		}
-	}
-
-	if (rec->opts.full_auxtrace) {
-		err = perf_event__synthesize_auxtrace_info(rec->itr, tool,
-					session, process_synthesized_event);
-		if (err)
-			goto out_delete_session;
-	}
-
-	err = perf_event__synthesize_kernel_mmap(tool, process_synthesized_event,
-						 machine);
-	WARN_ONCE(err < 0, "Couldn't record kernel reference relocation symbol\n"
-			   "Symbol resolution may be skewed if relocation was used (e.g. kexec).\n"
-			   "Check /proc/kallsyms permission or run as root.\n");
-
-	err = perf_event__synthesize_modules(tool, process_synthesized_event,
-					     machine);
-	WARN_ONCE(err < 0, "Couldn't record kernel module information.\n"
-			   "Symbol resolution may be skewed if relocation was used (e.g. kexec).\n"
-			   "Check /proc/modules permission or run as root.\n");
-
-	if (perf_guest) {
-		machines__process_guests(&session->machines,
-					 perf_event__synthesize_guest_os, tool);
-	}
-
-	err = __machine__synthesize_threads(machine, tool, &opts->target, rec->evlist->threads,
-					    process_synthesized_event, opts->sample_address,
-					    opts->proc_map_timeout);
-	if (err != 0)
+	err = record__synthesize(rec);
+	if (err < 0)
 		goto out_child;
 
 	if (rec->realtime_prio) {

2.5.0

From: Wang Nan <[email protected]>

Move code for finalizing 'perf.data' to record__finish_output(). It will be used by following commits to split output to multiple files.

---
 tools/perf/builtin-record.c | 37 +++++++++++++++++++++++++------------
 1 file changed, 25 insertions(+), 12 deletions(-)

index cb583b49a175..46e2772f838e 100644
@@ -468,6 +468,29 @@ static void record__init_features(struct record *rec)
 	perf_header__clear_feat(&session->header, HEADER_STAT);
 }
 
+static void
+record__finish_output(struct record *rec)
+{
+	struct perf_data_file *file = &rec->file;
+	int fd = perf_data_file__fd(file);
+
+	if (file->is_pipe)
+		return;
+
+	rec->session->header.data_size += rec->bytes_written;
+	file->size = lseek(perf_data_file__fd(file), 0, SEEK_CUR);
+
+	if (!rec->no_buildid) {
+		process_buildids(rec);
+
+		if (rec->buildid_all)
+			dsos__hit_all(rec->session);
+	}
+	perf_session__write_header(rec->session, rec->evlist, fd, true);
+
+	return;
+}
+
 static volatile int workload_exec_errno;
 
 /*

@@ -785,18 +808,8 @@ out_child:
 	/* this will be recalculated during process_buildids() */
 	rec->samples = 0;
 
-	if (!err && !file->is_pipe) {
-		rec->session->header.data_size += rec->bytes_written;
-		file->size = lseek(perf_data_file__fd(file), 0, SEEK_CUR);
-
-		if (!rec->no_buildid) {
-			process_buildids(rec);
-
-			if (rec->buildid_all)
-				dsos__hit_all(rec->session);
-		}
-		perf_session__write_header(rec->session, rec->evlist, fd, true);
-	}
+	if (!err)
+		record__finish_output(rec);
 
 	if (!err && !quiet) {
 		char samples[128];

2.5.0

From: Wang Nan <[email protected]>

perf_evlist__mmap_ex() can fail without setting errno (for example, fail in condition checking. In this case all syscall is success).

If this happen, record__open() incorrectly returns 0. Force setting rc is a quick way to avoid this problem, or we have to follow all possible code path in perf_evlist__mmap_ex() to make sure there's at least one system call before returning an error.

---
 tools/perf/builtin-record.c | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

index 46e2772f838e..515510ecc76a 100644
@@ -324,7 +324,10 @@ try_again:
 		} else {
 			pr_err("failed to mmap with %d (%s)\n", errno,
 				strerror_r(errno, msg, sizeof(msg)));
-			rc = -errno;
+			if (errno)
+				rc = -errno;
+			else
+				rc = -EINVAL;
 		}
 		goto out;
 	}

2.5.0

Hm, there's a 'perf stat' regression that I can see:

Before:

triton:~/tip> perf stat -a sleep 1

Performance counter stats for 'system wide':

      11990.023100      task-clock (msec)         #   11.981 CPUs utilized          
             8,802      context-switches          #    0.734 K/sec                  
               543      cpu-migrations            #    0.045 K/sec                  
            97,375      page-faults               #    0.008 M/sec                  
     9,854,385,894      cycles                    #    0.822 GHz                    
    15,274,841,152      stalled-cycles-frontend   #  155.01% frontend cycles idle   
   <not supported>      stalled-cycles-backend   
     9,634,486,137      instructions              #    0.98  insn per cycle         

# 1.59 stalled cycles per insn
1,818,488,088 branches # 151.667 M/sec
46,365,120 branch-misses # 2.55% of all branches

1.000741599 seconds time elapsed

After:

triton:~/tip> perf stat -a sleep 1

Performance counter stats for 'system wide':

      11989.280397      task-clock (msec)         #   11.981 CPUs utilized          
              1299      context-switches          #    0.108 K/sec                  
                 6      cpu-migrations            #    0.001 K/sec                  
                70      page-faults               #    0.006 K/sec                  
         127008602      cycles                    #    0.011 GHz                    
         279538533      stalled-cycles-frontend   #  220.09% frontend cycles idle   
         119213269      instructions              #    0.94  insn per cycle         
                                                  #    2.34  stalled cycles per insn
          24166678      branches                  #    2.016 M/sec                  
            505681      branch-misses             #    2.09% of all branches        

       1.000684278 seconds time elapsed

... see how the numbers became human-unreadable, losing the big-number separator?

I suspect it's due to the following commit:

fa184776ac27 perf stat: Check existence of frontend/backed stalled cycles

Thanks,

Ingo

yea, it used the pmu parsing which screwes locales, following patch fixed that for me..

jirka

---

index ce61f79dbaae..d8cd038baed2 100644
@@ -124,6 +124,17 @@ static int perf_pmu__parse_scale(struct perf_pmu_alias *alias, char *dir, char *
 	lc = setlocale(LC_NUMERIC, NULL);
 
 	/*
+	 * The lc string may be allocated in static storage,
+	 * so get a dynamic copy to make it survive setlocale
+	 * call below.
+	 */
+	lc = strdup(lc);
+	if (!lc) {
+		ret = -ENOMEM;
+		goto error;
+	}
+
+	/*
 	 * force to C locale to ensure kernel
 	 * scale string is converted correctly.
 	 * kernel uses default C locale.

@@ -135,6 +146,8 @@ static int perf_pmu__parse_scale(struct perf_pmu_alias *alias, char *dir, char *
 	/* restore locale */
 	setlocale(LC_NUMERIC, lc);
 
+	free((char *) lc);
+
 	ret = 0;
 error:
 	close(fd);

On Thu, Mar 03, 2016 at 10:15:22AM +0100, Jiri Olsa wrote:

SNIP

resending with full changelog

jirka

---
Ingo reported regression on display format of big numbers, which is missing separators (in default perf stat output).

triton:~/tip> perf stat -a sleep 1

         ...
         127008602      cycles                    #    0.011 GHz
         279538533      stalled-cycles-frontend   #  220.09% frontend cycles idle
         119213269      instructions              #    0.94  insn per cycle

This is caused by recent change:
perf stat: Check existence of frontend/backed stalled cycles

that added call to pmu_have_event, that subsequently calls perf_pmu__parse_scale, which has a bug in locale handling.

The lc string returned from setlocale, that we use to store old locale value, may be allocated in static storage. Getting a dynamic copy to make it survive another setlocale call.

[jolsa@krava perf]$ perf stat ls

         ...
         2,360,602      cycles                    #    3.080 GHz
         2,703,090      instructions              #    1.15  insn per cycle
           546,031      branches                  #  712.511 M/sec

---
 tools/perf/util/pmu.c | 13 +++++++++++++
 1 file changed, 13 insertions(+)

index ce61f79dbaae..d8cd038baed2 100644
@@ -124,6 +124,17 @@ static int perf_pmu__parse_scale(struct perf_pmu_alias *alias, char *dir, char *
 	lc = setlocale(LC_NUMERIC, NULL);
 
 	/*
+	 * The lc string may be allocated in static storage,
+	 * so get a dynamic copy to make it survive setlocale
+	 * call below.
+	 */
+	lc = strdup(lc);
+	if (!lc) {
+		ret = -ENOMEM;
+		goto error;
+	}
+
+	/*
 	 * force to C locale to ensure kernel
 	 * scale string is converted correctly.
 	 * kernel uses default C locale.

@@ -135,6 +146,8 @@ static int perf_pmu__parse_scale(struct perf_pmu_alias *alias, char *dir, char *
 	/* restore locale */
 	setlocale(LC_NUMERIC, lc);
 
+	free((char *) lc);
+
 	ret = 0;
 error:
 	close(fd);

2.4.3

Thanks. Looks good.

-Andi

libc free takes only non const pointers:

util/pmu.c: In function ‘perf_pmu__parse_scale’:
util/pmu.c:149:7: error: passing argument 1 of ‘free’ discards ‘const’ qualifier from pointer target type [-Werror=discarded-qualifiers]

  free(lc);
       ^
In file included from /home/jolsa/kernel/linux-perf/tools/include/linux/kernel.h:6:0,
                 from /home/jolsa/kernel/linux-perf/tools/include/linux/list.h:6,
                 from util/pmu.c:1:

/usr/include/stdlib.h:483:13: note: expected ‘void *’ but argument is of type ‘const char *’
extern void free (void *__ptr) __THROW;

but we could actually make it char* from the beginning.. for some reason I thought setlocale returns const ptr, and I did not check.. fix attached

jirka

---
There's no need to used const char pointer,
we can used char pointer from the beginning
and omit unnecessary cast.

---
 tools/perf/util/pmu.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

index d8cd038baed2..adef23b1352e 100644
@@ -98,7 +98,7 @@ static int perf_pmu__parse_scale(struct perf_pmu_alias *alias, char *dir, char *
 	char scale[128];
 	int fd, ret = -1;
 	char path[PATH_MAX];
-	const char *lc;
+	char *lc;
 
 	snprintf(path, PATH_MAX, "%s/%s.scale", dir, name);
 

@@ -146,7 +146,7 @@ static int perf_pmu__parse_scale(struct perf_pmu_alias *alias, char *dir, char *
 	/* restore locale */
 	setlocale(LC_NUMERIC, lc);
 
-	free((char *) lc);
+	free(lc);
 
 	ret = 0;
 error:

2.4.3

Em Tue, Mar 08, 2016 at 07:42:30PM +0100, Jiri Olsa escreveu:

Thanks, applied.

Em Thu, Mar 03, 2016 at 09:21:30AM +0100, Ingo Molnar escreveu:

Ok, I inserted Jiri's patch fixing the problem just before the commit (fa184776ac27) that triggers it, so that we don't break bisection for human-readable numbers in 'perf stat'.

Its all in a new signed tag, that combines the two outstanding ones (perf-core-for-mingo-20160229 + perf-core-for-mingo-20160302), please consider pulling.

- Arnaldo

The following changes since commit 675965b00d734c985e4285f5bec7e524d15fc4e1:

perf: Export perf_event_sysfs_show() (2016-02-29 09:35:27 +0100)

are available in the git repository at:

git://git.kernel.org/pub/scm/linux/kernel/git/acme/linux.git tags/perf-core-for-mingo-20160303

for you to fetch changes up to fb4605ba47e772ff9d62d1d54218a832ec8b3e1d:

perf stat: Check for frontend stalled for metrics (2016-03-03 11:10:40 -0300)

----------------------------------------------------------------
perf/core improvements and fixes:

User visible:

- Check existence of frontend/backed stalled cycles in 'perf stat' (Andi Kleen)

- Implement CSV metrics output in 'perf stat' (Andi Kleen)

- Support metrics in 'perf stat' --per-core/socket mode (Andi Kleen)

- Avoid installing .o files from tools/lib/ into the python extension (Jiri Olsa)

- Rename the tracepoint '/format' field that carries the syscall ID from 'nr', that is also the name of some syscalls arguments, to "__syscall_nr", to avoid having multiple fields with the same name, that was breaking the python script skeleton generator from perf.data files (Taeung Song)

- Support converting data from bpf events in 'perf data' (Wang Nan)

- Fix segfault in 'perf test' hists related entries (Arnaldo Carvalho de Melo)

- Fix output of %llu for 64 bit values read on 32 bit machines in libtraceevent (Steven Rostedt)

- Fix time stamp rounding issue in libtraceevent (Chaos.Chen)

Infrastructure:

- Fix setlocale() breakage in the pmu parsing code (Jiri Olsa)

- Split libtraceevent's pevent_print_event() (Steven Rostedt)

- Librarize some 'perf record' bits to allow handling multiple perf.data files per session (Wang Nan)

- Ensure return non-zero rc when mmap fails in 'perf record' (Wang Nan)

- Fix double free on 'command_line' in a error path in 'perf script' (Colin Ian King)

- Initialize struct sigaction 'sa_flags' field in a 'perf test' entry (Colin Ian King)

- Fix various build warnings in turbostat, detected with gcc6 (Colin Ian King)

- Use .s extension for preprocessed assembler code (Masahiro Yamada)

----------------------------------------------------------------
Andi Kleen (4):
perf stat: Check existence of frontend/backed stalled cycles perf stat: Implement CSV metrics output
perf stat: Support metrics in --per-core/socket mode perf stat: Check for frontend stalled for metrics

Arnaldo Carvalho de Melo (1):
perf test: Fix hists related entries

Chaos.Chen (1):
tools lib traceevent: Fix time stamp rounding issue

Colin Ian King (3):
perf script: Fix double free on command_line perf tests: Initialize sa.sa_flags tools/power turbostat: fix various build warnings

Jiri Olsa (2):
perf tools: Fix python extension build perf tools: Fix locale handling in pmu parsing

Masahiro Yamada (1):
tools build: Use .s extension for preprocessed assembler code

Steven Rostedt (1):
tools lib traceevent: Split pevent_print_event() into specific functionality functions

Steven Rostedt (Red Hat) (2):
tools lib traceevent: Set int_array fields to NULL if freeing from error tools lib traceevent: Fix output of %llu for 64 bit values read on 32 bit machines

Taeung Song (2):
perf trace: Check and discard not only 'nr' but also '__syscall_nr' tracing/syscalls: Rename "/format" tracepoint field name "nr" to "__syscall_nr:

Wang Nan (6):
perf data: Support converting data from bpf_perf_event_output() perf data: Explicitly set byte order for integer types perf record: Use WARN_ONCE to replace 'if' condition perf record: Extract synthesize code to record__synthesize() perf record: Introduce record__finish_output() to finish a perf.data perf record: Ensure return non-zero rc when mmap fail

 kernel/trace/trace_syscalls.c                      |  16 +-
 tools/build/Makefile.build                         |   2 +-
 tools/lib/traceevent/event-parse.c                 | 146 ++++++++++++++----
 tools/lib/traceevent/event-parse.h                 |  13 ++
 tools/perf/arch/x86/tests/rdpmc.c                  |   1 +
 tools/perf/builtin-record.c                        | 168 ++++++++++++---------
 tools/perf/builtin-stat.c                          | 158 +++++++++++++++++--
 tools/perf/builtin-trace.c                         |   8 +-
 tools/perf/util/data-convert-bt.c                  | 118 ++++++++++++++-
 tools/perf/util/pmu.c                              |  13 ++
 .../util/scripting-engines/trace-event-python.c    |   4 +-
 tools/perf/util/setup.py                           |   4 +
 tools/perf/util/sort.c                             |  37 +++--
 tools/perf/util/stat-shadow.c                      |  18 ++-
 tools/perf/util/stat.h                             |   1 +
 tools/power/x86/turbostat/turbostat.c              |   8 +-
 16 files changed, 566 insertions(+), 149 deletions(-)

Pulled, thanks a lot Arnaldo!

Ingo