[PATCH 2/2] perf tools: Add option to show time history of event samples

[David Ahern <daahern@cisco.com>]

Add a timehist option to perf record to save cpu and kernel timestamp
with each sample.

Add timehist option to perf report to display a pretty-print format
of the timestamp, cpu, and event data each event rather than
generating a histogram. The timehist option leverages the reference
timestamp from the perf header to correlate kernel timestamps to
time-of-day which allows correlating with external (non-perf)
log files.

As an example, consider recording context switches:
    perf record -e cs -c 1 -ga --timehist

Today the 'perf report -D' option gives output in the form
0 182392227877 0x17d8f8 [0xd8]: PERF_RECORD_SAMPLE(IP, 1): \
	1861/1861: 0xffffffff810348d2 period: 2057672
... chain: nr:21
.....  0: ffffffffffffff80
.....  1: ffffffff810348d2
.....  2: ffffffff8139c02b
.....  3: ffffffffa004b4a3
.....  4: ffffffff8139c79c
.....  5: ffffffff8139c83d
.....  6: ffffffffa004b43f
.....  7: ffffffffa00ec135
.....  8: ffffffffa00ec214
.....  9: ffffffffa00f01ec
..... 10: ffffffffa00f0439
..... 11: ffffffffa00d6e8b
..... 12: ffffffff8110b763
..... 13: ffffffff8110b883
..... 14: ffffffff8110ddcd
..... 15: ffffffff8110e45d
..... 16: ffffffff81101f36
..... 17: ffffffff81101ff3
..... 18: ffffffff81002c82
..... 19: fffffffffffffe00
..... 20: 00002acfd31ce050
 ... thread: cc1:1861
 ...... dso: /lib/modules/2.6.37-rc5/build/vmlinux

With the timehist option 'perf report --timehist' displays the same sample as
(lines wrapped to < 80 and truncated here):

17:11:10.174502     182392227877    0  cc1   1861  \
	ffffffff810348d2  perf_event_task_sched_out ([kernel.kallsyms])
17:11:10.174502     182392227877    0  cc1   1861  \
	ffffffff8139c02b  schedule ([kernel.kallsyms])
