[PATCH 0/2] perf tools: reference timestamp and time history dump

[PATCH 0/2] perf tools: reference timestamp and time history dump

[David Ahern]

First patch adds a reference timestamp to the perf header. The second
patch uses the reference timestamp to convert kernel timestamps to
time-of-day and outputs each sample.

David Ahern (2):
  perf tools: add reference timestamp to perf header
  perf tools: Add option to show time history of event samples

 tools/perf/builtin-record.c |    8 +++
 tools/perf/builtin-report.c |  120 ++++++++++++++++++++++++++++++++++++++++++-
 tools/perf/util/header.c    |   51 ++++++++++++++++++
 tools/perf/util/header.h    |    3 +
 tools/perf/util/session.c   |   26 +++++++++
 5 files changed, 206 insertions(+), 2 deletions(-)

-- 
1.7.2.3

[PATCH 1/2] perf tools: add reference timestamp to perf header

[David Ahern]

Reference timestamp is added to perf header to allow conversion of
kernel timestamps to time-of-day. Timestamp is added using a feature
bit for compatibility with older binaries.

Signed-off-by: David Ahern <daahern@cisco.com>
---
 tools/perf/util/header.c  |   51 +++++++++++++++++++++++++++++++++++++++++++++
 tools/perf/util/header.h  |    3 ++
 tools/perf/util/session.c |   26 +++++++++++++++++++++++
 3 files changed, 80 insertions(+), 0 deletions(-)

diff --git a/tools/perf/util/header.c b/tools/perf/util/header.c
index f65d7dc..0f04368 100644
--- a/tools/perf/util/header.c
+++ b/tools/perf/util/header.c
@@ -191,6 +191,40 @@ static int write_padded(int fd, const void *bf, size_t count,
 	return err;
 }
 
+static int perf_header__read_ref_time(struct perf_header *self,
+			int fd, u64 offset, u64 size)
+{
+	size_t sz_nsec = sizeof(self->nsec_ref);
+	size_t sz_tv   = sizeof(self->tv_ref);
+	int err = -1;
+
+	if (((size - offset) < (sz_nsec + sz_tv)) ||
+	    (read(fd, &self->nsec_ref, sz_nsec) != (ssize_t) sz_nsec) ||
+	    (read(fd, &self->tv_ref, sz_tv) != (ssize_t) sz_tv))
+		goto out;
+
+	err = 0;
+
+out:
+	return err;
+}
+
+static int perf_header__write_ref_time(struct perf_header *self, int fd)
+{
+	size_t sz_nsec = sizeof(self->nsec_ref);
+	size_t sz_tv   = sizeof(self->tv_ref);
+	int err = -1;
+
+	if ((write(fd, &self->nsec_ref, sz_nsec) != (ssize_t) sz_nsec) ||
+	    (write(fd, &self->tv_ref, sz_tv) != (ssize_t) sz_tv))
+		goto out;
+
+	err = 0;
+
+out:
+	return err;
+}
+
 #define dsos__for_each_with_build_id(pos, head)	\
 	list_for_each_entry(pos, head, node)	\
 		if (!pos->has_build_id)		\
@@ -483,6 +517,19 @@ static int perf_header__adds_write(struct perf_header *self, int fd)
 			perf_session__cache_build_ids(session);
 	}
 
+	if (perf_header__has_feat(self, HEADER_REFERENCE_TIME)) {
+		struct perf_file_section *tref_sec;
+
+		tref_sec = &feat_sec[idx++];
+		tref_sec->offset = lseek(fd, 0, SEEK_CUR);
+		err = perf_header__write_ref_time(self, fd);
+		if (err < 0) {
+			pr_debug("failed to write reference time\n");
+			goto out_free;
+		}
+		tref_sec->size = lseek(fd, 0, SEEK_CUR) - tref_sec->offset;
+	}
+
 	lseek(fd, sec_start, SEEK_SET);
 	err = do_write(fd, feat_sec, sec_size);
 	if (err < 0)
@@ -810,6 +857,10 @@ static int perf_file_section__process(struct perf_file_section *self,
 		if (perf_header__read_build_ids(ph, fd, self->offset, self->size))
 			pr_debug("Failed to read buildids, continuing...\n");
 		break;
+	case HEADER_REFERENCE_TIME:
+		if (perf_header__read_ref_time(ph, fd, self->offset, self->size))
+			pr_debug("Failed to read reference time, continuing...\n");
+		break;
 	default:
 		pr_debug("unknown feature %d, continuing...\n", feat);
 	}
