[PATCH 2/3] perf: Move all output for perf report -D into trace_event

[Ian Munsie]

From: Ian Munsie <imunsie@xxxxxxxxxxx>

This patch moves all the places that would produce output while doing a
perf report -D into the trace_event routine. This will be necessary to
allow perf report to process events ordered by timestamp and still
produce sane debugging output.

The offset of ordered events in the file are stored in the sample queue
to allow them to be printed in the debugging output as before.

Signed-off-by: Ian Munsie <imunsie@xxxxxxxxxxx>
---
 tools/perf/util/debug.c   |   53 +++++++++++++++++++++++++-
 tools/perf/util/debug.h   |    4 +-
 tools/perf/util/session.c |   92 +++++++++++++-------------------------------
 3 files changed, 82 insertions(+), 67 deletions(-)

diff --git a/tools/perf/util/debug.c b/tools/perf/util/debug.c
index 01bbe8e..d47dff4 100644
--- a/tools/perf/util/debug.c
+++ b/tools/perf/util/debug.c
@@ -11,6 +11,7 @@
 #include "event.h"
 #include "debug.h"
 #include "util.h"
+#include "session.h"
 
 int verbose;
 bool dump_trace = false, quiet = false;
@@ -57,7 +58,36 @@ void ui__warning(const char *format, ...)
 }
 #endif
 
-void trace_event(event_t *event)
+static void callchain__dump(struct sample_data *sample)
+{
+	unsigned int i;
+
+	printf("... chain: nr:%llu\n", sample->callchain->nr);
+
+	for (i = 0; i < sample->callchain->nr; i++)
+		printf("..... %2d: %016llx\n", i, sample->callchain->ips[i]);
+}
+
+static void perf_session__print_tstamp(struct perf_session *session,
+				       event_t *event,
+				       struct sample_data *sample)
+{
+	if (event->header.type != PERF_RECORD_SAMPLE &&
+	    !session->sample_id_all) {
+		fputs("-1 -1 ", stdout);
+		return;
+	}
+
+	if ((session->sample_type & PERF_SAMPLE_CPU))
+		printf("%u ", sample->cpu);
+
+	if (session->sample_type & PERF_SAMPLE_TIME)
+		printf("%llu ", sample->time);
+}
+
+void trace_event(event_t *event, u64 file_offset,
+		 struct perf_session *session,
+		 struct sample_data *sample)
 {
 	unsigned char *raw_event = (void *)event;
 	const char *color = PERF_COLOR_BLUE;
@@ -66,6 +96,9 @@ void trace_event(event_t *event)
 	if (!dump_trace)
 		return;
 
+	printf("\n%#llx [%#x]: event: %d\n",
+	       file_offset, event->header.size, event->header.type);
+
 	printf(".");
 	color_fprintf(stdout, color, "\n. ... raw event: size %d bytes\n",
 		      event->header.size);
@@ -91,4 +124,22 @@ void trace_event(event_t *event)
 		}
 	}
 	printf(".\n");
+
+	if (event->header.type >= PERF_RECORD_MMAP &&
+	    event->header.type <= PERF_RECORD_SAMPLE)
+		perf_session__print_tstamp(session, event, sample);
+
+	if (event->header.type < PERF_RECORD_HEADER_MAX) {
+		printf("%#llx [%#x]: PERF_RECORD_%s",
+		       file_offset, event->header.size,
+		       event__name[event->header.type]);
+	}
+
+	if (event->header.type == PERF_RECORD_SAMPLE) {
+		printf("(IP, %d): %d/%d: %#llx period: %lld\n", event->header.misc,
+		       sample->pid, sample->tid, sample->ip, sample->period);
+
+		if (session->sample_type & PERF_SAMPLE_CALLCHAIN)
+			callchain__dump(sample);
+	}
 }
diff --git a/tools/perf/util/debug.h b/tools/perf/util/debug.h
index ca35fd6..80f0285 100644
--- a/tools/perf/util/debug.h
+++ b/tools/perf/util/debug.h
@@ -9,7 +9,9 @@ extern int verbose;
 extern bool quiet, dump_trace;
 
 int dump_printf(const char *fmt, ...) __attribute__((format(printf, 1, 2)));
