Skip to contentSkip to conversation

perf intel-pt: Add more information to debug log

PATCH Applied Adrian Hunter 3 participants 6 messages Nov 5, 2018 – Nov 6, 2018 perf events

lore
Share & tools
lore

Adrian Hunter

author reviewer
#0 lore raw

cover perf intel-pt: Add more information to debug log

Hi

Here is a couple of small patches to add more information to the Intel PT debug log.

Adrian Hunter (2):
perf intel-pt: Add more event information to debug log perf intel-pt: Add MTC and CYC timestamps to debug log

 tools/perf/util/intel-pt-decoder/intel-pt-decoder.c |  4 ++++
 tools/perf/util/intel-pt-decoder/intel-pt-log.c     |  5 +++++
 tools/perf/util/intel-pt-decoder/intel-pt-log.h     |  1 +
 tools/perf/util/intel-pt.c                          | 16 +++++++++++++---
 4 files changed, 23 insertions(+), 3 deletions(-)

Regards
Adrian

author reviewer
#1 lore raw

PATCH 1/2 perf intel-pt: Add more event information to debug log

More event information is useful for debugging, especially MMAP events.

Signed-off-by Adrian Hunter <[email protected]>
---
 tools/perf/util/intel-pt-decoder/intel-pt-log.c |  5 +++++
 tools/perf/util/intel-pt-decoder/intel-pt-log.h |  1 +
 tools/perf/util/intel-pt.c                      | 16 +++++++++++++---
 3 files changed, 19 insertions(+), 3 deletions(-)
tools/perf/util/intel-pt-decoder/intel-pt-log.c +5 -0
index e02bc7b166a0..5e64da270f97 100644
@@ -31,6 +31,11 @@ static FILE *f;
 static char log_name[MAX_LOG_NAME];
 bool intel_pt_enable_logging;
 
+void *intel_pt_log_fp(void)
+{
+	return f;
+}
+
 void intel_pt_log_enable(void)
 {
 	intel_pt_enable_logging = true;
tools/perf/util/intel-pt-decoder/intel-pt-log.h +1 -0
index 45b64f93f358..cc084937f701 100644
@@ -22,6 +22,7 @@
 
 struct intel_pt_pkt;
 
+void *intel_pt_log_fp(void);
 void intel_pt_log_enable(void);
 void intel_pt_log_disable(void);
 void intel_pt_log_set_name(const char *name);
tools/perf/util/intel-pt.c +13 -3
index ffa385a029b3..71339d1d4340 100644
@@ -206,6 +206,16 @@ static void intel_pt_dump_event(struct intel_pt *pt, unsigned char *buf,
 	intel_pt_dump(pt, buf, len);
 }
 
+static void intel_pt_log_event(union perf_event *event)
+{
+	FILE *f = intel_pt_log_fp();
+
+	if (!intel_pt_enable_logging || !f)
+		return;
+
+	perf_event__fprintf(event, f);
+}
+
 static int intel_pt_do_fix_overlap(struct intel_pt *pt, struct auxtrace_buffer *a,
 				   struct auxtrace_buffer *b)
 {

@@ -2004,9 +2014,9 @@ static int intel_pt_process_event(struct perf_session *session,
 		 event->header.type == PERF_RECORD_SWITCH_CPU_WIDE)
 		err = intel_pt_context_switch(pt, event, sample);
 
-	intel_pt_log("event %s (%u): cpu %d time %"PRIu64" tsc %#"PRIx64"\n",
-		     perf_event__name(event->header.type), event->header.type,
-		     sample->cpu, sample->time, timestamp);
+	intel_pt_log("event %u: cpu %d time %"PRIu64" tsc %#"PRIx64" ",
+		     event->header.type, sample->cpu, sample->time, timestamp);
+	intel_pt_log_event(event);
 
 	return err;
 }
Signature · 1 line
2.17.1
merge bot
#2 lore raw

[tip:perf/urgent] perf intel-pt: Add more event information to debug log

perf intel-pt: Add more event information to debug log
Commit-ID:  93f8be2799515e01647c5a9b0d17a90a00ebcf82
Gitweb:     https://git.kernel.org/tip/93f8be2799515e01647c5a9b0d17a90a00ebcf82
Author:     Adrian Hunter <[email protected]>
AuthorDate: Mon, 5 Nov 2018 09:35:04 +0200
Committer:  Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Mon, 5 Nov 2018 14:53:37 -0300

perf intel-pt: Add more event information to debug log

More event information is useful for debugging, especially MMAP events.

Signed-off-by Adrian Hunter <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Arnaldo Carvalho de Melo <[email protected]>
---
 tools/perf/util/intel-pt-decoder/intel-pt-log.c |  5 +++++
 tools/perf/util/intel-pt-decoder/intel-pt-log.h |  1 +
 tools/perf/util/intel-pt.c                      | 16 +++++++++++++---
 3 files changed, 19 insertions(+), 3 deletions(-)
tools/perf/util/intel-pt-decoder/intel-pt-log.c +5 -0
index e02bc7b166a0..5e64da270f97 100644
@@ -31,6 +31,11 @@ static FILE *f;
 static char log_name[MAX_LOG_NAME];
 bool intel_pt_enable_logging;
 
+void *intel_pt_log_fp(void)
+{
+	return f;
+}
+
 void intel_pt_log_enable(void)
 {
 	intel_pt_enable_logging = true;
tools/perf/util/intel-pt-decoder/intel-pt-log.h +1 -0
index 45b64f93f358..cc084937f701 100644
@@ -22,6 +22,7 @@
 
 struct intel_pt_pkt;
 
+void *intel_pt_log_fp(void);
 void intel_pt_log_enable(void);
 void intel_pt_log_disable(void);
 void intel_pt_log_set_name(const char *name);
tools/perf/util/intel-pt.c +13 -3
index 86cc9a64e982..149ff361ca78 100644
@@ -206,6 +206,16 @@ static void intel_pt_dump_event(struct intel_pt *pt, unsigned char *buf,
 	intel_pt_dump(pt, buf, len);
 }
 
+static void intel_pt_log_event(union perf_event *event)
+{
+	FILE *f = intel_pt_log_fp();
+
+	if (!intel_pt_enable_logging || !f)
+		return;
+
+	perf_event__fprintf(event, f);
+}
+
 static int intel_pt_do_fix_overlap(struct intel_pt *pt, struct auxtrace_buffer *a,
 				   struct auxtrace_buffer *b)
 {

@@ -2010,9 +2020,9 @@ static int intel_pt_process_event(struct perf_session *session,
 		 event->header.type == PERF_RECORD_SWITCH_CPU_WIDE)
 		err = intel_pt_context_switch(pt, event, sample);
 
-	intel_pt_log("event %s (%u): cpu %d time %"PRIu64" tsc %#"PRIx64"\n",
-		     perf_event__name(event->header.type), event->header.type,
-		     sample->cpu, sample->time, timestamp);
+	intel_pt_log("event %u: cpu %d time %"PRIu64" tsc %#"PRIx64" ",
+		     event->header.type, sample->cpu, sample->time, timestamp);
+	intel_pt_log_event(event);
 
 	return err;
 }
author reviewer
#3 lore raw

PATCH 2/2 perf intel-pt: Add MTC and CYC timestamps to debug log

In reply to Adrian Hunter

One cause of decoding errors is un-synchronized side-band data. Timestamps are needed to debug such cases. TSC packet timestamps are logged. Log also MTC and CYC timestamps.

Signed-off-by Adrian Hunter <[email protected]>
---
 tools/perf/util/intel-pt-decoder/intel-pt-decoder.c | 4 ++++
 1 file changed, 4 insertions(+)
tools/perf/util/intel-pt-decoder/intel-pt-decoder.c +4 -0
index 58f6a9ceb590..4503f3ca45ab 100644
@@ -1474,6 +1474,8 @@ static void intel_pt_calc_mtc_timestamp(struct intel_pt_decoder *decoder)
 		decoder->have_calc_cyc_to_tsc = false;
 		intel_pt_calc_cyc_to_tsc(decoder, true);
 	}
+
+	intel_pt_log_to("Setting timestamp", decoder->timestamp);
 }
 
 static void intel_pt_calc_cbr(struct intel_pt_decoder *decoder)