diff --git a/tools/perf/util/header.h b/tools/perf/util/header.h
index ed550bf..d1a8e19 100644
--- a/tools/perf/util/header.h
+++ b/tools/perf/util/header.h
@@ -19,6 +19,7 @@ struct perf_header_attr {
 enum {
 	HEADER_TRACE_INFO = 1,
 	HEADER_BUILD_ID,
+	HEADER_REFERENCE_TIME,
 	HEADER_LAST_FEATURE,
 };
 
@@ -59,6 +60,8 @@ struct perf_header {
 	u64			data_size;
 	u64			event_offset;
 	u64			event_size;
+	u64			nsec_ref;
+	struct timeval		tv_ref;
 	DECLARE_BITMAP(adds_features, HEADER_FEAT_BITS);
 };
 
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index 3ae6955..1ceef22 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -70,6 +70,29 @@ void perf_session__update_sample_type(struct perf_session *self)
 	self->sample_type = perf_header__sample_type(&self->header);
 }
 
+static int perf_session__create_ref_time(struct perf_session *self)
+{
+	struct timespec tp;
+
+	/* race here between successive calls, but should be close enough */
+	if (gettimeofday(&self->header.tv_ref, NULL) != 0) {
+		pr_err("gettimeofday failed. Cannot set reference time.\n");
+		return -1;
+	}
+
+	if (clock_gettime(CLOCK_MONOTONIC, &tp) != 0) {
+		pr_err("clock_gettime failed. Cannot set reference time.\n");
+		return -1;
+	}
+
+	self->header.nsec_ref = (u64) tp.tv_sec * NSEC_PER_SEC
+	                            + (u64) tp.tv_nsec;
+
+	perf_header__set_feat(&self->header, HEADER_REFERENCE_TIME);
+
+	return 0;
+}
+
 int perf_session__create_kernel_maps(struct perf_session *self)
 {
 	int ret = machine__create_kernel_maps(&self->host_machine);
@@ -117,6 +140,9 @@ struct perf_session *perf_session__new(const char *filename, int mode, bool forc
 		 */
 		if (perf_session__create_kernel_maps(self) < 0)
 			goto out_delete;
+
+		if (perf_session__create_ref_time(self) < 0)
+			goto out_delete;
 	}
 
 	perf_session__update_sample_type(self);
-- 
1.7.2.3

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

[David Ahern]

Add a timehist option to perf record to save cpu and kernel timestamp
with each sample. Add timehist option to perf report to display the
cpu and timestamps for each event sample rather than generating a
histogram. The timehist option leverages the reference timestamp
from the perf header to create time-of-day stamps.

This option has been extremely in analyzing context switches. The
time history output can be mined for data such as how long a process
runs when scheduled in, where it is when scheduled out (ie., backtrace)
and how long between schedule in events.

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

diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
index 024e144..2496b04 100644
--- a/tools/perf/builtin-record.c
+++ b/tools/perf/builtin-record.c
@@ -49,6 +49,7 @@ static int			group				=      0;
 static int			realtime_prio			=      0;
 static bool			raw_samples			=  false;
 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;
@@ -281,6 +282,11 @@ static void create_counter(int counter, int cpu)
 	if (system_wide)
 		attr->sample_type	|= PERF_SAMPLE_CPU;
 
+	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;
@@ -840,6 +846,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 5de405d..042dc7c 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,106 @@ 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  "%33s  %3d  %-16s %5d  %16Lx  %s (%s)\n"
+
+static void timehist_header(void)
+{
+	printf("%33s  %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 *self,
+					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;
+
+	if (show_timehist_error &&
+		((data->cpu == (u32) -1) || !(self->sample_type & PERF_SAMPLE_TIME))) {
+		pr_err("Data for time history missing in perf event samples.\n"
+		       "Did you record with -T option?\n");
+		show_timehist_error = 0;
+	}
+
+	if (self->sample_type & PERF_SAMPLE_TIME)
+		timestamp = data->time;
+
+	tstr = timestr(timestamp, self);
+
+
+	if ((symbol_conf.use_callchain) && data->callchain) {
+		u64 i;
+
+		syms = perf_session__resolve_callchain(self, al->thread,
+						       data->callchain, &parent);
+		if (syms == NULL)
+			return -ENOMEM;
+
+		for (i = 0; i < data->callchain->nr; ++i) {
+			const char *symname = "", *dsoname = "";
+
+			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);
+		}
+
+		free(syms);
+
+	} else {
+		printf(TIMEHIST_FMT,
+			   tstr, data->cpu,
+			   al->thread->comm, al->thread->pid, al->addr,
+			   al->sym->name, al->map->dso->name);
+	}
+	printf("\n");
+
+	return 0;
+}
+
 static int add_event_total(struct perf_session *session,
 			   struct sample_data *data,
 			   struct perf_event_attr *attr)
@@ -165,7 +266,9 @@ static int process_sample_event(event_t *event, struct perf_session *session)
 	if (al.filtered || (hide_unresolved && al.sym == NULL))
 		return 0;
 
-	if (perf_session__add_hist_entry(session, &al, &data)) {
+	if (time_history) {
+		perf_session__print_sample(session, &al, &data);
+	} else if (perf_session__add_hist_entry(session, &al, &data)) {
 		pr_debug("problem incrementing symbol period, skipping event\n");
 		return -1;
 	}
@@ -318,6 +421,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;
@@ -333,6 +444,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;
@@ -478,6 +592,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()
 };
 
@@ -485,7 +601,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

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

[Arnaldo Carvalho de Melo]

Adding more people to the CC, hope they can stick some Acked-by on the
final version of this patch.

Em Mon, Nov 29, 2010 at 04:07:09PM -0700, David Ahern escreveu:
> Add a timehist option to perf record to save cpu and kernel timestamp
> with each sample. Add timehist option to perf report to display the
> cpu and timestamps for each event sample rather than generating a
> histogram. The timehist option leverages the reference timestamp
> from the perf header to create time-of-day stamps.
> 
> This option has been extremely in analyzing context switches. The
> time history output can be mined for data such as how long a process
> runs when scheduled in, where it is when scheduled out (ie., backtrace)
> and how long between schedule in events.

Suggestion: Please put some example output on the commit log message,
that way reviewers can have a glimpse of how it looks like.

More comments below.
 
> Signed-off-by: David Ahern <daahern@cisco.com>
> ---
>  tools/perf/builtin-record.c |    8 +++
>  tools/perf/builtin-report.c |  120 ++++++++++++++++++++++++++++++++++++++++++-
>  2 files changed, 126 insertions(+), 2 deletions(-)
> 
> diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
> index 024e144..2496b04 100644
> --- a/tools/perf/builtin-record.c
> +++ b/tools/perf/builtin-record.c
> @@ -49,6 +49,7 @@ static int			group				=      0;
>  static int			realtime_prio			=      0;
>  static bool			raw_samples			=  false;
>  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;
> @@ -281,6 +282,11 @@ static void create_counter(int counter, int cpu)
>  	if (system_wide)
>  		attr->sample_type	|= PERF_SAMPLE_CPU;
>  
> +	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;
> @@ -840,6 +846,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 5de405d..042dc7c 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,106 @@ 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  "%33s  %3d  %-16s %5d  %16Lx  %s (%s)\n"
> +
> +static void timehist_header(void)
> +{
> +	printf("%33s  %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 *self,

Please replace self with 'session', Thomas suggested that and I agreed
that its better. We'll slowly rename all those self variables.

> +					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;
> +
> +	if (show_timehist_error &&
> +		((data->cpu == (u32) -1) || !(self->sample_type & PERF_SAMPLE_TIME))) {
> +		pr_err("Data for time history missing in perf event samples.\n"
> +		       "Did you record with -T option?\n");

--timehist

As you used:

+	OPT_BOOLEAN(0, "timehist", &time_history,
+		    "Dump time history of event samples"),

In a branch I'm working on I'm using 'T' to mean "--sample_time", i.e.
to ask for just PERF_SAMPLE_TIME

> +		show_timehist_error = 0;
> +	}
> +
> +	if (self->sample_type & PERF_SAMPLE_TIME)
> +		timestamp = data->time;
> +
> +	tstr = timestr(timestamp, self);
> +
> +
> +	if ((symbol_conf.use_callchain) && data->callchain) {
> +		u64 i;
> +
> +		syms = perf_session__resolve_callchain(self, al->thread,
> +						       data->callchain, &parent);
> +		if (syms == NULL)
> +			return -ENOMEM;
> +
> +		for (i = 0; i < data->callchain->nr; ++i) {
> +			const char *symname = "", *dsoname = "";
> +
> +			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);
> +		}
> +
> +		free(syms);
> +
> +	} else {
> +		printf(TIMEHIST_FMT,
> +			   tstr, data->cpu,
> +			   al->thread->comm, al->thread->pid, al->addr,
> +			   al->sym->name, al->map->dso->name);
> +	}
> +	printf("\n");
> +
> +	return 0;
> +}
> +
>  static int add_event_total(struct perf_session *session,
>  			   struct sample_data *data,
>  			   struct perf_event_attr *attr)
> @@ -165,7 +266,9 @@ static int process_sample_event(event_t *event, struct perf_session *session)
>  	if (al.filtered || (hide_unresolved && al.sym == NULL))
>  		return 0;
>  
> -	if (perf_session__add_hist_entry(session, &al, &data)) {
> +	if (time_history) {
> +		perf_session__print_sample(session, &al, &data);
> +	} else if (perf_session__add_hist_entry(session, &al, &data)) {
>  		pr_debug("problem incrementing symbol period, skipping event\n");
>  		return -1;
>  	}
> @@ -318,6 +421,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;
> @@ -333,6 +444,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;
> @@ -478,6 +592,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()
>  };
>  
> @@ -485,7 +601,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
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[David S. Ahern]

On 11/30/10 12:19, Arnaldo Carvalho de Melo wrote:
> 
> Suggestion: Please put some example output on the commit log message,
> that way reviewers can have a glimpse of how it looks like.
> 

Will do. I actually had a comparison between today's 'report -D' and
'report --timehist'; I forgot to add it to the commit message.

The line lengths will be a bit ugly in an email. In practice, the
timehist is primarily a means of converting event data to sensible text
for 1. processing by scripts and gnuplot, and 2. correlating with log
entries from individual processes.

In case folks are interested now before generating another patch set:

./perf record --timehist -e cs -c 1 -p 983 -g

./perf report -D

0x1200 [0x88]: PERF_RECORD_SAMPLE(IP, 1): 983/983: 0xffffffff813e974f
period: 1 cpu:1
... chain: nr:11
.....  0: ffffffffffffff80
.....  1: ffffffff813e974f
.....  2: ffffffff813ea46d
.....  3: ffffffff813ea549
.....  4: ffffffff8111cf61
.....  5: ffffffff8111d7eb
.....  6: ffffffff8111d9a3
.....  7: ffffffff8111dad8
.....  8: ffffffff81002cf2
.....  9: fffffffffffffe00
..... 10: 00007f2e0d15dec3
 ... thread: sshd:983
 ...... dso: /lib/modules/2.6.37-rc2/build/vmlinux


./perf report --timehist -U

12:26:41.890762  105188460714 1  sshd  983  ffffffff813e974f  schedule
([kernel.kallsyms])
12:26:41.890762  105188460714 1  sshd  983  ffffffff813ea46d
schedule_hrtimeout_range_clock ([kernel.kallsyms])
12:26:41.890762  105188460714 1  sshd  983  ffffffff813ea549
schedule_hrtimeout_range ([kernel.kallsyms])
12:26:41.890762  105188460714 1  sshd  983  ffffffff8111cf61
poll_schedule_timeout ([kernel.kallsyms])
12:26:41.890762  105188460714 1  sshd  983  ffffffff8111d7eb  do_select
([kernel.kallsyms])
12:26:41.890762  105188460714 1  sshd  983  ffffffff8111d9a3
core_sys_select ([kernel.kallsyms])
12:26:41.890762  105188460714 1  sshd  983  ffffffff8111dad8  sys_select
([kernel.kallsyms])
12:26:41.890762  105188460714 1  sshd  983  ffffffff81002cf2
system_call ([kernel.kallsyms])
12:26:41.890762  105188460714 1  sshd  983      7f2e0d15dec3
__GI_select (/lib64/libc-2.12.90.so)



>> +static int perf_session__print_sample(struct perf_session *self,
> 
> Please replace self with 'session', Thomas suggested that and I agreed
> that its better. We'll slowly rename all those self variables.

Ok. I noted the mix and wasn't sure which name to use.

> 
>> +					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;
>> +
>> +	if (show_timehist_error &&
>> +		((data->cpu == (u32) -1) || !(self->sample_type & PERF_SAMPLE_TIME))) {
>> +		pr_err("Data for time history missing in perf event samples.\n"
>> +		       "Did you record with -T option?\n");
> 
> --timehist
> 
> As you used:
> 
> +	OPT_BOOLEAN(0, "timehist", &time_history,
> +		    "Dump time history of event samples"),
> 
> In a branch I'm working on I'm using 'T' to mean "--sample_time", i.e.
> to ask for just PERF_SAMPLE_TIME

Ok. I wanted consistency between record and report and moved from -T to
--timehist. Forgot to update the help message above.

David

[PATCH 0/2] perf tools: add reference timestamp and use it in time history dump

[David Ahern]

David Ahern (2):
  perf tools: Add reference timestamp to perf header
  perf tools: Add option to show time history of event samples

 tools/perf/builtin-record.c |    8 +++
 tools/perf/builtin-report.c |  131 ++++++++++++++++++++++++++++++++++++++++++-
 tools/perf/util/header.c    |   51 +++++++++++++++++
 tools/perf/util/header.h    |    3 +
 tools/perf/util/session.c   |   26 +++++++++
 5 files changed, 217 insertions(+), 2 deletions(-)

-- 
1.7.2.3

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

[David Ahern]

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

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

[Arnaldo Carvalho de Melo]

Em Tue, Dec 07, 2010 at 06:54:45PM -0700, David Ahern escreveu:
> 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):

You can instead compress the same info as:

-------------------------------

With the timehist option 'perf report --timehist' displays the same
sample as (some fields removed/compressed to make it fit under 80 columns)

17:11:10.1 cc1 61 ff810348d2 perf_event_task_sched_out ([kernel.kallsyms])
17:11:10.1 cc1 61 ff8139c02b schedule ([kernel.kallsyms])
17:11:10.1 cc1 61 ffa004b4a3 rpc_wait_bit_killable (/lib/modules/2.6.37-rc5/...
17:11:10.1 cc1 61 ff8139c79c __wait_on_bit ([kernel.kallsyms])
17:11:10.1 cc1 61 ff8139c83d out_of_line_wait_on_bit ([kernel.kallsyms])
17:11:10.1 cc1 61 ffa004b43f __rpc_wait_for_completion_task (/lib/modules/...
17:11:10.1 cc1 61 ffa00ec135 nfs4_wait_for_completion_rpc_task (/lib/modules/...
17:11:10.1 cc1 61 ffa00ec214 nfs4_run_open_task (/lib/modules/2.6.37-rc5/...
17:11:10.1 cc1 61 ffa00f01ec nfs4_do_open.clone.21 (/lib/modules/2.6.37-rc5/...
17:11:10.1 cc1 61 ffa00f0439 nfs4_atomic_open (/lib/modules/2.6.37-rc5/...
17:11:10.1 cc1 61 ffa00d6e8b nfs_open_revalidate (/lib/modules/2.6.37-rc5/...
17:11:10.1 cc1 61 ff8110b763 do_revalidate ([kernel.kallsyms])
17:11:10.1 cc1 61 ff8110b883 do_lookup ([kernel.kallsyms])
17:11:10.1 cc1 61 ff8110ddcd do_last ([kernel.kallsyms])
17:11:10.1 cc1 61 ff8110e45d do_filp_open ([kernel.kallsyms])
17:11:10.1 cc1 61 ff81101f36 do_sys_open ([kernel.kallsyms])
17:11:10.1 cc1 61 ff81101ff3 sys_open ([kernel.kallsyms])
17:11:10.1 cc1 61 ff81002c82 system_call ([kernel.kallsyms])
17:11:10.1 cc1 61 1ce050 __GI___libc_open (/lib64/libc-2.12.90.so)

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.

-----------------------------

changing the PID and addresses on the  'perf record -D' output to match the
shorter PID, etc, helps too.

will continue reviewing later, thanks
 
> 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
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Frederic Weisbecker]

On Tue, Dec 07, 2010 at 06:54:45PM -0700, David Ahern wrote:
> 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()
>  };

It seems you should only to the gettimeofday() / clock_gettime()
record if you have time_history set?

Thanks.

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