[PATCH 1/3] perf tools: Record total sampling time

[Namhyung Kim <namhyung@kernel.org>]

From: Namhyung Kim <namhyung.kim@lge.com>

It's sometimes useful to see total sampling or elapsed time with
normal performance result.  To do that, record first and last sample
time for each evsel and to display it in the header (--stdio only for
now).

  $ perf record -a sleep 1
  $ perf report --stdio
  ...
  # Samples: 4K of event 'cycles'
  # Event count (approx.): 4087481688
  # Total sampling time  : 1.001260 (sec)
  #
  # Overhead       Command               Shared Object                   Symbol
  # ........  ............  ..........................  .......................
  #
      89.06%      nautilus  libgobject-2.0.so.0.3701.0  [.] 0x0000000000020bf0
       1.79%   kworker/1:0  [kernel.kallsyms]           [k] generic_exec_single
       1.75%       swapper  [kernel.kallsyms]           [k] intel_idle
       1.14%      nautilus  [unknown]                   [.] 0x0000003153f2ff61
       0.69%   kworker/0:1  [kernel.kallsyms]           [k] generic_exec_single
       0.67%      nautilus  ld-2.17.so                  [.] do_lookup_x

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/perf/builtin-report.c | 15 ++++++++++++++-
 tools/perf/util/evsel.h     |  2 ++
 tools/perf/util/hist.h      |  1 +
 tools/perf/util/session.c   |  7 +++++++
 4 files changed, 24 insertions(+), 1 deletion(-)

diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
index 8cf8e66ba594..1d47fbec4421 100644
--- a/tools/perf/builtin-report.c
+++ b/tools/perf/builtin-report.c
@@ -456,6 +456,14 @@ static size_t hists__fprintf_nr_sample_events(struct perf_report *rep,
 		ret += fprintf(fp, "\n# Sort order   : %s", sort_order);
 	} else
 		ret += fprintf(fp, "\n# Event count (approx.): %" PRIu64, nr_events);
+	if (rep->tool.ordered_samples) {
+		u64 total_time = hists->stats.total_time;
+		u64 sec = total_time / NSEC_PER_SEC;
+		u64 usec = (total_time - sec * NSEC_PER_SEC) / NSEC_PER_USEC;
+
+		ret += fprintf(fp, "\n# Total sampling time  : "
+			       "%" PRIu64 ".%06" PRIu64 " (sec)", sec, usec);
+	}
 	return ret + fprintf(fp, "\n#\n");
 }
 
@@ -565,8 +573,13 @@ static int __cmd_report(struct perf_report *rep)
 	}
 
 	nr_samples = 0;
-	list_for_each_entry(pos, &session->evlist->entries, node)
+	list_for_each_entry(pos, &session->evlist->entries, node) {
 		nr_samples += pos->hists.nr_entries;
+		if (rep->tool.ordered_samples) {
+			pos->hists.stats.total_time = pos->last_timestamp -
+							pos->first_timestamp;
+		}
+	}
 
 	ui_progress__init(&prog, nr_samples, "Merging related events...");
 
diff --git a/tools/perf/util/evsel.h b/tools/perf/util/evsel.h
index 8120eeb86ac1..20a7c653b74b 100644
--- a/tools/perf/util/evsel.h
+++ b/tools/perf/util/evsel.h
@@ -67,6 +67,8 @@ struct perf_evsel {
 	int			idx;
 	u32			ids;
 	struct hists		hists;
+	u64			first_timestamp;
+	u64			last_timestamp;
 	char			*name;
 	double			scale;
 	const char		*unit;
diff --git a/tools/perf/util/hist.h b/tools/perf/util/hist.h
index b621347a1585..bc5acdfc2b4b 100644
--- a/tools/perf/util/hist.h
+++ b/tools/perf/util/hist.h
@@ -28,6 +28,7 @@ struct symbol;
  */
 struct events_stats {
 	u64 total_period;
+	u64 total_time;
 	u64 total_lost;
 	u64 total_invalid_chains;
 	u32 nr_events[PERF_RECORD_HEADER_MAX];
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index 4ce146bae552..e4b158f0586a 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -925,6 +925,13 @@ perf_session__deliver_sample(struct perf_session *session,
 	u64 sample_type = evsel->attr.sample_type;
 	u64 read_format = evsel->attr.read_format;
 
+	if (tool->ordered_samples) {
+		if (evsel->first_timestamp == 0)
+			evsel->first_timestamp = sample->time;
+
+		evsel->last_timestamp = sample->time;
+	}
+
 	/* Standard sample delievery. */
 	if (!(sample_type & PERF_SAMPLE_READ))
 		return tool->sample(tool, event, sample, evsel, machine);
-- 
1.7.11.7