@@ -1514,6 +1516,8 @@ static void intel_pt_calc_cyc_timestamp(struct intel_pt_decoder *decoder)
 		decoder->timestamp = timestamp;
 
 	decoder->timestamp_insn_cnt = 0;
+
+	intel_pt_log_to("Setting timestamp", decoder->timestamp);
 }
 
 /* Walk PSB+ packets when already in sync. */
Signature · 1 line
2.17.1
merge bot
#4 lore raw

[tip:perf/urgent] perf intel-pt: Add MTC and CYC timestamps to debug log

perf intel-pt: Add MTC and CYC timestamps to debug log
Commit-ID:  f6c23e3b55cb93f32a724f41af8d38888bc2ab6b
Gitweb:     https://git.kernel.org/tip/f6c23e3b55cb93f32a724f41af8d38888bc2ab6b
Author:     Adrian Hunter <[email protected]>
AuthorDate: Mon, 5 Nov 2018 09:35:05 +0200
Committer:  Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Mon, 5 Nov 2018 14:53:54 -0300

perf intel-pt: Add MTC and CYC timestamps to debug log

One cause of decoding errors is un-synchronized side-band data. Timestamps are needed to debug such cases. TSC packet timestamps are logged. Log also MTC and CYC timestamps.

Signed-off-by Adrian Hunter <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Arnaldo Carvalho de Melo <[email protected]>
---
 tools/perf/util/intel-pt-decoder/intel-pt-decoder.c | 4 ++++
 1 file changed, 4 insertions(+)
tools/perf/util/intel-pt-decoder/intel-pt-decoder.c +4 -0
index 58f6a9ceb590..4503f3ca45ab 100644
@@ -1474,6 +1474,8 @@ static void intel_pt_calc_mtc_timestamp(struct intel_pt_decoder *decoder)
 		decoder->have_calc_cyc_to_tsc = false;
 		intel_pt_calc_cyc_to_tsc(decoder, true);
 	}
+
+	intel_pt_log_to("Setting timestamp", decoder->timestamp);
 }
 
 static void intel_pt_calc_cbr(struct intel_pt_decoder *decoder)

@@ -1514,6 +1516,8 @@ static void intel_pt_calc_cyc_timestamp(struct intel_pt_decoder *decoder)
 		decoder->timestamp = timestamp;
 
 	decoder->timestamp_insn_cnt = 0;
+
+	intel_pt_log_to("Setting timestamp", decoder->timestamp);
 }
 
 /* Walk PSB+ packets when already in sync. */
maintainer Applied
#5 lore raw
In reply to Adrian Hunter

Em Mon, Nov 05, 2018 at 09:35:03AM +0200, Adrian Hunter escreveu:

Quoted 9 lines

Hi

Here is a couple of small patches to add more information to the Intel PT debug log.

Adrian Hunter (2):
perf intel-pt: Add more event information to debug log perf intel-pt: Add MTC and CYC timestamps to debug log

Thanks, applied both patches.

- Arnaldo