Skip to contentSkip to conversation

perf trace: Add --print-sample

tip:perf/core tip-bot for Arnaldo Carvalho de Melo 1 participant 1 message Jan 24, 2018 perf events

lore
Share & tools
lore

tip-bot for Arnaldo Carvalho de Melo

author merge bot
#0 lore raw
Commit-ID:  051d26532c21eceac8ff042f1b60af9ba748b433
Gitweb:     https://git.kernel.org/tip/051d26532c21eceac8ff042f1b60af9ba748b433
Author:     Arnaldo Carvalho de Melo <[email protected]>
AuthorDate: Mon, 22 Jan 2018 11:38:54 -0300
Committer:  Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Tue, 23 Jan 2018 09:51:50 -0300

perf trace: Add --print-sample

To help with debugging, like the interrupted out of order issue that will be dealt with in the next patch in this series, changing the code to deal with:

raw_syscalls:sys_enter 411967179.269 Timer 9609/9626 [2] raw_syscalls:sys_enter 411967179.213 file:// Content 9609/9609 [3]
328.038 (18446744073709.496 ms): Timer/9626 futex(uaddr: 0x7fc0d4027044, op: WAIT|PRIV, utime: 0x7fc0b0ffdb50 ) ...
raw_syscalls:sys_exit 411967179.225 file:// Content 9609/9609 [3]
327.982 ( 0.012 ms): file:// Conten/9609 futex(uaddr: 0x7fc0d4027040, op: WAKE|PRIV, val: 1 ) = 1

That long duration is the bug.

Cc Adrian Hunter <[email protected]>
Cc David Ahern <[email protected]>
Cc Jiri Olsa <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Wang Nan <[email protected]>
Link https://lkml.kernel.org/n/[email protected] open here
Signed-off-by Arnaldo Carvalho de Melo <[email protected]>
---
 tools/perf/Documentation/perf-trace.txt |  4 ++++
 tools/perf/builtin-trace.c              | 24 ++++++++++++++++++++++++
 2 files changed, 28 insertions(+)
tools/perf/Documentation/perf-trace.txt +4 -0
index 6909cf1..33a88e9 100644
@@ -163,6 +163,10 @@ the thread executes on the designated CPUs. Default is to monitor all CPUs.
         Implies '--call-graph dwarf' when --call-graph not present on the
         command line, on systems where DWARF unwinding was built in.
 
+--print-sample::
+	Print the PERF_RECORD_SAMPLE PERF_SAMPLE_ info for the
+	raw_syscalls:sys_{enter,exit} tracepoints, for debugging.
+
 --proc-map-timeout::
 	When processing pre-existing threads /proc/XXX/mmap, it may take a long time,
 	because the file may be huge. A time out is needed in such cases.
tools/perf/builtin-trace.c +24 -0
index 7dece5e..322c2b1 100644
@@ -110,6 +110,7 @@ struct trace {
 	bool			summary;
 	bool			summary_only;
 	bool			show_comm;
+	bool			print_sample;
 	bool			show_tool_stats;
 	bool			trace_syscalls;
 	bool			kernel_syscallchains;

@@ -1578,6 +1579,23 @@ static int trace__printf_interrupted_entry(struct trace *trace, struct perf_samp
 	return printed;
 }
 
+static int trace__fprintf_sample(struct trace *trace, struct perf_evsel *evsel,
+				 struct perf_sample *sample, struct thread *thread)
+{
+	int printed = 0;
+
+	if (trace->print_sample) {
+		double ts = (double)sample->time / NSEC_PER_MSEC;
+
+		printed += fprintf(trace->output, "%22s %10.3f %s %d/%d [%d]\n",
+				   perf_evsel__name(evsel), ts,
+				   thread__comm_str(thread),
+				   sample->pid, sample->tid, sample->cpu);
+	}
+
+	return printed;
+}
+
 static int trace__sys_enter(struct trace *trace, struct perf_evsel *evsel,
 			    union perf_event *event __maybe_unused,
 			    struct perf_sample *sample)

@@ -1598,6 +1616,8 @@ static int trace__sys_enter(struct trace *trace, struct perf_evsel *evsel,
 	if (ttrace == NULL)
 		goto out_put;
 
+	trace__fprintf_sample(trace, evsel, sample, thread);
+
 	args = perf_evsel__sc_tp_ptr(evsel, args, sample);
 
 	if (ttrace->entry_str == NULL) {

@@ -1688,6 +1708,8 @@ static int trace__sys_exit(struct trace *trace, struct perf_evsel *evsel,
 	if (ttrace == NULL)
 		goto out_put;
 
+	trace__fprintf_sample(trace, evsel, sample, thread);
+
 	if (trace->summary)
 		thread__update_stats(ttrace, id, sample);
 

@@ -3034,6 +3056,8 @@ int cmd_trace(int argc, const char **argv)
 		     "Set the maximum stack depth when parsing the callchain, "
 		     "anything beyond the specified depth will be ignored. "
 		     "Default: kernel.perf_event_max_stack or " __stringify(PERF_MAX_STACK_DEPTH)),
+	OPT_BOOLEAN(0, "print-sample", &trace.print_sample,
+			"print the PERF_RECORD_SAMPLE PERF_SAMPLE_ info, for debugging"),
 	OPT_UINTEGER(0, "proc-map-timeout", &trace.opts.proc_map_timeout,
 			"per thread proc mmap processing timeout in ms"),
 	OPT_UINTEGER('D', "delay", &trace.opts.initial_delay,