-void trace_event(event_t *event);
+void trace_event(event_t *event, u64 file_offset,
+		 struct perf_session *session,
+		 struct sample_data *sample);
 
 struct ui_progress;
 
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index 5c75660..596829f 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -444,6 +444,7 @@ static event__swap_op event__swap_ops[] = {
 
 struct sample_queue {
 	u64			timestamp;
+	u64			file_offset;
 	event_t			*event;
 	struct list_head	list;
 };
@@ -479,6 +480,9 @@ static void flush_sample_queue(struct perf_session *s,
 			break;
 
 		event__parse_sample(iter->event, s, &sample);
+
+		trace_event((event_t *)iter->event, iter->file_offset, s, &sample);
+
 		ops->sample(iter->event, &sample, s);
 
 		os->last_flush = iter->timestamp;
@@ -592,7 +596,7 @@ static void __queue_sample_event(struct sample_queue *new,
 #define MAX_SAMPLE_BUFFER	(64 * 1024 / sizeof(struct sample_queue))
 
 static int queue_sample_event(event_t *event, struct sample_data *data,
-			      struct perf_session *s)
+			      struct perf_session *s, u64 file_offset)
 {
 	struct ordered_samples *os = &s->ordered_samples;
 	struct list_head *sc = &os->sample_cache;
@@ -621,6 +625,7 @@ static int queue_sample_event(event_t *event, struct sample_data *data,
 	}
 
 	new->timestamp = timestamp;
+	new->file_offset = file_offset;
 	new->event = event;
 
 	__queue_sample_event(new, s);
@@ -631,43 +636,16 @@ static int queue_sample_event(event_t *event, struct sample_data *data,
 static int perf_session__process_sample(event_t *event,
 					struct sample_data *sample,
 					struct perf_session *s,
-					struct perf_event_ops *ops)
+					struct perf_event_ops *ops,
+					u64 file_offset)
 {
-	if (!ops->ordered_samples)
+	if (!ops->ordered_samples) {
+		trace_event(event, file_offset, s, sample);
 		return ops->sample(event, sample, s);
-
-	queue_sample_event(event, sample, s);
-	return 0;
-}
-
-static void callchain__dump(struct sample_data *sample)
-{
-	unsigned int i;
-
-	if (!dump_trace)
-		return;
-
-	printf("... chain: nr:%Lu\n", sample->callchain->nr);
-
-	for (i = 0; i < sample->callchain->nr; i++)
-		printf("..... %2d: %016Lx\n", i, sample->callchain->ips[i]);
-}
-
-static void perf_session__print_tstamp(struct perf_session *session,
-				       event_t *event,
-				       struct sample_data *sample)
-{
-	if (event->header.type != PERF_RECORD_SAMPLE &&
-	    !session->sample_id_all) {
-		fputs("-1 -1 ", stdout);
-		return;
 	}
 
-	if ((session->sample_type & PERF_SAMPLE_CPU))
-		printf("%u ", sample->cpu);
-
-	if (session->sample_type & PERF_SAMPLE_TIME)
-		printf("%Lu ", sample->time);
+	queue_sample_event(event, sample, s, file_offset);
+	return 0;
 }
 
 static int perf_session__process_event(struct perf_session *self,
@@ -677,44 +655,34 @@ static int perf_session__process_event(struct perf_session *self,
 {
 	struct sample_data sample;
 
-	trace_event(event);
-
 	if (self->header.needs_swap && event__swap_ops[event->header.type])
 		event__swap_ops[event->header.type](event);
 
 	if (event->header.type >= PERF_RECORD_MMAP &&
-	    event->header.type <= PERF_RECORD_SAMPLE) {
+	    event->header.type <= PERF_RECORD_SAMPLE)
 		event__parse_sample(event, self, &sample);
-		if (dump_trace)
-			perf_session__print_tstamp(self, event, &sample);
-	}
 
-	if (event->header.type < PERF_RECORD_HEADER_MAX) {
-		dump_printf("%#Lx [%#x]: PERF_RECORD_%s",
-			    file_offset, event->header.size,
-			    event__name[event->header.type]);
+	if (event->header.type < PERF_RECORD_HEADER_MAX)
 		hists__inc_nr_events(&self->hists, event->header.type);
-	}
 
 	switch (event->header.type) {
 	case PERF_RECORD_SAMPLE:
-		dump_printf("(IP, %d): %d/%d: %#Lx period: %Ld\n", event->header.misc,
-			    sample.pid, sample.tid, sample.ip, sample.period);
-
-		if (self->sample_type & PERF_SAMPLE_CALLCHAIN) {
-			if (!ip_callchain__valid(sample.callchain, event)) {
-				pr_debug("call-chain problem with event, "
-					 "skipping it.\n");
-				++self->hists.stats.nr_invalid_chains;
-				self->hists.stats.total_invalid_chains += sample.period;
-				return 0;
-			}
-
-			callchain__dump(&sample);
+		if (self->sample_type & PERF_SAMPLE_CALLCHAIN &&
+		    !ip_callchain__valid(sample.callchain, event)) {
+			pr_debug("call-chain problem with event, "
+				 "skipping it.\n");
+			++self->hists.stats.nr_invalid_chains;
+			self->hists.stats.total_invalid_chains += sample.period;
+			return 0;
 		}
 
-		return perf_session__process_sample(event, &sample, self, ops);
+		return perf_session__process_sample(event, &sample, self, ops, file_offset);
+	default: break;
+	}
+
+	trace_event(event, file_offset, self, &sample);
 
+	switch (event->header.type) {
 	case PERF_RECORD_MMAP:
 		return ops->mmap(event, &sample, self);
 	case PERF_RECORD_COMM:
@@ -851,9 +819,6 @@ more:
 
 	head += size;
 
-	dump_printf("\n%#Lx [%#x]: event: %d\n",
-		    head, event.header.size, event.header.type);
-
 	if (skip > 0)
 		head += skip;
 
@@ -942,9 +907,6 @@ more:
 
 	size = event->header.size;
 
-	dump_printf("\n%#Lx [%#x]: event: %d\n",
-		    file_pos, event->header.size, event->header.type);
-
 	if (size == 0 ||
 	    perf_session__process_event(session, event, ops, file_pos) < 0) {
 		dump_printf("%#Lx [%#x]: skipping unknown header type: %d\n",
-- 
1.7.2.3

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/