[PATCH v1 0/5] perf data/pipe handling improvements

[PATCH v1 0/5] perf data/pipe handling improvements

[Ian Rogers]

I'm looking at improving the perf data converter with files generated
in pipe mode. In pipe mode I found the feature handling for the last
feature marker was problematic. If a new feature was added then the
old marker looks like the new feature. These changes do some minor
logging and build fixes, but they also change the last feature
handling in pipe mode so that the marker is treated as a marker and
not a feature that is broken.

Ian Rogers (5):
  perf clockid: Add missing include
  perf header: Add utility to convert feature number to a string
  perf session: Extra logging for failed to process events
  perf header: Refactor pipe mode end marker handling
  perf evsel: Make unknown event names more unique

 tools/perf/builtin-annotate.c       | 11 +-----
 tools/perf/builtin-report.c         | 27 +++++--------
 tools/perf/builtin-script.c         | 11 +-----
 tools/perf/util/clockid.h           |  3 +-
 tools/perf/util/data-convert-bt.c   |  9 ++---
 tools/perf/util/data-convert-json.c | 12 +-----
 tools/perf/util/evsel.c             |  7 ++--
 tools/perf/util/header.c            | 60 ++++++++++++++++++++++-------
 tools/perf/util/header.h            |  6 ++-
 tools/perf/util/intel-tpebs.c       | 11 +-----
 tools/perf/util/session.c           | 28 ++++++++++----
 11 files changed, 95 insertions(+), 90 deletions(-)

-- 
2.53.0.414.gf7e9f6c205-goog

[PATCH v1 1/5] perf clockid: Add missing include

[Ian Rogers]

clockid_t is declared in time.h but the include is missing. Reordering
header files may result in build breakages. Add the include to avoid
this.

Signed-off-by: Ian Rogers <irogers@google.com>
---
 tools/perf/util/clockid.h | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/tools/perf/util/clockid.h b/tools/perf/util/clockid.h
index 9b49b4711c76..33dbd8673c1c 100644
--- a/tools/perf/util/clockid.h
+++ b/tools/perf/util/clockid.h
@@ -1,8 +1,9 @@
 /* SPDX-License-Identifier: GPL-2.0 */
-
 #ifndef __PERF_CLOCKID_H
 #define __PERF_CLOCKID_H
 
+#include <time.h>
+
 struct option;
 int parse_clockid(const struct option *opt, const char *str, int unset);
 
-- 
2.53.0.414.gf7e9f6c205-goog

[PATCH v1 2/5] perf header: Add utility to convert feature number to a string

[Ian Rogers]

For logging and debug messages it can be convenient to convert a
feature number to a name. Add header_feat__name for this and reuse the
data already within the feat_ops struct.

Signed-off-by: Ian Rogers <irogers@google.com>
---
 tools/perf/util/header.c | 7 +++++++
 tools/perf/util/header.h | 2 ++
 2 files changed, 9 insertions(+)

diff --git a/tools/perf/util/header.c b/tools/perf/util/header.c
index 9142a8ba4019..fe5d21dde04f 100644
--- a/tools/perf/util/header.c
+++ b/tools/perf/util/header.c
@@ -3770,6 +3770,13 @@ struct header_print_data {
 	bool full; /* extended list of headers */
 };
 
+const char *header_feat__name(unsigned int id)
+{
+	if (id < HEADER_LAST_FEATURE)
+		return feat_ops[id].name;
+	return "INVALID";
+}
+
 static int perf_file_section__fprintf_info(struct perf_file_section *section,
 					   struct perf_header *ph,
 					   int feat, int fd, void *data)