17:11:10.174502     182392227877    0  cc1   1861  \
	ffffffffa004b4a3  rpc_wait_bit_killable (/lib/modules/2.6.37-rc5/...
17:11:10.174502     182392227877    0  cc1   1861  \
	ffffffff8139c79c  __wait_on_bit ([kernel.kallsyms])
17:11:10.174502     182392227877    0  cc1   1861  \
	ffffffff8139c83d  out_of_line_wait_on_bit ([kernel.kallsyms])
17:11:10.174502     182392227877    0  cc1   1861  \
	ffffffffa004b43f  __rpc_wait_for_completion_task (/lib/modules/...
17:11:10.174502     182392227877    0  cc1   1861  \
	ffffffffa00ec135  nfs4_wait_for_completion_rpc_task (/lib/modules/...
17:11:10.174502     182392227877    0  cc1   1861  \
	ffffffffa00ec214  nfs4_run_open_task (/lib/modules/2.6.37-rc5/...
17:11:10.174502     182392227877    0  cc1   1861  \
	ffffffffa00f01ec  nfs4_do_open.clone.21 (/lib/modules/2.6.37-rc5/...
17:11:10.174502     182392227877    0  cc1   1861  \
 	ffffffffa00f0439  nfs4_atomic_open (/lib/modules/2.6.37-rc5/...
17:11:10.174502     182392227877    0  cc1   1861  \
	ffffffffa00d6e8b  nfs_open_revalidate (/lib/modules/2.6.37-rc5/...
17:11:10.174502     182392227877    0  cc1   1861  \
	ffffffff8110b763  do_revalidate ([kernel.kallsyms])
17:11:10.174502     182392227877    0  cc1   1861  \
	ffffffff8110b883  do_lookup ([kernel.kallsyms])
17:11:10.174502     182392227877    0  cc1   1861  \
	ffffffff8110ddcd  do_last ([kernel.kallsyms])
17:11:10.174502     182392227877    0  cc1   1861  \
	ffffffff8110e45d  do_filp_open ([kernel.kallsyms])
17:11:10.174502     182392227877    0  cc1   1861  \
	ffffffff81101f36  do_sys_open ([kernel.kallsyms])
17:11:10.174502     182392227877    0  cc1   1861  \
	ffffffff81101ff3  sys_open ([kernel.kallsyms])
17:11:10.174502     182392227877    0  cc1   1861  \
	ffffffff81002c82  system_call ([kernel.kallsyms])
17:11:10.174502     182392227877    0  cc1   1861  \
	    2acfd31ce050  __GI___libc_open (/lib64/libc-2.12.90.so)

While the line lengths are horrible for a git commit message and email,
the data is indispensable. It allows you to see each schedule out point,
where the process is when it gets scheduled out and, with additional
processing on the timehist output, time between schedule-in events and
time on the processor.

Signed-off-by: David Ahern <daahern@cisco.com>
---
 tools/perf/builtin-record.c |    8 +++
 tools/perf/builtin-report.c |  131 ++++++++++++++++++++++++++++++++++++++++++-
 2 files changed, 137 insertions(+), 2 deletions(-)

diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
index 699dd21..cf30c98 100644
--- a/tools/perf/builtin-record.c
+++ b/tools/perf/builtin-record.c
@@ -51,6 +51,7 @@ static int			realtime_prio			=      0;
 static bool			raw_samples			=  false;
 static bool			sample_id_all_avail		=   true;
 static bool			system_wide			=  false;
+static bool			time_history			=  false;
 static pid_t			target_pid			=     -1;
 static pid_t			target_tid			=     -1;
 static pid_t			*all_tids			=      NULL;
@@ -288,6 +289,11 @@ static void create_counter(int counter, int cpu)
 	if (sample_time)
 		attr->sample_type	|= PERF_SAMPLE_TIME;
 
+	if (time_history) {
+		attr->sample_type	|= PERF_SAMPLE_TIME;
+		attr->sample_type	|= PERF_SAMPLE_CPU;
+	}
+
 	if (raw_samples) {
 		attr->sample_type	|= PERF_SAMPLE_TIME;
 		attr->sample_type	|= PERF_SAMPLE_RAW;
@@ -863,6 +869,8 @@ const struct option record_options[] = {
 		    "do not update the buildid cache"),
 	OPT_BOOLEAN('B', "no-buildid", &no_buildid,
 		    "do not collect buildids in perf.data"),
+	OPT_BOOLEAN(0, "timehist", &time_history,
+		    "collect data for time history report"),
 	OPT_END()
 };
 
diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
index 904519f..bcde3c2 100644
--- a/tools/perf/builtin-report.c
+++ b/tools/perf/builtin-report.c
@@ -35,6 +35,7 @@ static char		const *input_name = "perf.data";
 static bool		force, use_tui, use_stdio;
 static bool		hide_unresolved;
 static bool		dont_use_callchains;
+static bool		time_history;
 
 static bool		show_threads;
 static struct perf_read_values	show_threads_values;
@@ -124,6 +125,117 @@ out_free_syms:
 	return err;
 }
 
+static const char *timestr(u64 timestamp, struct perf_session *session)
+{
+	struct tm ltime;
+	u64 dt;
+	struct timeval tv_dt, tv_res;
+	static char tstr[64];
+
+	dt = timestamp - session->header.nsec_ref;
+	tv_dt.tv_sec = (time_t) (dt / NSEC_PER_SEC);
+	tv_dt.tv_usec = (suseconds_t) ((dt - tv_dt.tv_sec * NSEC_PER_SEC) / 1000);
+
+	timeradd(&session->header.tv_ref, &tv_dt, &tv_res);
+
+	if ((session->header.nsec_ref == 0) ||
+		(localtime_r(&tv_res.tv_sec, &ltime) == NULL)) {
+		snprintf(tstr, sizeof(tstr), "00:00:00.000000 %16Ld", timestamp);
+	} else {
+		char date[64];
+		strftime(date, sizeof(date), "%H:%M:%S", &ltime);
+		snprintf(tstr, sizeof(tstr), "%s.%06ld %16Ld",
+		         date, tv_res.tv_usec, timestamp);
+	}
+
+	return tstr;
+}
+
+#define TIMEHIST_FMT  "%32s  %3d  %-16s %5d  %16Lx  %s (%s)\n"
+
+static void timehist_header(void)
+{
+	printf("%32s  %3s  %-16s %5s  %16s  %s (%s)\n",
+		   "  Time-of-Day   Kernel Timestamp",
+	       "cpu", "Command Name", "PID",
+	       "    IP    ", "Symbol Name", "DSO Name");
+}
+
+static int perf_session__print_sample(struct perf_session *session,
+					struct addr_location *al,
+					struct sample_data *data)
+{
+	static int show_timehist_error = 1;
+	u64 timestamp = 0;
+	struct map_symbol *syms = NULL;
+	struct symbol *parent = NULL;
+	const char *tstr;
+	bool need_spacer = false;
+
+	if (show_timehist_error && ((data->cpu == (u32) -1) ||
+		 !(session->sample_type & PERF_SAMPLE_TIME))) {
+		pr_err("Data for time history missing in perf event samples.\n"
+		       "Did you record with --timehist option?\n");
+		show_timehist_error = 0;
+	}
+
+	if (session->sample_type & PERF_SAMPLE_TIME)
+		timestamp = data->time;
+
+	tstr = timestr(timestamp, session);
+
+
+	if ((symbol_conf.use_callchain) && data->callchain) {
+		u64 i;
+
+		syms = perf_session__resolve_callchain(session, al->thread,
+						   data->callchain, &parent);
+		if (syms == NULL)
+			return -ENOMEM;
+
+		for (i = 0; i < data->callchain->nr; ++i) {
+			const char *symname = "", *dsoname = "";
+
+			if (data->callchain->ips[i] >= PERF_CONTEXT_MAX)
+				continue;
+
+			if (syms[i].sym && syms[i].sym->name)
+				symname = syms[i].sym->name;
+			else if (hide_unresolved)
+				continue;
+
+			if (syms[i].map && syms[i].map->dso &&
+					syms[i].map->dso->name)
+				dsoname = syms[i].map->dso->name;
+			else if (hide_unresolved)
+				continue;
+
+			printf(TIMEHIST_FMT,
+				   tstr, data->cpu,
+				   al->thread->comm, al->thread->pid,
+				   data->callchain->ips[i], symname, dsoname);
+
+			need_spacer = true;
+		}
+
+		free(syms);
+
+	} else {
+		printf(TIMEHIST_FMT,
+			   tstr, data->cpu,
+			   al->thread->comm, al->thread->pid, al->addr,
+			   al->sym->name, al->map->dso->name);
+
+		need_spacer = true;
+	}
+
+	/* put a gap between records */
+	if (need_spacer)
+		printf("\n");
+
+	return 0;
+}
+
 static int add_event_total(struct perf_session *session,
 			   struct sample_data *data,
 			   struct perf_event_attr *attr)
@@ -165,7 +277,9 @@ static int process_sample_event(event_t *event, struct sample_data *sample,
 	if (al.filtered || (hide_unresolved && al.sym == NULL))
 		return 0;
 
-	if (perf_session__add_hist_entry(session, &al, sample)) {
+	if (time_history) {
+		perf_session__print_sample(session, &al, sample);
+	} else if (perf_session__add_hist_entry(session, &al, sample)) {
 		pr_debug("problem incrementing symbol period, skipping event\n");
 		return -1;
 	}
@@ -319,6 +433,14 @@ static int __cmd_report(void)
 	if (ret)
 		goto out_delete;
 
+	if (time_history) {
+		if (!session->header.nsec_ref) {
+			pr_err("Reference timestamp missing in perf.data file.\n"
+			  "Cannot convert kernel timestamps to time-of-day.\n");
+		}
+		timehist_header();
+	}
+
 	ret = perf_session__process_events(session, &event_ops);
 	if (ret)
 		goto out_delete;
@@ -334,6 +456,9 @@ static int __cmd_report(void)
 	if (verbose > 2)
 		perf_session__fprintf_dsos(session, stdout);
 
+	if (time_history)
+		goto out_delete;
+
 	next = rb_first(&session->hists_tree);
 	while (next) {
 		struct hists *hists;
@@ -479,6 +604,8 @@ static const struct option options[] = {
 		   "columns '.' is reserved."),
 	OPT_BOOLEAN('U', "hide-unresolved", &hide_unresolved,
 		    "Only display entries resolved to a symbol"),
+	OPT_BOOLEAN(0, "timehist", &time_history,
+		    "Dump time history of event samples"),
 	OPT_END()
 };
 
@@ -486,7 +613,7 @@ int cmd_report(int argc, const char **argv, const char *prefix __used)
 {
 	argc = parse_options(argc, argv, options, report_usage, 0);
 
-	if (use_stdio)
+	if (use_stdio || time_history)
 		use_browser = 0;
 	else if (use_tui)
 		use_browser = 1;
-- 
1.7.2.3