diff --git a/tools/perf/util/header.h b/tools/perf/util/header.h
index cc40ac796f52..ca22030a1434 100644
--- a/tools/perf/util/header.h
+++ b/tools/perf/util/header.h
@@ -132,6 +132,8 @@ struct perf_header_feature_ops {
 
 extern const char perf_version_string[];
 
+const char *header_feat__name(unsigned int id);
+
 int perf_session__read_header(struct perf_session *session);
 int perf_session__write_header(struct perf_session *session,
 			       struct evlist *evlist,
-- 
2.53.0.414.gf7e9f6c205-goog

[PATCH v1 3/5] perf session: Extra logging for failed to process events

[Ian Rogers]

Print log information in ordered event processing so that the cause of
finished round failing is clearer. Print the event name along with its
number when an event isn't processed. Add extra detail about where the
failure happened.

Signed-off-by: Ian Rogers <irogers@google.com>
---
 tools/perf/util/session.c | 28 ++++++++++++++++++++--------
 1 file changed, 20 insertions(+), 8 deletions(-)

diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index 4b465abfa36c..7f3ffbe633af 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -131,10 +131,17 @@ static int ordered_events__deliver_event(struct ordered_events *oe,
 {
 	struct perf_session *session = container_of(oe, struct perf_session,
 						    ordered_events);
+	int ret =  perf_session__deliver_event(session, event->event,
+					      session->tool, event->file_offset,
+					      event->file_path);
 
-	return perf_session__deliver_event(session, event->event,
-					   session->tool, event->file_offset,
-					   event->file_path);
+	if (ret) {
+		pr_err("%#" PRIx64 " [%#x]: ordered event processing failed (%d) for event of type: %s (%d)\n",
+			event->file_offset, event->event->header.size, ret,
+			perf_event__name(event->event->header.type),
+			event->event->header.type);
+	}
+	return ret;
 }
 
 struct perf_session *__perf_session__new(struct perf_data *data,
@@ -2110,8 +2117,10 @@ static int __perf_session__process_pipe_events(struct perf_session *session)
 	}
 
 	if ((skip = perf_session__process_event(session, event, head, "pipe")) < 0) {
-		pr_err("%#" PRIx64 " [%#x]: failed to process type: %d\n",
-		       head, event->header.size, event->header.type);
+		pr_err("%#" PRIx64 " [%#x]: piped event processing failed for event of type: %s (%d)\n",
+			head, event->header.size,
+			perf_event__name(event->header.type),
+			event->header.type);
 		err = -EINVAL;
 		goto out_err;
 	}
@@ -2225,8 +2234,10 @@ static int __perf_session__process_decomp_events(struct perf_session *session)
 		if (size < sizeof(struct perf_event_header) ||
 		    (skip = perf_session__process_event(session, event, decomp->file_pos,
 							decomp->file_path)) < 0) {
-			pr_err("%#" PRIx64 " [%#x]: failed to process type: %d\n",
-				decomp->file_pos + decomp->head, event->header.size, event->header.type);
+			pr_err("%#" PRIx64 " [%#x]: decompress event processing failed for event of type: %s (%d)\n",
+				decomp->file_pos + decomp->head, event->header.size,
+				perf_event__name(event->header.type),
+				event->header.type);
 			return -EINVAL;
 		}
 
@@ -2382,8 +2393,9 @@ reader__read_event(struct reader *rd, struct perf_session *session,
 	if (size < sizeof(struct perf_event_header) ||
 	    (skip = rd->process(session, event, rd->file_pos, rd->path)) < 0) {
 		errno = -skip;
-		pr_err("%#" PRIx64 " [%#x]: failed to process type: %d [%m]\n",
+		pr_err("%#" PRIx64 " [%#x]: processing failed for event of type: %s (%d) [%m]\n",
 		       rd->file_offset + rd->head, event->header.size,
+		       perf_event__name(event->header.type),
 		       event->header.type);
 		err = skip;
 		goto out;
-- 
2.53.0.414.gf7e9f6c205-goog

[PATCH v1 4/5] perf header: Refactor pipe mode end marker handling

[Ian Rogers]

In non-pipe/data mode the header has a 256-bit bitmap representing
whether a feature is enabled or not. In pipe mode features are written
out in perf_event__synthesize_features as PERF_RECORD_HEADER_FEATURE
events with a special zero sized marker for the last feature. If a new
feature is added the last feature marker event appears as that feature
from old pipe mode perf data. As the event is zero sized it will fail
to be processed and generally terminate perf.

Add a last_feat variable to the header that in non-pipe/data mode is
just HEADER_LAST_FEATURE. In pipe mode compute the last_feat by
handling zero sized feature events, assuming they are the marker and
updating last_feat accordingly. Potentially a feature event could be
zero sized and so still process the feature event, just ignore the
error if it fails.

As perf_event__process_feature can properly handle pipe mode data,
migrate users to it except for report that still wants to group events
with the last feature marker. Make perf_event__process_feature
non-fatal in the case of a newer feature than this version of perf's
HEADER_LAST_FEATURE, which was the behavior all users wanted.

Signed-off-by: Ian Rogers <irogers@google.com>
---
 tools/perf/builtin-annotate.c       | 11 +-----
 tools/perf/builtin-report.c         | 27 ++++++---------
 tools/perf/builtin-script.c         | 11 +-----
 tools/perf/util/data-convert-bt.c   |  9 ++---
 tools/perf/util/data-convert-json.c | 12 +------
 tools/perf/util/header.c            | 53 ++++++++++++++++++++++-------
 tools/perf/util/header.h            |  4 ++-
 tools/perf/util/intel-tpebs.c       | 11 +-----
 8 files changed, 60 insertions(+), 78 deletions(-)

diff --git a/tools/perf/builtin-annotate.c b/tools/perf/builtin-annotate.c
index 9c27bb30b708..cf2d2011e148 100644
--- a/tools/perf/builtin-annotate.c
+++ b/tools/perf/builtin-annotate.c
@@ -313,15 +313,6 @@ static int process_sample_event(const struct perf_tool *tool,
 	return ret;
 }
 
-static int process_feature_event(const struct perf_tool *tool __maybe_unused,
-				 struct perf_session *session,
-				 union perf_event *event)
-{
-	if (event->feat.feat_id < HEADER_LAST_FEATURE)
-		return perf_event__process_feature(session, event);
-	return 0;
-}
-
 static int hist_entry__stdio_annotate(struct hist_entry *he,
 				    struct evsel *evsel,
 				    struct perf_annotate *ann)
@@ -876,7 +867,7 @@ int cmd_annotate(int argc, const char **argv)
 	annotate.tool.id_index	= perf_event__process_id_index;
 	annotate.tool.auxtrace_info	= perf_event__process_auxtrace_info;
 	annotate.tool.auxtrace	= perf_event__process_auxtrace;
-	annotate.tool.feature	= process_feature_event;
+	annotate.tool.feature	= perf_event__process_feature;
 	annotate.tool.ordering_requires_timestamps = true;
 
 	annotate.session = perf_session__new(&data, &annotate.tool);
diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
index 3b81f4b3dc49..d1163f22648e 100644
--- a/tools/perf/builtin-report.c
+++ b/tools/perf/builtin-report.c
@@ -245,25 +245,18 @@ static int process_feature_event(const struct perf_tool *tool,
 				 union perf_event *event)
 {
 	struct report *rep = container_of(tool, struct report, tool);
+	int ret = perf_event__process_feature(tool, session, event);
 
-	if (event->feat.feat_id < HEADER_LAST_FEATURE)
-		return perf_event__process_feature(session, event);
-
-	if (event->feat.feat_id != HEADER_LAST_FEATURE) {
-		pr_err("failed: wrong feature ID: %" PRI_lu64 "\n",
-		       event->feat.feat_id);
-		return -1;
-	} else if (rep->header_only) {
-		session_done = 1;
+	if (ret == 0 && event->header.size == sizeof(struct perf_record_header_feature) &&
+	    (int)event->feat.feat_id == session->header.last_feat) {
+		/*
+		 * (feat_id = HEADER_LAST_FEATURE) is the end marker which means
+		 * all features are received, now we can force the group if
+		 * needed.
+		 */
+		setup_forced_leader(rep, session->evlist);
 	}
-
-	/*
-	 * (feat_id = HEADER_LAST_FEATURE) is the end marker which
-	 * means all features are received, now we can force the
-	 * group if needed.
-	 */
-	setup_forced_leader(rep, session->evlist);
-	return 0;
+	return ret;
 }
 
 static int process_sample_event(const struct perf_tool *tool,
diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c
index 7c743a303507..92b76ff24f16 100644
--- a/tools/perf/builtin-script.c
+++ b/tools/perf/builtin-script.c
@@ -3939,15 +3939,6 @@ int process_cpu_map_event(const struct perf_tool *tool,
 	return set_maps(script);
 }
 
-static int process_feature_event(const struct perf_tool *tool __maybe_unused,
-				 struct perf_session *session,
-				 union perf_event *event)
-{
-	if (event->feat.feat_id < HEADER_LAST_FEATURE)
-		return perf_event__process_feature(session, event);
-	return 0;
-}
-
 static int perf_script__process_auxtrace_info(const struct perf_tool *tool,
 					      struct perf_session *session,
 					      union perf_event *event)
@@ -4423,7 +4414,7 @@ int cmd_script(int argc, const char **argv)
 #ifdef HAVE_LIBTRACEEVENT
 	script.tool.tracing_data	 = perf_event__process_tracing_data;
 #endif
-	script.tool.feature		 = process_feature_event;
+	script.tool.feature		 = perf_event__process_feature;
 	script.tool.build_id		 = perf_event__process_build_id;
 	script.tool.id_index		 = perf_event__process_id_index;
 	script.tool.auxtrace_info	 = perf_script__process_auxtrace_info;
diff --git a/tools/perf/util/data-convert-bt.c b/tools/perf/util/data-convert-bt.c
index ba1c8e48d495..665bf8eea24b 100644
--- a/tools/perf/util/data-convert-bt.c
+++ b/tools/perf/util/data-convert-bt.c
@@ -1412,13 +1412,10 @@ static int process_feature_event(const struct perf_tool *tool,
 	struct convert *c = container_of(tool, struct convert, tool);
 	struct ctf_writer *cw = &c->writer;
 	struct perf_record_header_feature *fe = &event->feat;
+	int ret = perf_event__process_feature(tool, session, event);
 
-	if (event->feat.feat_id < HEADER_LAST_FEATURE) {
-		int ret = perf_event__process_feature(session, event);
-
-		if (ret)
-			return ret;
-	}
+	if (ret)
+		return ret;
 
 	switch (fe->feat_id) {
 	case HEADER_HOSTNAME:
diff --git a/tools/perf/util/data-convert-json.c b/tools/perf/util/data-convert-json.c
index 6a626322476a..4b1b2f7bed25 100644
--- a/tools/perf/util/data-convert-json.c
+++ b/tools/perf/util/data-convert-json.c
@@ -326,16 +326,6 @@ static void output_headers(struct perf_session *session, struct convert_json *c)
 	output_json_format(out, false, 2, "]");
 }
 
-static int process_feature_event(const struct perf_tool *tool __maybe_unused,
-				 struct perf_session *session,
-				 union perf_event *event)
-{
-	if (event->feat.feat_id < HEADER_LAST_FEATURE)
-		return perf_event__process_feature(session, event);
-
-	return 0;
-}
-
 int bt_convert__perf2json(const char *input_name, const char *output_name,
 		struct perf_data_convert_opts *opts __maybe_unused)
 {
@@ -375,7 +365,7 @@ int bt_convert__perf2json(const char *input_name, const char *output_name,
 	c.tool.auxtrace       = perf_event__process_auxtrace;
 	c.tool.event_update   = perf_event__process_event_update;
 	c.tool.attr           = perf_event__process_attr;
-	c.tool.feature        = process_feature_event;
+	c.tool.feature        = perf_event__process_feature;
 	c.tool.ordering_requires_timestamps = true;
 
 	if (opts->all) {
diff --git a/tools/perf/util/header.c b/tools/perf/util/header.c
index fe5d21dde04f..7031f6c6bd66 100644
--- a/tools/perf/util/header.c
+++ b/tools/perf/util/header.c
@@ -3785,11 +3785,11 @@ static int perf_file_section__fprintf_info(struct perf_file_section *section,
 	struct feat_fd ff;
 
 	if (lseek(fd, section->offset, SEEK_SET) == (off_t)-1) {
-		pr_debug("Failed to lseek to %" PRIu64 " offset for feature "
-				"%d, continuing...\n", section->offset, feat);
+		pr_debug("Failed to lseek to %" PRIu64 " offset for feature %s (%d), continuing...\n",
+			 section->offset, header_feat__name(feat), feat);
 		return 0;
 	}
-	if (feat >= HEADER_LAST_FEATURE) {
+	if (feat >= ph->last_feat) {
 		pr_warning("unknown feature %d\n", feat);
 		return 0;
 	}
@@ -3841,7 +3841,7 @@ int perf_header__fprintf_info(struct perf_session *session, FILE *fp, bool full)
 		return 0;
 
 	fprintf(fp, "# missing features: ");
-	for_each_clear_bit(bit, header->adds_features, HEADER_LAST_FEATURE) {
+	for_each_clear_bit(bit, header->adds_features, header->last_feat) {
 		if (bit)
 			fprintf(fp, "%s ", feat_ops[bit].name);
 	}
@@ -4171,7 +4171,7 @@ int perf_header__process_sections(struct perf_header *header, int fd,
 	if (err < 0)
 		goto out_free;
 
-	for_each_set_bit(feat, header->adds_features, HEADER_LAST_FEATURE) {
+	for_each_set_bit(feat, header->adds_features, header->last_feat) {
 		err = process(sec++, header, feat, fd, data);
 		if (err < 0)
 			goto out_free;
@@ -4386,6 +4386,7 @@ int perf_file_header__read(struct perf_file_header *header,
 	ph->data_offset  = header->data.offset;
 	ph->data_size	 = header->data.size;
 	ph->feat_offset  = header->data.offset + header->data.size;
+	ph->last_feat	 = HEADER_LAST_FEATURE;
 	return 0;
 }
 
@@ -4401,8 +4402,8 @@ static int perf_file_section__process(struct perf_file_section *section,
 	};
 
 	if (lseek(fd, section->offset, SEEK_SET) == (off_t)-1) {
-		pr_debug("Failed to lseek to %" PRIu64 " offset for feature "
-			  "%d, continuing...\n", section->offset, feat);
+		pr_debug("Failed to lseek to %" PRIu64 " offset for feature %s (%d), continuing...\n",
+			 section->offset, header_feat__name(feat), feat);
 		return 0;
 	}
 
@@ -4435,6 +4436,8 @@ static int perf_file_header__read_pipe(struct perf_pipe_file_header *header,
 	if (ph->needs_swap)
 		header->size = bswap_64(header->size);
 
+	/* The last feature is written out as a 0 sized event and will update this value. */
+	ph->last_feat = 0;
 	return 0;
 }
 
@@ -4667,31 +4670,55 @@ int perf_session__read_header(struct perf_session *session)
 	return -ENOMEM;
 }
 
-int perf_event__process_feature(struct perf_session *session,
+int perf_event__process_feature(const struct perf_tool *tool __maybe_unused,
+				struct perf_session *session,
 				union perf_event *event)
 {
 	struct feat_fd ff = { .fd = 0 };
 	struct perf_record_header_feature *fe = (struct perf_record_header_feature *)event;
+	struct perf_header *header = &session->header;
 	int type = fe->header.type;
-	u64 feat = fe->feat_id;
+	int feat = (int)fe->feat_id;
 	int ret = 0;
 	bool print = dump_trace;
+	bool last_feature_mark = false;
 
 	if (type < 0 || type >= PERF_RECORD_HEADER_MAX) {
 		pr_warning("invalid record type %d in pipe-mode\n", type);
 		return 0;
 	}
-	if (feat == HEADER_RESERVED || feat >= HEADER_LAST_FEATURE) {
-		pr_warning("invalid record type %d in pipe-mode\n", type);
+	if (feat == HEADER_RESERVED) {
+		pr_warning("invalid reserved record type in pipe-mode\n");
 		return -1;
 	}
+	if (feat >= header->last_feat) {
+		if (event->header.size == sizeof(*fe)) {
+			// Either an unexpected zero size feature or the
+			// HEADER_LAST_FEATURE mark.
+			if (feat > header->last_feat)
+				header->last_feat = min(feat, HEADER_LAST_FEATURE);
+			last_feature_mark = true;
+		} else {
+			// A feature but beyond what is known as in
+			// bounds. Assume the last feature is 1 beyond this
+			// feature.
+			session->header.last_feat = min(feat + 1, HEADER_LAST_FEATURE);
+		}
+	}
+	if (feat >= HEADER_LAST_FEATURE) {
+		pr_warning("unknown feature %d for data file version (%s) in this version of perf (%s)\n",
+			   feat, header->env.version, perf_version_string);
+		return 0;
+	}
 
 	ff.buf  = (void *)fe->data;
 	ff.size = event->header.size - sizeof(*fe);
-	ff.ph = &session->header;
+	ff.ph = header;
 
 	if (feat_ops[feat].process && feat_ops[feat].process(&ff, NULL)) {
-		ret = -1;
+		// Processing failed, ignore when this is the last feature mark.
+		if (!last_feature_mark)
+			ret = -1;
 		goto out;
 	}
 
diff --git a/tools/perf/util/header.h b/tools/perf/util/header.h
index ca22030a1434..41ce663d93ff 100644
--- a/tools/perf/util/header.h
+++ b/tools/perf/util/header.h
@@ -109,6 +109,7 @@ struct perf_header {
 	u64				data_size;
 	u64				feat_offset;
 	DECLARE_BITMAP(adds_features, HEADER_FEAT_BITS);
+	int				last_feat;
 	struct perf_env 	env;
 };
 
@@ -172,7 +173,8 @@ int perf_header__process_sections(struct perf_header *header, int fd,
 
 int perf_header__fprintf_info(struct perf_session *s, FILE *fp, bool full);
 
-int perf_event__process_feature(struct perf_session *session,
+int perf_event__process_feature(const struct perf_tool *tool,
+				struct perf_session *session,
 				union perf_event *event);
 int perf_event__process_attr(const struct perf_tool *tool, union perf_event *event,
 			     struct evlist **pevlist);
diff --git a/tools/perf/util/intel-tpebs.c b/tools/perf/util/intel-tpebs.c
index 3c958d738ca6..f57ea6db02a0 100644
--- a/tools/perf/util/intel-tpebs.c
+++ b/tools/perf/util/intel-tpebs.c
@@ -217,15 +217,6 @@ static int process_sample_event(const struct perf_tool *tool __maybe_unused,
 	return 0;
 }
 
-static int process_feature_event(const struct perf_tool *tool __maybe_unused,
-				 struct perf_session *session,
-				 union perf_event *event)
-{
-	if (event->feat.feat_id < HEADER_LAST_FEATURE)
-		return perf_event__process_feature(session, event);
-	return 0;
-}
-
 static void *__sample_reader(void *arg __maybe_unused)
 {
 	struct perf_session *session;
@@ -238,7 +229,7 @@ static void *__sample_reader(void *arg __maybe_unused)
 
 	perf_tool__init(&tool, /*ordered_events=*/false);
 	tool.sample = process_sample_event;
-	tool.feature = process_feature_event;
+	tool.feature = perf_event__process_feature;
 	tool.attr = perf_event__process_attr;
 
 	session = perf_session__new(&data, &tool);
-- 
2.53.0.414.gf7e9f6c205-goog

[PATCH v1 5/5] perf evsel: Make unknown event names more unique

[Ian Rogers]

In situations like the perf data converter the evsel__name will be
used to create babeltrace events. If the events have the same name
then creation can fail. Avoid these failures by including more
information into the unknown event names.

Signed-off-by: Ian Rogers <irogers@google.com>
---
 tools/perf/util/evsel.c | 7 ++++---
 1 file changed, 4 insertions(+), 3 deletions(-)

diff --git a/tools/perf/util/evsel.c b/tools/perf/util/evsel.c
index f59228c1a39e..fdc67df0e739 100644
--- a/tools/perf/util/evsel.c
+++ b/tools/perf/util/evsel.c
@@ -926,7 +926,8 @@ const char *evsel__name(struct evsel *evsel)
 		break;
 
 	case PERF_TYPE_TRACEPOINT:
-		scnprintf(bf, sizeof(bf), "%s", "unknown tracepoint");
+		scnprintf(bf, sizeof(bf), "unknown tracepoint id=%#"PRId64,
+			  evsel->core.attr.config);
 		break;
 
 	case PERF_TYPE_BREAKPOINT:
@@ -938,8 +939,8 @@ const char *evsel__name(struct evsel *evsel)
 		break;
 
 	default:
-		scnprintf(bf, sizeof(bf), "unknown attr type: %d",
-			  evsel->core.attr.type);
+		scnprintf(bf, sizeof(bf), "unknown event PMU=%d config=%#"PRIx64,
+			  evsel->core.attr.type, evsel->core.attr.config);
 		break;
 	}
 
-- 
2.53.0.414.gf7e9f6c205-goog

Re: [PATCH v1 3/5] perf session: Extra logging for failed to process events

[Namhyung Kim]

On Wed, Feb 25, 2026 at 05:35:32PM -0800, Ian Rogers wrote:
> Print log information in ordered event processing so that the cause of
> finished round failing is clearer. Print the event name along with its
> number when an event isn't processed. Add extra detail about where the
> failure happened.

It'd be nice if you show messages before and after the change.

> 
> Signed-off-by: Ian Rogers <irogers@google.com>
> ---
>  tools/perf/util/session.c | 28 ++++++++++++++++++++--------
>  1 file changed, 20 insertions(+), 8 deletions(-)
> 
> diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
> index 4b465abfa36c..7f3ffbe633af 100644
> --- a/tools/perf/util/session.c
> +++ b/tools/perf/util/session.c
> @@ -131,10 +131,17 @@ static int ordered_events__deliver_event(struct ordered_events *oe,
>  {
>  	struct perf_session *session = container_of(oe, struct perf_session,
>  						    ordered_events);
> +	int ret =  perf_session__deliver_event(session, event->event,

Slightly unaligned.. it seems to have 2 spaces.

Thanks,
Namhyung


> +					      session->tool, event->file_offset,
> +					      event->file_path);
>  
> -	return perf_session__deliver_event(session, event->event,
> -					   session->tool, event->file_offset,
> -					   event->file_path);
> +	if (ret) {
> +		pr_err("%#" PRIx64 " [%#x]: ordered event processing failed (%d) for event of type: %s (%d)\n",
> +			event->file_offset, event->event->header.size, ret,
> +			perf_event__name(event->event->header.type),
> +			event->event->header.type);
> +	}
> +	return ret;
>  }
>  
>  struct perf_session *__perf_session__new(struct perf_data *data,
> @@ -2110,8 +2117,10 @@ static int __perf_session__process_pipe_events(struct perf_session *session)
>  	}
>  
>  	if ((skip = perf_session__process_event(session, event, head, "pipe")) < 0) {
> -		pr_err("%#" PRIx64 " [%#x]: failed to process type: %d\n",
> -		       head, event->header.size, event->header.type);
> +		pr_err("%#" PRIx64 " [%#x]: piped event processing failed for event of type: %s (%d)\n",
> +			head, event->header.size,
> +			perf_event__name(event->header.type),
> +			event->header.type);
>  		err = -EINVAL;
>  		goto out_err;
>  	}
> @@ -2225,8 +2234,10 @@ static int __perf_session__process_decomp_events(struct perf_session *session)
>  		if (size < sizeof(struct perf_event_header) ||
>  		    (skip = perf_session__process_event(session, event, decomp->file_pos,
>  							decomp->file_path)) < 0) {
> -			pr_err("%#" PRIx64 " [%#x]: failed to process type: %d\n",
> -				decomp->file_pos + decomp->head, event->header.size, event->header.type);
> +			pr_err("%#" PRIx64 " [%#x]: decompress event processing failed for event of type: %s (%d)\n",
> +				decomp->file_pos + decomp->head, event->header.size,
> +				perf_event__name(event->header.type),
> +				event->header.type);
>  			return -EINVAL;
>  		}
>  
> @@ -2382,8 +2393,9 @@ reader__read_event(struct reader *rd, struct perf_session *session,
>  	if (size < sizeof(struct perf_event_header) ||
>  	    (skip = rd->process(session, event, rd->file_pos, rd->path)) < 0) {
>  		errno = -skip;
> -		pr_err("%#" PRIx64 " [%#x]: failed to process type: %d [%m]\n",
> +		pr_err("%#" PRIx64 " [%#x]: processing failed for event of type: %s (%d) [%m]\n",
>  		       rd->file_offset + rd->head, event->header.size,
> +		       perf_event__name(event->header.type),
>  		       event->header.type);
>  		err = skip;
>  		goto out;
> -- 
> 2.53.0.414.gf7e9f6c205-goog
> 

Re: [PATCH v1 4/5] perf header: Refactor pipe mode end marker handling

[Namhyung Kim]

On Wed, Feb 25, 2026 at 05:35:33PM -0800, Ian Rogers wrote:
> In non-pipe/data mode the header has a 256-bit bitmap representing
> whether a feature is enabled or not. In pipe mode features are written
> out in perf_event__synthesize_features as PERF_RECORD_HEADER_FEATURE
> events with a special zero sized marker for the last feature. If a new
> feature is added the last feature marker event appears as that feature
> from old pipe mode perf data. As the event is zero sized it will fail
> to be processed and generally terminate perf.
> 
> Add a last_feat variable to the header that in non-pipe/data mode is
> just HEADER_LAST_FEATURE. In pipe mode compute the last_feat by
> handling zero sized feature events, assuming they are the marker and
> updating last_feat accordingly. Potentially a feature event could be
> zero sized and so still process the feature event, just ignore the
> error if it fails.
> 
> As perf_event__process_feature can properly handle pipe mode data,
> migrate users to it except for report that still wants to group events
> with the last feature marker. Make perf_event__process_feature
> non-fatal in the case of a newer feature than this version of perf's
> HEADER_LAST_FEATURE, which was the behavior all users wanted.
> 
> Signed-off-by: Ian Rogers <irogers@google.com>
> ---
>  tools/perf/builtin-annotate.c       | 11 +-----
>  tools/perf/builtin-report.c         | 27 ++++++---------
>  tools/perf/builtin-script.c         | 11 +-----
>  tools/perf/util/data-convert-bt.c   |  9 ++---
>  tools/perf/util/data-convert-json.c | 12 +------
>  tools/perf/util/header.c            | 53 ++++++++++++++++++++++-------
>  tools/perf/util/header.h            |  4 ++-
>  tools/perf/util/intel-tpebs.c       | 11 +-----
>  8 files changed, 60 insertions(+), 78 deletions(-)
> 
> diff --git a/tools/perf/builtin-annotate.c b/tools/perf/builtin-annotate.c
> index 9c27bb30b708..cf2d2011e148 100644
> --- a/tools/perf/builtin-annotate.c
> +++ b/tools/perf/builtin-annotate.c
> @@ -313,15 +313,6 @@ static int process_sample_event(const struct perf_tool *tool,
>  	return ret;
>  }
>  
> -static int process_feature_event(const struct perf_tool *tool __maybe_unused,
> -				 struct perf_session *session,
> -				 union perf_event *event)
> -{
> -	if (event->feat.feat_id < HEADER_LAST_FEATURE)
> -		return perf_event__process_feature(session, event);
> -	return 0;
> -}
> -
>  static int hist_entry__stdio_annotate(struct hist_entry *he,
>  				    struct evsel *evsel,
>  				    struct perf_annotate *ann)
> @@ -876,7 +867,7 @@ int cmd_annotate(int argc, const char **argv)
>  	annotate.tool.id_index	= perf_event__process_id_index;
>  	annotate.tool.auxtrace_info	= perf_event__process_auxtrace_info;
>  	annotate.tool.auxtrace	= perf_event__process_auxtrace;
> -	annotate.tool.feature	= process_feature_event;
> +	annotate.tool.feature	= perf_event__process_feature;
>  	annotate.tool.ordering_requires_timestamps = true;
>  
>  	annotate.session = perf_session__new(&data, &annotate.tool);
> diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
> index 3b81f4b3dc49..d1163f22648e 100644
> --- a/tools/perf/builtin-report.c
> +++ b/tools/perf/builtin-report.c
> @@ -245,25 +245,18 @@ static int process_feature_event(const struct perf_tool *tool,
>  				 union perf_event *event)
>  {
>  	struct report *rep = container_of(tool, struct report, tool);
> +	int ret = perf_event__process_feature(tool, session, event);
>  
> -	if (event->feat.feat_id < HEADER_LAST_FEATURE)
> -		return perf_event__process_feature(session, event);
> -
> -	if (event->feat.feat_id != HEADER_LAST_FEATURE) {
> -		pr_err("failed: wrong feature ID: %" PRI_lu64 "\n",
> -		       event->feat.feat_id);
> -		return -1;
> -	} else if (rep->header_only) {
> -		session_done = 1;

It looks like this part is missing.  Still need to handle --header-only
option.


> +	if (ret == 0 && event->header.size == sizeof(struct perf_record_header_feature) &&
> +	    (int)event->feat.feat_id == session->header.last_feat) {
> +		/*
> +		 * (feat_id = HEADER_LAST_FEATURE) is the end marker which means
> +		 * all features are received, now we can force the group if
> +		 * needed.
> +		 */
> +		setup_forced_leader(rep, session->evlist);
>  	}
> -
> -	/*
> -	 * (feat_id = HEADER_LAST_FEATURE) is the end marker which
> -	 * means all features are received, now we can force the
> -	 * group if needed.
> -	 */
> -	setup_forced_leader(rep, session->evlist);
> -	return 0;
> +	return ret;
>  }
>  
>  static int process_sample_event(const struct perf_tool *tool,
> diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c
> index 7c743a303507..92b76ff24f16 100644
> --- a/tools/perf/builtin-script.c
> +++ b/tools/perf/builtin-script.c
> @@ -3939,15 +3939,6 @@ int process_cpu_map_event(const struct perf_tool *tool,
>  	return set_maps(script);
>  }
>  
> -static int process_feature_event(const struct perf_tool *tool __maybe_unused,
> -				 struct perf_session *session,
> -				 union perf_event *event)
> -{
> -	if (event->feat.feat_id < HEADER_LAST_FEATURE)
> -		return perf_event__process_feature(session, event);
> -	return 0;
> -}
> -
>  static int perf_script__process_auxtrace_info(const struct perf_tool *tool,
>  					      struct perf_session *session,
>  					      union perf_event *event)
> @@ -4423,7 +4414,7 @@ int cmd_script(int argc, const char **argv)
>  #ifdef HAVE_LIBTRACEEVENT
>  	script.tool.tracing_data	 = perf_event__process_tracing_data;
>  #endif
> -	script.tool.feature		 = process_feature_event;
> +	script.tool.feature		 = perf_event__process_feature;
>  	script.tool.build_id		 = perf_event__process_build_id;
>  	script.tool.id_index		 = perf_event__process_id_index;
>  	script.tool.auxtrace_info	 = perf_script__process_auxtrace_info;
> diff --git a/tools/perf/util/data-convert-bt.c b/tools/perf/util/data-convert-bt.c
> index ba1c8e48d495..665bf8eea24b 100644
> --- a/tools/perf/util/data-convert-bt.c
> +++ b/tools/perf/util/data-convert-bt.c
> @@ -1412,13 +1412,10 @@ static int process_feature_event(const struct perf_tool *tool,
>  	struct convert *c = container_of(tool, struct convert, tool);
>  	struct ctf_writer *cw = &c->writer;
>  	struct perf_record_header_feature *fe = &event->feat;
> +	int ret = perf_event__process_feature(tool, session, event);
>  
> -	if (event->feat.feat_id < HEADER_LAST_FEATURE) {
> -		int ret = perf_event__process_feature(session, event);
> -
> -		if (ret)
> -			return ret;
> -	}
> +	if (ret)
> +		return ret;
>  
>  	switch (fe->feat_id) {
>  	case HEADER_HOSTNAME:
> diff --git a/tools/perf/util/data-convert-json.c b/tools/perf/util/data-convert-json.c
> index 6a626322476a..4b1b2f7bed25 100644
> --- a/tools/perf/util/data-convert-json.c
> +++ b/tools/perf/util/data-convert-json.c
> @@ -326,16 +326,6 @@ static void output_headers(struct perf_session *session, struct convert_json *c)
>  	output_json_format(out, false, 2, "]");
>  }
>  
> -static int process_feature_event(const struct perf_tool *tool __maybe_unused,
> -				 struct perf_session *session,
> -				 union perf_event *event)
> -{
> -	if (event->feat.feat_id < HEADER_LAST_FEATURE)
> -		return perf_event__process_feature(session, event);
> -
> -	return 0;
> -}
> -
>  int bt_convert__perf2json(const char *input_name, const char *output_name,
>  		struct perf_data_convert_opts *opts __maybe_unused)
>  {
> @@ -375,7 +365,7 @@ int bt_convert__perf2json(const char *input_name, const char *output_name,
>  	c.tool.auxtrace       = perf_event__process_auxtrace;
>  	c.tool.event_update   = perf_event__process_event_update;
>  	c.tool.attr           = perf_event__process_attr;
> -	c.tool.feature        = process_feature_event;
> +	c.tool.feature        = perf_event__process_feature;
>  	c.tool.ordering_requires_timestamps = true;
>  
>  	if (opts->all) {
> diff --git a/tools/perf/util/header.c b/tools/perf/util/header.c
> index fe5d21dde04f..7031f6c6bd66 100644
> --- a/tools/perf/util/header.c
> +++ b/tools/perf/util/header.c
> @@ -3785,11 +3785,11 @@ static int perf_file_section__fprintf_info(struct perf_file_section *section,
>  	struct feat_fd ff;
>  
>  	if (lseek(fd, section->offset, SEEK_SET) == (off_t)-1) {
> -		pr_debug("Failed to lseek to %" PRIu64 " offset for feature "
> -				"%d, continuing...\n", section->offset, feat);
> +		pr_debug("Failed to lseek to %" PRIu64 " offset for feature %s (%d), continuing...\n",
> +			 section->offset, header_feat__name(feat), feat);
>  		return 0;
>  	}
> -	if (feat >= HEADER_LAST_FEATURE) {
> +	if (feat >= ph->last_feat) {
>  		pr_warning("unknown feature %d\n", feat);
>  		return 0;
>  	}
> @@ -3841,7 +3841,7 @@ int perf_header__fprintf_info(struct perf_session *session, FILE *fp, bool full)
>  		return 0;
>  
>  	fprintf(fp, "# missing features: ");
> -	for_each_clear_bit(bit, header->adds_features, HEADER_LAST_FEATURE) {
> +	for_each_clear_bit(bit, header->adds_features, header->last_feat) {
>  		if (bit)
>  			fprintf(fp, "%s ", feat_ops[bit].name);
>  	}
> @@ -4171,7 +4171,7 @@ int perf_header__process_sections(struct perf_header *header, int fd,
>  	if (err < 0)
>  		goto out_free;
>  
> -	for_each_set_bit(feat, header->adds_features, HEADER_LAST_FEATURE) {
> +	for_each_set_bit(feat, header->adds_features, header->last_feat) {
>  		err = process(sec++, header, feat, fd, data);
>  		if (err < 0)
>  			goto out_free;
> @@ -4386,6 +4386,7 @@ int perf_file_header__read(struct perf_file_header *header,
>  	ph->data_offset  = header->data.offset;
>  	ph->data_size	 = header->data.size;
>  	ph->feat_offset  = header->data.offset + header->data.size;
> +	ph->last_feat	 = HEADER_LAST_FEATURE;
>  	return 0;
>  }
>  
> @@ -4401,8 +4402,8 @@ static int perf_file_section__process(struct perf_file_section *section,
>  	};
>  
>  	if (lseek(fd, section->offset, SEEK_SET) == (off_t)-1) {
> -		pr_debug("Failed to lseek to %" PRIu64 " offset for feature "
> -			  "%d, continuing...\n", section->offset, feat);
> +		pr_debug("Failed to lseek to %" PRIu64 " offset for feature %s (%d), continuing...\n",
> +			 section->offset, header_feat__name(feat), feat);
>  		return 0;
>  	}
>  
> @@ -4435,6 +4436,8 @@ static int perf_file_header__read_pipe(struct perf_pipe_file_header *header,
>  	if (ph->needs_swap)
>  		header->size = bswap_64(header->size);
>  
> +	/* The last feature is written out as a 0 sized event and will update this value. */
> +	ph->last_feat = 0;
>  	return 0;
>  }
>  
> @@ -4667,31 +4670,55 @@ int perf_session__read_header(struct perf_session *session)
>  	return -ENOMEM;
>  }
>  
> -int perf_event__process_feature(struct perf_session *session,
> +int perf_event__process_feature(const struct perf_tool *tool __maybe_unused,
> +				struct perf_session *session,
>  				union perf_event *event)
>  {
>  	struct feat_fd ff = { .fd = 0 };
>  	struct perf_record_header_feature *fe = (struct perf_record_header_feature *)event;
> +	struct perf_header *header = &session->header;
>  	int type = fe->header.type;
> -	u64 feat = fe->feat_id;
> +	int feat = (int)fe->feat_id;
>  	int ret = 0;
>  	bool print = dump_trace;
> +	bool last_feature_mark = false;
>  
>  	if (type < 0 || type >= PERF_RECORD_HEADER_MAX) {
>  		pr_warning("invalid record type %d in pipe-mode\n", type);
>  		return 0;
>  	}
> -	if (feat == HEADER_RESERVED || feat >= HEADER_LAST_FEATURE) {
> -		pr_warning("invalid record type %d in pipe-mode\n", type);
> +	if (feat == HEADER_RESERVED) {
> +		pr_warning("invalid reserved record type in pipe-mode\n");
>  		return -1;
>  	}
> +	if (feat >= header->last_feat) {
> +		if (event->header.size == sizeof(*fe)) {
> +			// Either an unexpected zero size feature or the
> +			// HEADER_LAST_FEATURE mark.

Nit: I think we prefer C-style block comments.


> +			if (feat > header->last_feat)
> +				header->last_feat = min(feat, HEADER_LAST_FEATURE);
> +			last_feature_mark = true;
> +		} else {
> +			// A feature but beyond what is known as in
> +			// bounds. Assume the last feature is 1 beyond this
> +			// feature.

Ditto.

Thanks,
Namhyung


> +			session->header.last_feat = min(feat + 1, HEADER_LAST_FEATURE);
> +		}
> +	}
> +	if (feat >= HEADER_LAST_FEATURE) {
> +		pr_warning("unknown feature %d for data file version (%s) in this version of perf (%s)\n",
> +			   feat, header->env.version, perf_version_string);
> +		return 0;
> +	}
>  
>  	ff.buf  = (void *)fe->data;
>  	ff.size = event->header.size - sizeof(*fe);
> -	ff.ph = &session->header;
> +	ff.ph = header;
>  
>  	if (feat_ops[feat].process && feat_ops[feat].process(&ff, NULL)) {
> -		ret = -1;
> +		// Processing failed, ignore when this is the last feature mark.
> +		if (!last_feature_mark)
> +			ret = -1;
>  		goto out;
>  	}
>  
> diff --git a/tools/perf/util/header.h b/tools/perf/util/header.h
> index ca22030a1434..41ce663d93ff 100644
> --- a/tools/perf/util/header.h
> +++ b/tools/perf/util/header.h
> @@ -109,6 +109,7 @@ struct perf_header {
>  	u64				data_size;
>  	u64				feat_offset;
>  	DECLARE_BITMAP(adds_features, HEADER_FEAT_BITS);
> +	int				last_feat;
>  	struct perf_env 	env;
>  };
>  
> @@ -172,7 +173,8 @@ int perf_header__process_sections(struct perf_header *header, int fd,
>  
>  int perf_header__fprintf_info(struct perf_session *s, FILE *fp, bool full);
>  
> -int perf_event__process_feature(struct perf_session *session,
> +int perf_event__process_feature(const struct perf_tool *tool,
> +				struct perf_session *session,
>  				union perf_event *event);
>  int perf_event__process_attr(const struct perf_tool *tool, union perf_event *event,
>  			     struct evlist **pevlist);
> diff --git a/tools/perf/util/intel-tpebs.c b/tools/perf/util/intel-tpebs.c
> index 3c958d738ca6..f57ea6db02a0 100644
> --- a/tools/perf/util/intel-tpebs.c
> +++ b/tools/perf/util/intel-tpebs.c
> @@ -217,15 +217,6 @@ static int process_sample_event(const struct perf_tool *tool __maybe_unused,
>  	return 0;
>  }
>  
> -static int process_feature_event(const struct perf_tool *tool __maybe_unused,
> -				 struct perf_session *session,
> -				 union perf_event *event)
> -{
> -	if (event->feat.feat_id < HEADER_LAST_FEATURE)
> -		return perf_event__process_feature(session, event);
> -	return 0;
> -}
> -
>  static void *__sample_reader(void *arg __maybe_unused)
>  {
>  	struct perf_session *session;
> @@ -238,7 +229,7 @@ static void *__sample_reader(void *arg __maybe_unused)
>  
>  	perf_tool__init(&tool, /*ordered_events=*/false);
>  	tool.sample = process_sample_event;
> -	tool.feature = process_feature_event;
> +	tool.feature = perf_event__process_feature;
>  	tool.attr = perf_event__process_attr;
>  
>  	session = perf_session__new(&data, &tool);
> -- 
> 2.53.0.414.gf7e9f6c205-goog
>