[RFC 0/3] perf tools: Show time info (v1)

[RFC 0/3] perf tools: Show time info (v1)

[Namhyung Kim]

Hi,

Sometimes users might want to see time information along with the
performance result but the perf cannot provide it currently.

In this patchset, I added such feature using sample->time.  When the
perf processes sample events, it calculate time info and update last
timestamp.  It keeps the last timestamp for each evsel (and for each
cpu if it's a per-cpu session).

It guesses whether a session is per-cpu if it found PERF_SAMPLE_CPU in
a evsel->attr.sample_type since I couldn't find a better way.  However
it'll have a trouble if used with tracepoint events since they require
the cpu info in the sample_type even for the per-thread sessions.

The sample time will usually be proportional to the overhead but
sometimes it show a different result especially in idle state.

With this patch, perf report can show time information in the header
(on --stdio output only for now) and a new column which can be enabled
by --show-time-info option.

  $ perf record -- perf bench sched messaging
  $ perf report --stdio --show-time-info

  # Samples: 10K of event 'cycles'
  # Event count (approx.): 5168954556
  # Total sampling time  : 0.179102 (sec)       <--- here
  #
  # Overhead        Time          Command       Shared Object                        Symbol
  # ........  ..........  ...............  ..................  ............................
  #
       6.59%    0.006093  sched-messaging  [unknown]           [.] 0x0000003153ebc7ed
       4.81%    0.005354  sched-messaging  [kernel.kallsyms]   [k] copy_user_generic_string
       3.89%    0.004098  sched-messaging  [kernel.kallsyms]   [k] avc_has_perm_flags
       3.77%    0.003630  sched-messaging  [kernel.kallsyms]   [k] unix_stream_recvmsg
       3.37%    0.003733  sched-messaging  [kernel.kallsyms]   [k] _raw_spin_lock
       2.97%    0.003489  sched-messaging  [kernel.kallsyms]   [k] _raw_spin_lock_irqsave
       2.73%    0.002615  sched-messaging  [kernel.kallsyms]   [k] __slab_free
       2.56%    0.002392  sched-messaging  [kernel.kallsyms]   [k] page_fault
       2.45%    0.002572  sched-messaging  [kernel.kallsyms]   [k] sock_alloc_send_pskb

I put the series on 'perf/time-sample-v1' branch in my tree:

  git://git.kernel.org/pub/scm/linux/kernel/git/namhyung/linux-perf.git

Any comments are welcome, thanks
Namhyung


Namhyung Kim (3):
  perf tools: Record total sampling time
  perf tools: Record sampling time for each entry
  perf report: Add --show-time-info option

 tools/perf/builtin-annotate.c |  2 +-
 tools/perf/builtin-diff.c     |  2 +-
 tools/perf/builtin-report.c   | 26 +++++++++++++----
 tools/perf/builtin-top.c      |  2 +-
 tools/perf/tests/hists_link.c |  4 +--
 tools/perf/ui/hist.c          | 68 ++++++++++++++++++++++++++++++++++++-------
 tools/perf/util/evsel.h       |  3 ++
 tools/perf/util/hist.c        | 15 ++++++----
 tools/perf/util/hist.h        |  4 ++-
 tools/perf/util/session.c     | 49 +++++++++++++++++++++++++++++++
 tools/perf/util/sort.h        |  1 +
 tools/perf/util/symbol.h      |  3 +-
 12 files changed, 151 insertions(+), 28 deletions(-)

-- 
1.7.11.7

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

[Namhyung Kim]

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

[PATCH 2/3] perf tools: Record sampling time for each entry

[Namhyung Kim]

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

Calculate elapsed time for each sample and record it.  The elapsed
time is a diff between current sample->time and previous sample->time
which was saved for each evsel and cpu.

Maybe we can use PERF_SAMPLE_READ for the precise result.

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/perf/builtin-annotate.c |  2 +-
 tools/perf/builtin-diff.c     |  2 +-
 tools/perf/builtin-report.c   |  9 +++++----
 tools/perf/builtin-top.c      |  2 +-
 tools/perf/tests/hists_link.c |  4 ++--
 tools/perf/util/evsel.h       |  1 +
 tools/perf/util/hist.c        | 15 ++++++++++-----
 tools/perf/util/hist.h        |  2 +-
 tools/perf/util/session.c     | 42 ++++++++++++++++++++++++++++++++++++++++++
 tools/perf/util/sort.h        |  1 +
 10 files changed, 65 insertions(+), 15 deletions(-)

diff --git a/tools/perf/builtin-annotate.c b/tools/perf/builtin-annotate.c
index 4087ab19823c..dc43a64bf723 100644
--- a/tools/perf/builtin-annotate.c
+++ b/tools/perf/builtin-annotate.c
@@ -65,7 +65,7 @@ static int perf_evsel__add_sample(struct perf_evsel *evsel,
 		return 0;
 	}
 
-	he = __hists__add_entry(&evsel->hists, al, NULL, NULL, NULL, 1, 1, 0);
+	he = __hists__add_entry(&evsel->hists, al, NULL, NULL, NULL, 1, 0, 1, 0);
 	if (he == NULL)
 		return -ENOMEM;
 
diff --git a/tools/perf/builtin-diff.c b/tools/perf/builtin-diff.c
index 3b67ea2444bd..85aa961a647e 100644
--- a/tools/perf/builtin-diff.c
+++ b/tools/perf/builtin-diff.c
@@ -307,7 +307,7 @@ static int hists__add_entry(struct hists *hists,
 			    struct addr_location *al, u64 period,
 			    u64 weight, u64 transaction)
 {
-	if (__hists__add_entry(hists, al, NULL, NULL, NULL, period, weight,
+	if (__hists__add_entry(hists, al, NULL, NULL, NULL, period, 0, weight,
 			       transaction) != NULL)
 		return 0;
 	return -ENOMEM;
diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
index 1d47fbec4421..eb849e9f7093 100644
--- a/tools/perf/builtin-report.c
+++ b/tools/perf/builtin-report.c
@@ -116,7 +116,7 @@ static int perf_report__add_mem_hist_entry(struct perf_tool *tool,
 	 * and the he_stat__add_period() function.
 	 */
 	he = __hists__add_entry(&evsel->hists, al, parent, NULL, mi,
-				cost, cost, 0);
+				cost, 0, cost, 0);
 	if (!he)
 		return -ENOMEM;
 
@@ -210,7 +210,7 @@ static int perf_report__add_branch_hist_entry(struct perf_tool *tool,
 		 * and not events sampled. Thus we use a pseudo period of 1.
 		 */
 		he = __hists__add_entry(&evsel->hists, al, parent, &bi[i], NULL,
-					1, 1, 0);
+					1, 0, 1, 0);
 		if (he) {
 			struct annotation *notes;
 			bx = he->branch_info;
@@ -272,8 +272,9 @@ static int perf_evsel__add_hist_entry(struct perf_tool *tool,
 	}
 
 	he = __hists__add_entry(&evsel->hists, al, parent, NULL, NULL,
-				sample->period, sample->weight,
-				sample->transaction);
+				sample->period,
+				tool->ordered_samples ? sample->read.time_enabled : 0,
+				sample->weight, sample->transaction);
 	if (he == NULL)
 		return -ENOMEM;
 
diff --git a/tools/perf/builtin-top.c b/tools/perf/builtin-top.c
index 03d37a76c612..175bde2a0ece 100644
--- a/tools/perf/builtin-top.c
+++ b/tools/perf/builtin-top.c
@@ -247,7 +247,7 @@ static struct hist_entry *perf_evsel__add_hist_entry(struct perf_evsel *evsel,
 
 	pthread_mutex_lock(&evsel->hists.lock);
 	he = __hists__add_entry(&evsel->hists, al, NULL, NULL, NULL,
-				sample->period, sample->weight,
+				sample->period, 0, sample->weight,
 				sample->transaction);
 	pthread_mutex_unlock(&evsel->hists.lock);
 	if (he == NULL)
diff --git a/tools/perf/tests/hists_link.c b/tools/perf/tests/hists_link.c
index 173bf42cc03e..7bb952e6be62 100644
--- a/tools/perf/tests/hists_link.c
+++ b/tools/perf/tests/hists_link.c
@@ -223,7 +223,7 @@ static int add_hist_entries(struct perf_evlist *evlist, struct machine *machine)
 				goto out;
 
 			he = __hists__add_entry(&evsel->hists, &al, NULL,
-						NULL, NULL, 1, 1, 0);
+						NULL, NULL, 1, 0, 1, 0);
 			if (he == NULL)
 				goto out;
 
@@ -246,7 +246,7 @@ static int add_hist_entries(struct perf_evlist *evlist, struct machine *machine)
 				goto out;
 
 			he = __hists__add_entry(&evsel->hists, &al, NULL,
-						NULL, NULL, 1, 1, 0);
+						NULL, NULL, 1, 0, 1, 0);
 			if (he == NULL)
 				goto out;
 
diff --git a/tools/perf/util/evsel.h b/tools/perf/util/evsel.h
index 20a7c653b74b..ac65fc67972c 100644
--- a/tools/perf/util/evsel.h
+++ b/tools/perf/util/evsel.h
@@ -69,6 +69,7 @@ struct perf_evsel {
 	struct hists		hists;
 	u64			first_timestamp;
 	u64			last_timestamp;
+	u64			*prev_timestamps;
 	char			*name;
 	double			scale;
 	const char		*unit;
diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
index 822903eaa201..8d9278df59fa 100644
--- a/tools/perf/util/hist.c
+++ b/tools/perf/util/hist.c
@@ -204,11 +204,12 @@ static void hist_entry__add_cpumode_period(struct hist_entry *he,
 }
 
 static void he_stat__add_period(struct he_stat *he_stat, u64 period,
-				u64 weight)
+				u64 time, u64 weight)
 {
 
 	he_stat->period		+= period;
 	he_stat->weight		+= weight;
+	he_stat->time		+= time;
 	he_stat->nr_events	+= 1;
 }
 
@@ -221,10 +222,12 @@ static void he_stat__add_stat(struct he_stat *dest, struct he_stat *src)
 	dest->period_guest_us	+= src->period_guest_us;
 	dest->nr_events		+= src->nr_events;
 	dest->weight		+= src->weight;
+	dest->time		+= src->time;
 }
 
 static void hist_entry__decay(struct hist_entry *he)
 {
+	he->stat.time = (he->stat.time * 7) / 8;
 	he->stat.period = (he->stat.period * 7) / 8;
 	he->stat.nr_events = (he->stat.nr_events * 7) / 8;
 	/* XXX need decay for weight too? */
@@ -344,7 +347,7 @@ static u8 symbol__parent_filter(const struct symbol *parent)
 static struct hist_entry *add_hist_entry(struct hists *hists,
 				      struct hist_entry *entry,
 				      struct addr_location *al,
-				      u64 period,
+				      u64 period, u64 time,
 				      u64 weight)
 {
 	struct rb_node **p;
@@ -367,7 +370,7 @@ static struct hist_entry *add_hist_entry(struct hists *hists,
 		cmp = hist_entry__cmp(he, entry);
 
 		if (!cmp) {
-			he_stat__add_period(&he->stat, period, weight);
+			he_stat__add_period(&he->stat, period, time, weight);
 
 			/*
 			 * This mem info was allocated from machine__resolve_mem
@@ -412,7 +415,8 @@ struct hist_entry *__hists__add_entry(struct hists *hists,
 				      struct symbol *sym_parent,
 				      struct branch_info *bi,
 				      struct mem_info *mi,
-				      u64 period, u64 weight, u64 transaction)
+				      u64 period, u64 time,
+				      u64 weight, u64 transaction)
 {
 	struct hist_entry entry = {
 		.thread	= al->thread,
@@ -428,6 +432,7 @@ struct hist_entry *__hists__add_entry(struct hists *hists,
 			.nr_events = 1,
 			.period	= period,
 			.weight = weight,
+			.time = time,
 		},
 		.parent = sym_parent,
 		.filtered = symbol__parent_filter(sym_parent),
@@ -437,7 +442,7 @@ struct hist_entry *__hists__add_entry(struct hists *hists,
 		.transaction = transaction,
 	};
 
-	return add_hist_entry(hists, &entry, al, period, weight);
+	return add_hist_entry(hists, &entry, al, period, time, weight);
 }
 
 int64_t
diff --git a/tools/perf/util/hist.h b/tools/perf/util/hist.h
index bc5acdfc2b4b..0433469812dc 100644
--- a/tools/perf/util/hist.h
+++ b/tools/perf/util/hist.h
@@ -89,7 +89,7 @@ struct hist_entry *__hists__add_entry(struct hists *hists,
 				      struct addr_location *al,
 				      struct symbol *parent,
 				      struct branch_info *bi,
-				      struct mem_info *mi, u64 period,
+				      struct mem_info *mi, u64 period, u64 time,
 				      u64 weight, u64 transaction);
 int64_t hist_entry__cmp(struct hist_entry *left, struct hist_entry *right);
 int64_t hist_entry__collapse(struct hist_entry *left, struct hist_entry *right);
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index e4b158f0586a..f36e95f00a05 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -926,6 +926,48 @@ perf_session__deliver_sample(struct perf_session *session,
 	u64 read_format = evsel->attr.read_format;
 
 	if (tool->ordered_samples) {
+		/* FIXME: need to find a way to determine cpu-wide session */
+		bool per_cpu_session = sample_type & PERF_SAMPLE_CPU;
+
+		sample->read.time_enabled = 0;
+
+		if (per_cpu_session) {
+			u64 *ts = evsel->prev_timestamps;
+
+			if (ts == NULL) {
+				int nr_cpus = session->header.env.nr_cpus_online;
+
+				ts = zalloc(nr_cpus * sizeof(ts));
+				if (ts == NULL)
+					return -ENOMEM;
+
+				evsel->prev_timestamps = ts;
+			}
+
+			if (ts[sample->cpu] != 0) {
+				u64 diff = sample->time - ts[sample->cpu];
+
+				sample->read.time_enabled = diff;
+			}
+			ts[sample->cpu] = sample->time;
+		} else {
+			u64 *ts = evsel->prev_timestamps;
+
+			if (ts == NULL) {
+				ts = zalloc(sizeof(*ts));
+				if (ts == NULL)
+					return -ENOMEM;
+
+				evsel->prev_timestamps = ts;
+			}
+
+			if (*ts != 0) {
+				u64 diff = sample->time - *ts;
+				sample->read.time_enabled = diff;
+			}
+			*ts = sample->time;
+		}
+
 		if (evsel->first_timestamp == 0)
 			evsel->first_timestamp = sample->time;
 
diff --git a/tools/perf/util/sort.h b/tools/perf/util/sort.h
index 43e5ff42a609..16aaf0a47346 100644
--- a/tools/perf/util/sort.h
+++ b/tools/perf/util/sort.h
@@ -51,6 +51,7 @@ struct he_stat {
 	u64			period_guest_sys;
 	u64			period_guest_us;
 	u64			weight;
+	u64			time;
 	u32			nr_events;
 };
 
-- 
1.7.11.7

[PATCH 3/3] perf report: Add --show-time-info option

[Namhyung Kim]

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

The --show-time-info option is for displaying elapsed sampling time
information for each entry.

  $ perf record -- perf bench sched messaging
  $ perf report --stdio --show-time-info
  ...
  # Samples: 10K of event 'cycles'
  # Event count (approx.): 5118793536
  # Total sampling time  : 0.184277 (sec)
  #
  # Overhead        Time          Command      Shared Object                       Symbol
  # ........  ..........  ...............  .................  ...........................
  #
       7.26%    0.007413  sched-messaging  [unknown]          [.] 0x0000003153e7a6e7
       4.79%    0.006088  sched-messaging  [kernel.kallsyms]  [k] avc_has_perm_flags
       4.38%    0.004809  sched-messaging  [kernel.kallsyms]  [k] copy_user_generic_string
       3.81%    0.005457  sched-messaging  [kernel.kallsyms]  [k] _raw_spin_lock
       2.92%    0.002745  sched-messaging  [kernel.kallsyms]  [k] _raw_spin_lock_irqsave
       2.72%    0.002896  sched-messaging  [kernel.kallsyms]  [k] unix_stream_recvmsg
       2.55%    0.003745  sched-messaging  [kernel.kallsyms]  [k] __slab_free
       2.45%    0.002807  sched-messaging  [kernel.kallsyms]  [k] page_fault
       2.08%    0.002258  sched-messaging  [kernel.kallsyms]  [k] sock_has_perm

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/perf/builtin-report.c |  2 ++
 tools/perf/ui/hist.c        | 68 +++++++++++++++++++++++++++++++++++++--------
 tools/perf/util/hist.h      |  1 +
 tools/perf/util/symbol.h    |  3 +-
 4 files changed, 62 insertions(+), 12 deletions(-)

diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
index eb849e9f7093..345cce6f5fa2 100644
--- a/tools/perf/builtin-report.c
+++ b/tools/perf/builtin-report.c
@@ -898,6 +898,8 @@ int cmd_report(int argc, const char **argv, const char *prefix __maybe_unused)
 	OPT_BOOLEAN(0, "mem-mode", &report.mem_mode, "mem access profile"),
 	OPT_CALLBACK(0, "percent-limit", &report, "percent",
 		     "Don't show entries under that percent", parse_percent_limit),
+	OPT_BOOLEAN(0, "show-time-info", &symbol_conf.show_time_info,
+		    "Show a column with the elapsed time"),
 	OPT_END()
 	};
 	struct perf_data_file file = {
diff --git a/tools/perf/ui/hist.c b/tools/perf/ui/hist.c
index 78f4c92e9b73..7cf584a0bb61 100644
--- a/tools/perf/ui/hist.c
+++ b/tools/perf/ui/hist.c
@@ -7,19 +7,24 @@
 #include "../util/evsel.h"
 
 /* hist period print (hpp) functions */
+enum hpp_fmt_type {
+	HPP_FMT__PERCENT,
+	HPP_FMT__RAW,
+	HPP_FMT__TIME,
+};
 
 typedef int (*hpp_snprint_fn)(char *buf, size_t size, const char *fmt, ...);
 
 static int __hpp__fmt(struct perf_hpp *hpp, struct hist_entry *he,
 		      u64 (*get_field)(struct hist_entry *),
 		      const char *fmt, hpp_snprint_fn print_fn,
-		      bool fmt_percent)
+		      enum hpp_fmt_type type)
 {
 	int ret;
 	struct hists *hists = he->hists;
 	struct perf_evsel *evsel = hists_to_evsel(hists);
 
-	if (fmt_percent) {
+	if (type == HPP_FMT__PERCENT) {
 		double percent = 0.0;
 
 		if (hists->stats.total_period)
@@ -27,8 +32,15 @@ static int __hpp__fmt(struct perf_hpp *hpp, struct hist_entry *he,
 				  hists->stats.total_period;
 
 		ret = print_fn(hpp->buf, hpp->size, fmt, percent);
-	} else
+	} else if (type == HPP_FMT__RAW) {
 		ret = print_fn(hpp->buf, hpp->size, fmt, get_field(he));
+	} else if (type == HPP_FMT__TIME) {
+		u64 time = get_field(he);
+		u64 sec = time / NSEC_PER_SEC;
+		u64 usec = (time - sec * NSEC_PER_SEC) / NSEC_PER_USEC;
+
+		ret = print_fn(hpp->buf, hpp->size, fmt, sec, usec);
+	}
 
 	if (perf_evsel__is_group_event(evsel)) {
 		int prev_idx, idx_delta;
@@ -53,15 +65,22 @@ static int __hpp__fmt(struct perf_hpp *hpp, struct hist_entry *he,
 				 * have no sample
 				 */
 				ret += print_fn(hpp->buf + ret, hpp->size - ret,
-						fmt, 0);
+						fmt, 0, 0);
 			}
 
-			if (fmt_percent)
+			if (type == HPP_FMT__PERCENT)
 				ret += print_fn(hpp->buf + ret, hpp->size - ret,
 						fmt, 100.0 * period / total);
-			else
+			else if (type == HPP_FMT__RAW)
 				ret += print_fn(hpp->buf + ret, hpp->size - ret,
 						fmt, period);
+			else if (type == HPP_FMT__TIME) {
+				u64 sec = period / NSEC_PER_SEC;
+				u64 usec = (period - sec * NSEC_PER_SEC) / NSEC_PER_USEC;
+
+				ret += print_fn(hpp->buf + ret, hpp->size - ret,
+						fmt, sec, usec);
+			}
 
 			prev_idx = perf_evsel__group_idx(evsel);
 		}
@@ -73,7 +92,7 @@ static int __hpp__fmt(struct perf_hpp *hpp, struct hist_entry *he,
 			 * zero-fill group members at last which have no sample
 			 */
 			ret += print_fn(hpp->buf + ret, hpp->size - ret,
-					fmt, 0);
+					fmt, 0, 0);
 		}
 	}
 	return ret;
@@ -117,7 +136,7 @@ static int hpp__color_##_type(struct perf_hpp_fmt *fmt __maybe_unused,		\
 			      struct perf_hpp *hpp, struct hist_entry *he) 	\
 {										\
 	return __hpp__fmt(hpp, he, he_get_##_field, " %6.2f%%",			\
-			  percent_color_snprintf, true);			\
+			  percent_color_snprintf, HPP_FMT__PERCENT);		\
 }
 
 #define __HPP_ENTRY_PERCENT_FN(_type, _field)					\
@@ -126,7 +145,7 @@ static int hpp__entry_##_type(struct perf_hpp_fmt *_fmt __maybe_unused,		\
 {										\
 	const char *fmt = symbol_conf.field_sep ? " %.2f" : " %6.2f%%";		\
 	return __hpp__fmt(hpp, he, he_get_##_field, fmt,			\
-			  scnprintf, true);					\
+			  scnprintf, HPP_FMT__PERCENT);				\
 }
 
 #define __HPP_ENTRY_RAW_FN(_type, _field)					\
@@ -139,7 +158,23 @@ static int hpp__entry_##_type(struct perf_hpp_fmt *_fmt __maybe_unused,		\
 			      struct perf_hpp *hpp, struct hist_entry *he) 	\
 {										\
 	const char *fmt = symbol_conf.field_sep ? " %"PRIu64 : " %11"PRIu64;	\
-	return __hpp__fmt(hpp, he, he_get_raw_##_field, fmt, scnprintf, false);	\
+	return __hpp__fmt(hpp, he, he_get_raw_##_field, fmt, scnprintf,		\
+			  HPP_FMT__RAW);					\
+}
+
+#define __HPP_ENTRY_TIME_FN(_type, _field)					\
+static u64 he_get_raw_##_field(struct hist_entry *he)				\
+{										\
+	return he->stat._field;							\
+}										\
+										\
+static int hpp__entry_##_type(struct perf_hpp_fmt *_fmt __maybe_unused,		\
+			      struct perf_hpp *hpp, struct hist_entry *he) 	\
+{										\
+	const char *fmt = symbol_conf.field_sep ? " %"PRIu64 ".%06"PRIu64 : 	\
+						  " %2"PRIu64 ".%06"PRIu64;	\
+	return __hpp__fmt(hpp, he, he_get_raw_##_field, fmt, scnprintf,		\
+			  HPP_FMT__TIME);					\
 }
 
 #define HPP_PERCENT_FNS(_type, _str, _field, _min_width, _unit_width)	\
@@ -153,6 +188,11 @@ __HPP_HEADER_FN(_type, _str, _min_width, _unit_width)			\
 __HPP_WIDTH_FN(_type, _min_width, _unit_width)				\
 __HPP_ENTRY_RAW_FN(_type, _field)
 
+#define HPP_TIME_FNS(_type, _str, _field, _min_width, _unit_width)	\
+__HPP_HEADER_FN(_type, _str, _min_width, _unit_width)			\
+__HPP_WIDTH_FN(_type, _min_width, _unit_width)				\
+__HPP_ENTRY_TIME_FN(_type, _field)
+
 
 HPP_PERCENT_FNS(overhead, "Overhead", period, 8, 8)
 HPP_PERCENT_FNS(overhead_sys, "sys", period_sys, 8, 8)
@@ -163,6 +203,8 @@ HPP_PERCENT_FNS(overhead_guest_us, "guest usr", period_guest_us, 9, 8)
 HPP_RAW_FNS(samples, "Samples", nr_events, 12, 12)
 HPP_RAW_FNS(period, "Period", period, 12, 12)
 
+HPP_TIME_FNS(time, "Time", time, 10, 10)
+
 #define HPP__COLOR_PRINT_FNS(_name)			\
 	{						\
 		.header	= hpp__header_ ## _name,	\
@@ -185,7 +227,8 @@ struct perf_hpp_fmt perf_hpp__format[] = {
 	HPP__COLOR_PRINT_FNS(overhead_guest_sys),
 	HPP__COLOR_PRINT_FNS(overhead_guest_us),
 	HPP__PRINT_FNS(samples),
-	HPP__PRINT_FNS(period)
+	HPP__PRINT_FNS(period),
+	HPP__PRINT_FNS(time)
 };
 
 LIST_HEAD(perf_hpp__list);
@@ -223,6 +266,9 @@ void perf_hpp__init(void)
 
 	if (symbol_conf.show_total_period)
 		perf_hpp__column_enable(PERF_HPP__PERIOD);
+
+	if (symbol_conf.show_time_info)
+		perf_hpp__column_enable(PERF_HPP__TIME);
 }
 
 void perf_hpp__column_register(struct perf_hpp_fmt *format)
diff --git a/tools/perf/util/hist.h b/tools/perf/util/hist.h
index 0433469812dc..17e89fb31db9 100644
--- a/tools/perf/util/hist.h
+++ b/tools/perf/util/hist.h
@@ -162,6 +162,7 @@ enum {
 	PERF_HPP__OVERHEAD_GUEST_US,
 	PERF_HPP__SAMPLES,
 	PERF_HPP__PERIOD,
+	PERF_HPP__TIME,
 
 	PERF_HPP__MAX_INDEX
 };
diff --git a/tools/perf/util/symbol.h b/tools/perf/util/symbol.h
index f1031a1358a1..b29d26222c6f 100644
--- a/tools/perf/util/symbol.h
+++ b/tools/perf/util/symbol.h
@@ -99,7 +99,8 @@ struct symbol_conf {
 			annotate_asm_raw,
 			annotate_src,
 			event_group,
-			demangle;
+			demangle,
+			show_time_info;
 	const char	*vmlinux_name,
 			*kallsyms_name,
 			*source_prefix,
-- 
1.7.11.7

Re: [RFC 0/3] perf tools: Show time info (v1)

[Pekka Enberg]

On 12/02/2013 08:53 AM, Namhyung Kim wrote:
> Sometimes users might want to see time information along with the
> performance result but the perf cannot provide it currently.
>
> In this patchset, I added such feature using sample->time.  When the
> perf processes sample events, it calculate time info and update last
> timestamp.  It keeps the last timestamp for each evsel (and for each
> cpu if it's a per-cpu session).
>
> It guesses whether a session is per-cpu if it found PERF_SAMPLE_CPU in
> a evsel->attr.sample_type since I couldn't find a better way.  However
> it'll have a trouble if used with tracepoint events since they require
> the cpu info in the sample_type even for the per-thread sessions.
>
> The sample time will usually be proportional to the overhead but
> sometimes it show a different result especially in idle state.
>
> With this patch, perf report can show time information in the header
> (on --stdio output only for now) and a new column which can be enabled
> by --show-time-info option.
>
>    $ perf record -- perf bench sched messaging
>    $ perf report --stdio --show-time-info
>
>    # Samples: 10K of event 'cycles'
>    # Event count (approx.): 5168954556
>    # Total sampling time  : 0.179102 (sec)       <--- here
>    #
>    # Overhead        Time          Command       Shared Object                        Symbol
>    # ........  ..........  ...............  ..................  ............................
>    #
>         6.59%    0.006093  sched-messaging  [unknown]           [.] 0x0000003153ebc7ed
>         4.81%    0.005354  sched-messaging  [kernel.kallsyms]   [k] copy_user_generic_string
>         3.89%    0.004098  sched-messaging  [kernel.kallsyms]   [k] avc_has_perm_flags
>         3.77%    0.003630  sched-messaging  [kernel.kallsyms]   [k] unix_stream_recvmsg
>         3.37%    0.003733  sched-messaging  [kernel.kallsyms]   [k] _raw_spin_lock
>         2.97%    0.003489  sched-messaging  [kernel.kallsyms]   [k] _raw_spin_lock_irqsave
>         2.73%    0.002615  sched-messaging  [kernel.kallsyms]   [k] __slab_free
>         2.56%    0.002392  sched-messaging  [kernel.kallsyms]   [k] page_fault
>         2.45%    0.002572  sched-messaging  [kernel.kallsyms]   [k] sock_alloc_send_pskb
>
> I put the series on 'perf/time-sample-v1' branch in my tree:
>
>    git://git.kernel.org/pub/scm/linux/kernel/git/namhyung/linux-perf.git
>
> Any comments are welcome, thanks

Reviewed-by: Pekka Enberg <penberg@kernel.org>

for the whole series.

Re: [PATCH 3/3] perf report: Add --show-time-info option

[Arnaldo Carvalho de Melo]

Em Mon, Dec 02, 2013 at 03:53:19PM +0900, Namhyung Kim escreveu:
> From: Namhyung Kim <namhyung.kim@lge.com>
> 
> The --show-time-info option is for displaying elapsed sampling time

Isn't that too long? Can't we use just --time/-t?

> information for each entry.
> 
>   $ perf record -- perf bench sched messaging
>   $ perf report --stdio --show-time-info
>   ...
>   # Samples: 10K of event 'cycles'
>   # Event count (approx.): 5118793536
>   # Total sampling time  : 0.184277 (sec)
>   #
>   # Overhead        Time          Command      Shared Object                       Symbol
>   # ........  ..........  ...............  .................  ...........................
>   #
>        7.26%    0.007413  sched-messaging  [unknown]          [.] 0x0000003153e7a6e7
>        4.79%    0.006088  sched-messaging  [kernel.kallsyms]  [k] avc_has_perm_flags
>        4.38%    0.004809  sched-messaging  [kernel.kallsyms]  [k] copy_user_generic_string
>        3.81%    0.005457  sched-messaging  [kernel.kallsyms]  [k] _raw_spin_lock
>        2.92%    0.002745  sched-messaging  [kernel.kallsyms]  [k] _raw_spin_lock_irqsave
>        2.72%    0.002896  sched-messaging  [kernel.kallsyms]  [k] unix_stream_recvmsg
>        2.55%    0.003745  sched-messaging  [kernel.kallsyms]  [k] __slab_free
>        2.45%    0.002807  sched-messaging  [kernel.kallsyms]  [k] page_fault
>        2.08%    0.002258  sched-messaging  [kernel.kallsyms]  [k] sock_has_perm
> 
> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> ---
>  tools/perf/builtin-report.c |  2 ++
>  tools/perf/ui/hist.c        | 68 +++++++++++++++++++++++++++++++++++++--------
>  tools/perf/util/hist.h      |  1 +
>  tools/perf/util/symbol.h    |  3 +-
>  4 files changed, 62 insertions(+), 12 deletions(-)
> 
> diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
> index eb849e9f7093..345cce6f5fa2 100644
> --- a/tools/perf/builtin-report.c
> +++ b/tools/perf/builtin-report.c
> @@ -898,6 +898,8 @@ int cmd_report(int argc, const char **argv, const char *prefix __maybe_unused)
>  	OPT_BOOLEAN(0, "mem-mode", &report.mem_mode, "mem access profile"),
>  	OPT_CALLBACK(0, "percent-limit", &report, "percent",
>  		     "Don't show entries under that percent", parse_percent_limit),
> +	OPT_BOOLEAN(0, "show-time-info", &symbol_conf.show_time_info,
> +		    "Show a column with the elapsed time"),
>  	OPT_END()
>  	};
>  	struct perf_data_file file = {
> diff --git a/tools/perf/ui/hist.c b/tools/perf/ui/hist.c
> index 78f4c92e9b73..7cf584a0bb61 100644
> --- a/tools/perf/ui/hist.c
> +++ b/tools/perf/ui/hist.c
> @@ -7,19 +7,24 @@
>  #include "../util/evsel.h"
>  
>  /* hist period print (hpp) functions */
> +enum hpp_fmt_type {
> +	HPP_FMT__PERCENT,
> +	HPP_FMT__RAW,
> +	HPP_FMT__TIME,
> +};

I wonder if we can't make this a bitmask... Does it make sense to print
both percent and time, for instance?
  
>  typedef int (*hpp_snprint_fn)(char *buf, size_t size, const char *fmt, ...);
>  
>  static int __hpp__fmt(struct perf_hpp *hpp, struct hist_entry *he,
>  		      u64 (*get_field)(struct hist_entry *),
>  		      const char *fmt, hpp_snprint_fn print_fn,
> -		      bool fmt_percent)
> +		      enum hpp_fmt_type type)
>  {
>  	int ret;
>  	struct hists *hists = he->hists;
>  	struct perf_evsel *evsel = hists_to_evsel(hists);
>  
> -	if (fmt_percent) {
> +	if (type == HPP_FMT__PERCENT) {
>  		double percent = 0.0;
>  
>  		if (hists->stats.total_period)
> @@ -27,8 +32,15 @@ static int __hpp__fmt(struct perf_hpp *hpp, struct hist_entry *he,
>  				  hists->stats.total_period;
>  
>  		ret = print_fn(hpp->buf, hpp->size, fmt, percent);
> -	} else
> +	} else if (type == HPP_FMT__RAW) {
>  		ret = print_fn(hpp->buf, hpp->size, fmt, get_field(he));
> +	} else if (type == HPP_FMT__TIME) {
> +		u64 time = get_field(he);
> +		u64 sec = time / NSEC_PER_SEC;
> +		u64 usec = (time - sec * NSEC_PER_SEC) / NSEC_PER_USEC;
> +
> +		ret = print_fn(hpp->buf, hpp->size, fmt, sec, usec);
> +	}
>  
>  	if (perf_evsel__is_group_event(evsel)) {
>  		int prev_idx, idx_delta;
> @@ -53,15 +65,22 @@ static int __hpp__fmt(struct perf_hpp *hpp, struct hist_entry *he,
>  				 * have no sample
>  				 */
>  				ret += print_fn(hpp->buf + ret, hpp->size - ret,
> -						fmt, 0);
> +						fmt, 0, 0);
>  			}
>  
> -			if (fmt_percent)
> +			if (type == HPP_FMT__PERCENT)
>  				ret += print_fn(hpp->buf + ret, hpp->size - ret,
>  						fmt, 100.0 * period / total);
> -			else
> +			else if (type == HPP_FMT__RAW)
>  				ret += print_fn(hpp->buf + ret, hpp->size - ret,
>  						fmt, period);
> +			else if (type == HPP_FMT__TIME) {
> +				u64 sec = period / NSEC_PER_SEC;
> +				u64 usec = (period - sec * NSEC_PER_SEC) / NSEC_PER_USEC;
> +
> +				ret += print_fn(hpp->buf + ret, hpp->size - ret,
> +						fmt, sec, usec);
> +			}
>  
>  			prev_idx = perf_evsel__group_idx(evsel);
>  		}
> @@ -73,7 +92,7 @@ static int __hpp__fmt(struct perf_hpp *hpp, struct hist_entry *he,
>  			 * zero-fill group members at last which have no sample
>  			 */
>  			ret += print_fn(hpp->buf + ret, hpp->size - ret,
> -					fmt, 0);
> +					fmt, 0, 0);
>  		}
>  	}
>  	return ret;
> @@ -117,7 +136,7 @@ static int hpp__color_##_type(struct perf_hpp_fmt *fmt __maybe_unused,		\
>  			      struct perf_hpp *hpp, struct hist_entry *he) 	\
>  {										\
>  	return __hpp__fmt(hpp, he, he_get_##_field, " %6.2f%%",			\
> -			  percent_color_snprintf, true);			\
> +			  percent_color_snprintf, HPP_FMT__PERCENT);		\
>  }
>  
>  #define __HPP_ENTRY_PERCENT_FN(_type, _field)					\
> @@ -126,7 +145,7 @@ static int hpp__entry_##_type(struct perf_hpp_fmt *_fmt __maybe_unused,		\
>  {										\
>  	const char *fmt = symbol_conf.field_sep ? " %.2f" : " %6.2f%%";		\
>  	return __hpp__fmt(hpp, he, he_get_##_field, fmt,			\
> -			  scnprintf, true);					\
> +			  scnprintf, HPP_FMT__PERCENT);				\
>  }
>  
>  #define __HPP_ENTRY_RAW_FN(_type, _field)					\
> @@ -139,7 +158,23 @@ static int hpp__entry_##_type(struct perf_hpp_fmt *_fmt __maybe_unused,		\
>  			      struct perf_hpp *hpp, struct hist_entry *he) 	\
>  {										\
>  	const char *fmt = symbol_conf.field_sep ? " %"PRIu64 : " %11"PRIu64;	\
> -	return __hpp__fmt(hpp, he, he_get_raw_##_field, fmt, scnprintf, false);	\
> +	return __hpp__fmt(hpp, he, he_get_raw_##_field, fmt, scnprintf,		\
> +			  HPP_FMT__RAW);					\
> +}
> +
> +#define __HPP_ENTRY_TIME_FN(_type, _field)					\
> +static u64 he_get_raw_##_field(struct hist_entry *he)				\
> +{										\
> +	return he->stat._field;							\
> +}										\
> +										\
> +static int hpp__entry_##_type(struct perf_hpp_fmt *_fmt __maybe_unused,		\
> +			      struct perf_hpp *hpp, struct hist_entry *he) 	\
> +{										\
> +	const char *fmt = symbol_conf.field_sep ? " %"PRIu64 ".%06"PRIu64 : 	\
> +						  " %2"PRIu64 ".%06"PRIu64;	\
> +	return __hpp__fmt(hpp, he, he_get_raw_##_field, fmt, scnprintf,		\
> +			  HPP_FMT__TIME);					\
>  }
>  
>  #define HPP_PERCENT_FNS(_type, _str, _field, _min_width, _unit_width)	\
> @@ -153,6 +188,11 @@ __HPP_HEADER_FN(_type, _str, _min_width, _unit_width)			\
>  __HPP_WIDTH_FN(_type, _min_width, _unit_width)				\
>  __HPP_ENTRY_RAW_FN(_type, _field)
>  
> +#define HPP_TIME_FNS(_type, _str, _field, _min_width, _unit_width)	\
> +__HPP_HEADER_FN(_type, _str, _min_width, _unit_width)			\
> +__HPP_WIDTH_FN(_type, _min_width, _unit_width)				\
> +__HPP_ENTRY_TIME_FN(_type, _field)
> +
>  
>  HPP_PERCENT_FNS(overhead, "Overhead", period, 8, 8)
>  HPP_PERCENT_FNS(overhead_sys, "sys", period_sys, 8, 8)
> @@ -163,6 +203,8 @@ HPP_PERCENT_FNS(overhead_guest_us, "guest usr", period_guest_us, 9, 8)
>  HPP_RAW_FNS(samples, "Samples", nr_events, 12, 12)
>  HPP_RAW_FNS(period, "Period", period, 12, 12)
>  
> +HPP_TIME_FNS(time, "Time", time, 10, 10)
> +
>  #define HPP__COLOR_PRINT_FNS(_name)			\
>  	{						\
>  		.header	= hpp__header_ ## _name,	\
> @@ -185,7 +227,8 @@ struct perf_hpp_fmt perf_hpp__format[] = {
>  	HPP__COLOR_PRINT_FNS(overhead_guest_sys),
>  	HPP__COLOR_PRINT_FNS(overhead_guest_us),
>  	HPP__PRINT_FNS(samples),
> -	HPP__PRINT_FNS(period)
> +	HPP__PRINT_FNS(period),
> +	HPP__PRINT_FNS(time)
>  };
>  
>  LIST_HEAD(perf_hpp__list);
> @@ -223,6 +266,9 @@ void perf_hpp__init(void)
>  
>  	if (symbol_conf.show_total_period)
>  		perf_hpp__column_enable(PERF_HPP__PERIOD);
> +
> +	if (symbol_conf.show_time_info)
> +		perf_hpp__column_enable(PERF_HPP__TIME);
>  }
>  
>  void perf_hpp__column_register(struct perf_hpp_fmt *format)
> diff --git a/tools/perf/util/hist.h b/tools/perf/util/hist.h
> index 0433469812dc..17e89fb31db9 100644
> --- a/tools/perf/util/hist.h
> +++ b/tools/perf/util/hist.h
> @@ -162,6 +162,7 @@ enum {
>  	PERF_HPP__OVERHEAD_GUEST_US,
>  	PERF_HPP__SAMPLES,
>  	PERF_HPP__PERIOD,
> +	PERF_HPP__TIME,
>  
>  	PERF_HPP__MAX_INDEX
>  };
> diff --git a/tools/perf/util/symbol.h b/tools/perf/util/symbol.h
> index f1031a1358a1..b29d26222c6f 100644
> --- a/tools/perf/util/symbol.h
> +++ b/tools/perf/util/symbol.h
> @@ -99,7 +99,8 @@ struct symbol_conf {
>  			annotate_asm_raw,
>  			annotate_src,
>  			event_group,
> -			demangle;
> +			demangle,
> +			show_time_info;
>  	const char	*vmlinux_name,
>  			*kallsyms_name,
>  			*source_prefix,
> -- 
> 1.7.11.7

Re: [PATCH 2/3] perf tools: Record sampling time for each entry

[Arnaldo Carvalho de Melo]

Em Mon, Dec 02, 2013 at 03:53:18PM +0900, Namhyung Kim escreveu:
> From: Namhyung Kim <namhyung.kim@lge.com>
> 
> Calculate elapsed time for each sample and record it.  The elapsed
> time is a diff between current sample->time and previous sample->time
> which was saved for each evsel and cpu.

Can you elaborate on why this is interesting to have? What meaning can
one get from the sample->time - prev_sample->time?

We need clearer changelogs...

- Arnaldo
 
> Maybe we can use PERF_SAMPLE_READ for the precise result.
> 
> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> ---
>  tools/perf/builtin-annotate.c |  2 +-
>  tools/perf/builtin-diff.c     |  2 +-
>  tools/perf/builtin-report.c   |  9 +++++----
>  tools/perf/builtin-top.c      |  2 +-
>  tools/perf/tests/hists_link.c |  4 ++--
>  tools/perf/util/evsel.h       |  1 +
>  tools/perf/util/hist.c        | 15 ++++++++++-----
>  tools/perf/util/hist.h        |  2 +-
>  tools/perf/util/session.c     | 42 ++++++++++++++++++++++++++++++++++++++++++
>  tools/perf/util/sort.h        |  1 +
>  10 files changed, 65 insertions(+), 15 deletions(-)
> 
> diff --git a/tools/perf/builtin-annotate.c b/tools/perf/builtin-annotate.c
> index 4087ab19823c..dc43a64bf723 100644
> --- a/tools/perf/builtin-annotate.c
> +++ b/tools/perf/builtin-annotate.c
> @@ -65,7 +65,7 @@ static int perf_evsel__add_sample(struct perf_evsel *evsel,
>  		return 0;
>  	}
>  
> -	he = __hists__add_entry(&evsel->hists, al, NULL, NULL, NULL, 1, 1, 0);
> +	he = __hists__add_entry(&evsel->hists, al, NULL, NULL, NULL, 1, 0, 1, 0);
>  	if (he == NULL)
>  		return -ENOMEM;
>  
> diff --git a/tools/perf/builtin-diff.c b/tools/perf/builtin-diff.c
> index 3b67ea2444bd..85aa961a647e 100644
> --- a/tools/perf/builtin-diff.c
> +++ b/tools/perf/builtin-diff.c
> @@ -307,7 +307,7 @@ static int hists__add_entry(struct hists *hists,
>  			    struct addr_location *al, u64 period,
>  			    u64 weight, u64 transaction)
>  {
> -	if (__hists__add_entry(hists, al, NULL, NULL, NULL, period, weight,
> +	if (__hists__add_entry(hists, al, NULL, NULL, NULL, period, 0, weight,
>  			       transaction) != NULL)
>  		return 0;
>  	return -ENOMEM;
> diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
> index 1d47fbec4421..eb849e9f7093 100644
> --- a/tools/perf/builtin-report.c
> +++ b/tools/perf/builtin-report.c
> @@ -116,7 +116,7 @@ static int perf_report__add_mem_hist_entry(struct perf_tool *tool,
>  	 * and the he_stat__add_period() function.
>  	 */
>  	he = __hists__add_entry(&evsel->hists, al, parent, NULL, mi,
> -				cost, cost, 0);
> +				cost, 0, cost, 0);
>  	if (!he)
>  		return -ENOMEM;
>  
> @@ -210,7 +210,7 @@ static int perf_report__add_branch_hist_entry(struct perf_tool *tool,
>  		 * and not events sampled. Thus we use a pseudo period of 1.
>  		 */
>  		he = __hists__add_entry(&evsel->hists, al, parent, &bi[i], NULL,
> -					1, 1, 0);
> +					1, 0, 1, 0);
>  		if (he) {
>  			struct annotation *notes;
>  			bx = he->branch_info;
> @@ -272,8 +272,9 @@ static int perf_evsel__add_hist_entry(struct perf_tool *tool,
>  	}
>  
>  	he = __hists__add_entry(&evsel->hists, al, parent, NULL, NULL,
> -				sample->period, sample->weight,
> -				sample->transaction);
> +				sample->period,
> +				tool->ordered_samples ? sample->read.time_enabled : 0,
> +				sample->weight, sample->transaction);
>  	if (he == NULL)
>  		return -ENOMEM;
>  
> diff --git a/tools/perf/builtin-top.c b/tools/perf/builtin-top.c
> index 03d37a76c612..175bde2a0ece 100644
> --- a/tools/perf/builtin-top.c
> +++ b/tools/perf/builtin-top.c
> @@ -247,7 +247,7 @@ static struct hist_entry *perf_evsel__add_hist_entry(struct perf_evsel *evsel,
>  
>  	pthread_mutex_lock(&evsel->hists.lock);
>  	he = __hists__add_entry(&evsel->hists, al, NULL, NULL, NULL,
> -				sample->period, sample->weight,
> +				sample->period, 0, sample->weight,
>  				sample->transaction);
>  	pthread_mutex_unlock(&evsel->hists.lock);
>  	if (he == NULL)
> diff --git a/tools/perf/tests/hists_link.c b/tools/perf/tests/hists_link.c
> index 173bf42cc03e..7bb952e6be62 100644
> --- a/tools/perf/tests/hists_link.c
> +++ b/tools/perf/tests/hists_link.c
> @@ -223,7 +223,7 @@ static int add_hist_entries(struct perf_evlist *evlist, struct machine *machine)
>  				goto out;
>  
>  			he = __hists__add_entry(&evsel->hists, &al, NULL,
> -						NULL, NULL, 1, 1, 0);
> +						NULL, NULL, 1, 0, 1, 0);
>  			if (he == NULL)
>  				goto out;
>  
> @@ -246,7 +246,7 @@ static int add_hist_entries(struct perf_evlist *evlist, struct machine *machine)
>  				goto out;
>  
>  			he = __hists__add_entry(&evsel->hists, &al, NULL,
> -						NULL, NULL, 1, 1, 0);
> +						NULL, NULL, 1, 0, 1, 0);
>  			if (he == NULL)
>  				goto out;
>  
> diff --git a/tools/perf/util/evsel.h b/tools/perf/util/evsel.h
> index 20a7c653b74b..ac65fc67972c 100644
> --- a/tools/perf/util/evsel.h
> +++ b/tools/perf/util/evsel.h
> @@ -69,6 +69,7 @@ struct perf_evsel {
>  	struct hists		hists;
>  	u64			first_timestamp;
>  	u64			last_timestamp;
> +	u64			*prev_timestamps;
>  	char			*name;
>  	double			scale;
>  	const char		*unit;
> diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
> index 822903eaa201..8d9278df59fa 100644
> --- a/tools/perf/util/hist.c
> +++ b/tools/perf/util/hist.c
> @@ -204,11 +204,12 @@ static void hist_entry__add_cpumode_period(struct hist_entry *he,
>  }
>  
>  static void he_stat__add_period(struct he_stat *he_stat, u64 period,
> -				u64 weight)
> +				u64 time, u64 weight)
>  {
>  
>  	he_stat->period		+= period;
>  	he_stat->weight		+= weight;
> +	he_stat->time		+= time;
>  	he_stat->nr_events	+= 1;
>  }
>  
> @@ -221,10 +222,12 @@ static void he_stat__add_stat(struct he_stat *dest, struct he_stat *src)
>  	dest->period_guest_us	+= src->period_guest_us;
>  	dest->nr_events		+= src->nr_events;
>  	dest->weight		+= src->weight;
> +	dest->time		+= src->time;
>  }
>  
>  static void hist_entry__decay(struct hist_entry *he)
>  {
> +	he->stat.time = (he->stat.time * 7) / 8;
>  	he->stat.period = (he->stat.period * 7) / 8;
>  	he->stat.nr_events = (he->stat.nr_events * 7) / 8;
>  	/* XXX need decay for weight too? */
> @@ -344,7 +347,7 @@ static u8 symbol__parent_filter(const struct symbol *parent)
>  static struct hist_entry *add_hist_entry(struct hists *hists,
>  				      struct hist_entry *entry,
>  				      struct addr_location *al,
> -				      u64 period,
> +				      u64 period, u64 time,
>  				      u64 weight)
>  {
>  	struct rb_node **p;
> @@ -367,7 +370,7 @@ static struct hist_entry *add_hist_entry(struct hists *hists,
>  		cmp = hist_entry__cmp(he, entry);
>  
>  		if (!cmp) {
> -			he_stat__add_period(&he->stat, period, weight);
> +			he_stat__add_period(&he->stat, period, time, weight);
>  
>  			/*
>  			 * This mem info was allocated from machine__resolve_mem
> @@ -412,7 +415,8 @@ struct hist_entry *__hists__add_entry(struct hists *hists,
>  				      struct symbol *sym_parent,
>  				      struct branch_info *bi,
>  				      struct mem_info *mi,
> -				      u64 period, u64 weight, u64 transaction)
> +				      u64 period, u64 time,
> +				      u64 weight, u64 transaction)
>  {
>  	struct hist_entry entry = {
>  		.thread	= al->thread,
> @@ -428,6 +432,7 @@ struct hist_entry *__hists__add_entry(struct hists *hists,
>  			.nr_events = 1,
>  			.period	= period,
>  			.weight = weight,
> +			.time = time,
>  		},
>  		.parent = sym_parent,
>  		.filtered = symbol__parent_filter(sym_parent),
> @@ -437,7 +442,7 @@ struct hist_entry *__hists__add_entry(struct hists *hists,
>  		.transaction = transaction,
>  	};
>  
> -	return add_hist_entry(hists, &entry, al, period, weight);
> +	return add_hist_entry(hists, &entry, al, period, time, weight);
>  }
>  
>  int64_t
> diff --git a/tools/perf/util/hist.h b/tools/perf/util/hist.h
> index bc5acdfc2b4b..0433469812dc 100644
> --- a/tools/perf/util/hist.h
> +++ b/tools/perf/util/hist.h
> @@ -89,7 +89,7 @@ struct hist_entry *__hists__add_entry(struct hists *hists,
>  				      struct addr_location *al,
>  				      struct symbol *parent,
>  				      struct branch_info *bi,
> -				      struct mem_info *mi, u64 period,
> +				      struct mem_info *mi, u64 period, u64 time,
>  				      u64 weight, u64 transaction);
>  int64_t hist_entry__cmp(struct hist_entry *left, struct hist_entry *right);
>  int64_t hist_entry__collapse(struct hist_entry *left, struct hist_entry *right);
> diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
> index e4b158f0586a..f36e95f00a05 100644
> --- a/tools/perf/util/session.c
> +++ b/tools/perf/util/session.c
> @@ -926,6 +926,48 @@ perf_session__deliver_sample(struct perf_session *session,
>  	u64 read_format = evsel->attr.read_format;
>  
>  	if (tool->ordered_samples) {
> +		/* FIXME: need to find a way to determine cpu-wide session */
> +		bool per_cpu_session = sample_type & PERF_SAMPLE_CPU;
> +
> +		sample->read.time_enabled = 0;
> +
> +		if (per_cpu_session) {
> +			u64 *ts = evsel->prev_timestamps;
> +
> +			if (ts == NULL) {
> +				int nr_cpus = session->header.env.nr_cpus_online;
> +
> +				ts = zalloc(nr_cpus * sizeof(ts));
> +				if (ts == NULL)
> +					return -ENOMEM;
> +
> +				evsel->prev_timestamps = ts;
> +			}
> +
> +			if (ts[sample->cpu] != 0) {
> +				u64 diff = sample->time - ts[sample->cpu];
> +
> +				sample->read.time_enabled = diff;
> +			}
> +			ts[sample->cpu] = sample->time;
> +		} else {
> +			u64 *ts = evsel->prev_timestamps;
> +
> +			if (ts == NULL) {
> +				ts = zalloc(sizeof(*ts));
> +				if (ts == NULL)
> +					return -ENOMEM;
> +
> +				evsel->prev_timestamps = ts;
> +			}
> +
> +			if (*ts != 0) {
> +				u64 diff = sample->time - *ts;
> +				sample->read.time_enabled = diff;
> +			}
> +			*ts = sample->time;
> +		}
> +
>  		if (evsel->first_timestamp == 0)
>  			evsel->first_timestamp = sample->time;
>  
> diff --git a/tools/perf/util/sort.h b/tools/perf/util/sort.h
> index 43e5ff42a609..16aaf0a47346 100644
> --- a/tools/perf/util/sort.h
> +++ b/tools/perf/util/sort.h
> @@ -51,6 +51,7 @@ struct he_stat {
>  	u64			period_guest_sys;
>  	u64			period_guest_us;
>  	u64			weight;
> +	u64			time;
>  	u32			nr_events;
>  };
>  
> -- 
> 1.7.11.7

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

[Ingo Molnar]

* Namhyung Kim <namhyung@kernel.org> wrote:

> 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)

Btw., would it make sense to output it using the 'perf stat' print-out 
machinery?

If the 'count' of every event sampled is saved in the perf.data, 
including elapsed time, at the beginning and at the end, then all 
information is there to output things in perf stat style.

( It might even make sense to save two more timestamps: rusage stime
  and utime - that way the output could be made /usr/bin/time-alike. )

Also I think there is some related existing functionality, I think 
Stephane added a way to essentially do non-sampling 'perf stat' via 
perf record - but the details escape me, I think it was related to the 
-n option?

So what we want here is in essence a sampling mode that can record and 
report all the absolute counts as well.

Thanks,

	Ingo

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

[Ingo Molnar]

So basically, in the end I think it should be possible to have the 
following behavior:

   perf record -a -e cycles sleep 1

   perf report stat              # Reports as if we ran: 'perf stat -a -e cycles sleep 1'
   perf report                   # Reports the usual histogram

   perf report --stat            # Reports the perf stat output and the histogram

or so.

i.e. a perf.data file would by default always carry enough information 
to enable the extraction of the 'perf stat' data.

At that point visualizing it is purely report-time logic, it does not 
need any record-time options.

This would work for multi-event sampling as well, if we do:

   perf record -a -e cycles -e branches sleep 1

then 'perf report stat' would output the same as:

 $ perf stat -e cycles -e branches -a sleep 1

 Performance counter stats for 'system wide':

        34,174,518      cycles                    [100.00%]
         3,155,677      branches                                                    

       1.000802852 seconds time elapsed

Another neat feature this kind of workflo enables is the integration 
of --repeat to perf record, so something like:

    perf record --repeat 3 -a -e cycles -e branches sleep 1

would save 3 samples after each other, and would allow extraction of 
the statistical stability of the measurement, and 'perf report stat' 
would print the same result as a raw perf stat run would:

 $ perf stat --repeat 3 -e cycles -e branches -e instructions -a sleep 1

 Performance counter stats for 'system wide' (3 runs):

    28,975,150,642      cycles                     ( +-  0.43% ) [100.00%]
    10,740,235,371      branches                                                      ( +-  0.47% ) [100.00%]
    44,535,464,754      instructions              #    1.54  insns per cycle          ( +-  0.47% )

       1.005718027 seconds time elapsed                                          ( +-  0.43% )

Or something like that. At that point we share reporting between perf 
stat and perf report, no special ad-hoc options are needed to just 
measure and report timestamps, it would all be a 'natural' side effect 
of having perf stat.

What do you think?

Thanks,

	Ingo

Re: [PATCH 3/3] perf report: Add --show-time-info option

[Namhyung Kim]

Hi Arnaldo,

2013-12-02 (월), 09:33 -0300, Arnaldo Carvalho de Melo:
> Em Mon, Dec 02, 2013 at 03:53:19PM +0900, Namhyung Kim escreveu:
> > From: Namhyung Kim <namhyung.kim@lge.com>
> > 
> > The --show-time-info option is for displaying elapsed sampling time
> 
> Isn't that too long? Can't we use just --time/-t?

Hmm.. interesting.  Your previous feedback was to use longer and clearer
option name. :)

https://lkml.org/lkml/2013/11/18/198

> 
> > information for each entry.
> > 
> >   $ perf record -- perf bench sched messaging
> >   $ perf report --stdio --show-time-info
> >   ...
> >   # Samples: 10K of event 'cycles'
> >   # Event count (approx.): 5118793536
> >   # Total sampling time  : 0.184277 (sec)
> >   #
> >   # Overhead        Time          Command      Shared Object                       Symbol
> >   # ........  ..........  ...............  .................  ...........................
> >   #
> >        7.26%    0.007413  sched-messaging  [unknown]          [.] 0x0000003153e7a6e7
> >        4.79%    0.006088  sched-messaging  [kernel.kallsyms]  [k] avc_has_perm_flags
> >        4.38%    0.004809  sched-messaging  [kernel.kallsyms]  [k] copy_user_generic_string
> >        3.81%    0.005457  sched-messaging  [kernel.kallsyms]  [k] _raw_spin_lock
> >        2.92%    0.002745  sched-messaging  [kernel.kallsyms]  [k] _raw_spin_lock_irqsave
> >        2.72%    0.002896  sched-messaging  [kernel.kallsyms]  [k] unix_stream_recvmsg
> >        2.55%    0.003745  sched-messaging  [kernel.kallsyms]  [k] __slab_free
> >        2.45%    0.002807  sched-messaging  [kernel.kallsyms]  [k] page_fault
> >        2.08%    0.002258  sched-messaging  [kernel.kallsyms]  [k] sock_has_perm
> > 
> > Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> > ---
> >  tools/perf/builtin-report.c |  2 ++
> >  tools/perf/ui/hist.c        | 68 +++++++++++++++++++++++++++++++++++++--------
> >  tools/perf/util/hist.h      |  1 +
> >  tools/perf/util/symbol.h    |  3 +-
> >  4 files changed, 62 insertions(+), 12 deletions(-)
> > 
> > diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
> > index eb849e9f7093..345cce6f5fa2 100644
> > --- a/tools/perf/builtin-report.c
> > +++ b/tools/perf/builtin-report.c
> > @@ -898,6 +898,8 @@ int cmd_report(int argc, const char **argv, const char *prefix __maybe_unused)
> >  	OPT_BOOLEAN(0, "mem-mode", &report.mem_mode, "mem access profile"),
> >  	OPT_CALLBACK(0, "percent-limit", &report, "percent",
> >  		     "Don't show entries under that percent", parse_percent_limit),
> > +	OPT_BOOLEAN(0, "show-time-info", &symbol_conf.show_time_info,
> > +		    "Show a column with the elapsed time"),
> >  	OPT_END()
> >  	};
> >  	struct perf_data_file file = {
> > diff --git a/tools/perf/ui/hist.c b/tools/perf/ui/hist.c
> > index 78f4c92e9b73..7cf584a0bb61 100644
> > --- a/tools/perf/ui/hist.c
> > +++ b/tools/perf/ui/hist.c
> > @@ -7,19 +7,24 @@
> >  #include "../util/evsel.h"
> >  
> >  /* hist period print (hpp) functions */
> > +enum hpp_fmt_type {
> > +	HPP_FMT__PERCENT,
> > +	HPP_FMT__RAW,
> > +	HPP_FMT__TIME,
> > +};
> 
> I wonder if we can't make this a bitmask... Does it make sense to print
> both percent and time, for instance?

I'm not sure I understood you correctly, but did you mean printing both
percent and time in a single column?  This enum and the __hpp_fmt()
function is for a single column.  I can add a new column for time
percent if you want.

Thanks,
Namhyung

Re: [PATCH 2/3] perf tools: Record sampling time for each entry

[Namhyung Kim]

2013-12-02 (월), 09:39 -0300, Arnaldo Carvalho de Melo:
> Em Mon, Dec 02, 2013 at 03:53:18PM +0900, Namhyung Kim escreveu:
> > From: Namhyung Kim <namhyung.kim@lge.com>
> > 
> > Calculate elapsed time for each sample and record it.  The elapsed
> > time is a diff between current sample->time and previous sample->time
> > which was saved for each evsel and cpu.
> 
> Can you elaborate on why this is interesting to have? What meaning can
> one get from the sample->time - prev_sample->time?
> 
> We need clearer changelogs...

Sorry about that.. how about this?

Sometimes users might want see a relation between value and time of a
sample.  And the time itself is a very important information to have.
As the sample->period value is a diff of counter values between samples
it might make sense to add time-diff between samples into a hist entry.

To do that, calculate elapsed time for each sample and record it.  The
elapsed time is the diff between current sample->time and previous
sample->time which was saved for each evsel.

Thanks,
Namhyung

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

[Namhyung Kim]

Hi Ingo,

2013-12-02 (월), 13:45 +0100, Ingo Molnar:
> * Namhyung Kim <namhyung@kernel.org> wrote:
> 
> > 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)
> 
> Btw., would it make sense to output it using the 'perf stat' print-out 
> machinery?
> 
> If the 'count' of every event sampled is saved in the perf.data, 
> including elapsed time, at the beginning and at the end, then all 
> information is there to output things in perf stat style.

Yeah, it'd be great if we can share same code in the end.

> 
> ( It might even make sense to save two more timestamps: rusage stime
>   and utime - that way the output could be made /usr/bin/time-alike. )

Hmm.. I think I can do it by adding time info according to a cpumode in
a sample.

> 
> Also I think there is some related existing functionality, I think 
> Stephane added a way to essentially do non-sampling 'perf stat' via 
> perf record - but the details escape me, I think it was related to the 
> -n option?

I have no idea about the perf record -n/--no-samples option.  It looks
like something related to task stat?

  commit 649c48a9e7fafcc72bfcc99471d9dea98d789d59
  Author: Peter Zijlstra <a.p.zijlstra@chello.nl>
  Date:   Wed Jun 24 21:12:48 2009 +0200
  
      perf-report: Add modes for inherited stats and no-samples
      
      Now that we can collect per task statistics, add modes that
      make use of that facility.
      
      Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
      LKML-Reference: <new-submission>
      Signed-off-by: Ingo Molnar <mingo@elte.hu>


But everytime I tried to use it, perf report always complained about the
file has no samples.. :-/

> 
> So what we want here is in essence a sampling mode that can record and 
> report all the absolute counts as well.

Agreed.

Thanks,
Namhyung

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

[Namhyung Kim]

2013-12-02 (월), 13:57 +0100, Ingo Molnar:
> So basically, in the end I think it should be possible to have the 
> following behavior:
> 
>    perf record -a -e cycles sleep 1
> 
>    perf report stat              # Reports as if we ran: 'perf stat -a -e cycles sleep 1'
>    perf report                   # Reports the usual histogram
> 
>    perf report --stat            # Reports the perf stat output and the histogram
> 
> or so.

I don't think we need both of 'perf report stat' and 'perf report
--stat'.  At least it looks somewhat confusing to users IMHO.

For perf report stat usage, I think there's not much thing we can do for
a single event - the most case.  We can simple show total count and
elapsed (or sampled time) for the event, but it's already in the header
with this patch.

      # Samples: 4K of event 'cycles'
      # Event count (approx.): 4087481688
      # Total sampling time  : 1.001260 (sec)


If an user really want to see perf stat-like output (without the usual
histogram) for a recorded session, it'd be better to have 'perf record
--stat' do the job (like git diff --stat) IMHO.

> 
> i.e. a perf.data file would by default always carry enough information 
> to enable the extraction of the 'perf stat' data.
> 
> At that point visualizing it is purely report-time logic, it does not 
> need any record-time options.
> 
> This would work for multi-event sampling as well, if we do:
> 
>    perf record -a -e cycles -e branches sleep 1
> 
> then 'perf report stat' would output the same as:
> 
>  $ perf stat -e cycles -e branches -a sleep 1
> 
>  Performance counter stats for 'system wide':
> 
>         34,174,518      cycles                    [100.00%]
>          3,155,677      branches                                                    
> 
>        1.000802852 seconds time elapsed
> 

Yeah, it'd be good to have same output both for perf stat and perf
report --stat (or stat if you want).  But I don't think it's possible to
determine multiplexed counter values like perf stat does unless we use
PERF_SAMPLE_READ for recoding.


> Another neat feature this kind of workflo enables is the integration 
> of --repeat to perf record, so something like:
> 
>     perf record --repeat 3 -a -e cycles -e branches sleep 1
> 
> would save 3 samples after each other, and would allow extraction of 
> the statistical stability of the measurement, and 'perf report stat' 
> would print the same result as a raw perf stat run would:
> 
>  $ perf stat --repeat 3 -e cycles -e branches -e instructions -a sleep 1
> 
>  Performance counter stats for 'system wide' (3 runs):
> 
>     28,975,150,642      cycles                     ( +-  0.43% ) [100.00%]
>     10,740,235,371      branches                                                      ( +-  0.47% ) [100.00%]
>     44,535,464,754      instructions              #    1.54  insns per cycle          ( +-  0.47% )
> 
>        1.005718027 seconds time elapsed                                          ( +-  0.43% )

Yeah, but it can be used only for a new forked workload.

> 
> Or something like that. At that point we share reporting between perf 
> stat and perf report, no special ad-hoc options are needed to just 
> measure and report timestamps, it would all be a 'natural' side effect 
> of having perf stat.
> 
> What do you think?

I think it'd be better if we can share code as much as possible.  And
it'd much better if we can forget about the difference in options. :)

Thanks,
Namhyung

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

[Ingo Molnar]

* Namhyung Kim <namhyung@kernel.org> wrote:

> 2013-12-02 (월), 13:57 +0100, Ingo Molnar:
> > So basically, in the end I think it should be possible to have the 
> > following behavior:
> > 
> >    perf record -a -e cycles sleep 1
> > 
> >    perf report stat              # Reports as if we ran: 'perf stat -a -e cycles sleep 1'
> >    perf report                   # Reports the usual histogram
> > 
> >    perf report --stat            # Reports the perf stat output and the histogram
> > 
> > or so.
> 
> I don't think we need both of 'perf report stat' and 'perf report
> --stat'.  At least it looks somewhat confusing to users IMHO.

Okay. Maybe the --stat option would be the more logical choice, 
because '--' options can be added arbitrarily, while it would be weird 
to add multiple subcommand options.

So basically there would be two options:

   --show-stat         [--no-show-stat]
   --show-histogram    [--no-show-histogram]

Today --show-histogram is the only one enabled by default.

Running:

   perf report --no-show-histogram --show-stat

would give perf-stat output.

This --show-* pattern could be used in the future, for example to 
express debug output:

  perf report --show-debug

Or to show other details that are off by default.

'perf report --show' should perhaps list all --show options that are 
available currently.

Maybe the syntax should be similar to the sort option?

What's your preference?

> For perf report stat usage, I think there's not much thing we can do 
> for a single event - the most case.  We can simple show total count 
> and elapsed (or sampled time) for the event, but it's already in the 
> header with this patch.
> 
>       # Samples: 4K of event 'cycles'
>       # Event count (approx.): 4087481688
>       # Total sampling time  : 1.001260 (sec)

That's what I mean, instead of 'this patch' we should utilize perf 
stat output mode. That will solve your particular feature request 
here, plus gives us much more: it gives perf stat integration into 
report.

> If an user really want to see perf stat-like output (without the 
> usual histogram) for a recorded session, it'd be better to have 
> 'perf record --stat' do the job (like git diff --stat) IMHO.

Why? Showing the result is a reporting feature really. Firstly we 
record everything, then we 'analyze', looking at various details of 
data.

Getting perf stat output could be used to get a first, rough, high 
level overview.

> > i.e. a perf.data file would by default always carry enough information 
> > to enable the extraction of the 'perf stat' data.
> > 
> > At that point visualizing it is purely report-time logic, it does not 
> > need any record-time options.
> > 
> > This would work for multi-event sampling as well, if we do:
> > 
> >    perf record -a -e cycles -e branches sleep 1
> > 
> > then 'perf report stat' would output the same as:
> > 
> >  $ perf stat -e cycles -e branches -a sleep 1
> > 
> >  Performance counter stats for 'system wide':
> > 
> >         34,174,518      cycles                    [100.00%]
> >          3,155,677      branches                                                    
> > 
> >        1.000802852 seconds time elapsed
> > 
> 
> Yeah, it'd be good to have same output both for perf stat and perf 
> report --stat (or stat if you want).  But I don't think it's 
> possible to determine multiplexed counter values like perf stat does 
> unless we use PERF_SAMPLE_READ for recoding.

That's my point: is there any reason why we shouldn't turn on 
PERF_SAMPLE_READ for these events, and read them at the beginning and 
at the end of a sampling session?

( some people might even want periodic samples emitted inbetween, to 
  be able to see a time flow representation of samples, but that's for 
  the future. )

> > Another neat feature this kind of workflo enables is the integration 
> > of --repeat to perf record, so something like:
> > 
> >     perf record --repeat 3 -a -e cycles -e branches sleep 1
> > 
> > would save 3 samples after each other, and would allow extraction of 
> > the statistical stability of the measurement, and 'perf report stat' 
> > would print the same result as a raw perf stat run would:
> > 
> >  $ perf stat --repeat 3 -e cycles -e branches -e instructions -a sleep 1
> > 
> >  Performance counter stats for 'system wide' (3 runs):
> > 
> >     28,975,150,642      cycles                     ( +-  0.43% ) [100.00%]
> >     10,740,235,371      branches                                                      ( +-  0.47% ) [100.00%]
> >     44,535,464,754      instructions              #    1.54  insns per cycle          ( +-  0.47% )
> > 
> >        1.005718027 seconds time elapsed                                          ( +-  0.43% )
> 
> Yeah, but it can be used only for a new forked workload.

Well, it can be used for anything that perf record can do today, 
except maybe the Ctrl-C method of measurement, right?

> > Or something like that. At that point we share reporting between 
> > perf stat and perf report, no special ad-hoc options are needed to 
> > just measure and report timestamps, it would all be a 'natural' 
> > side effect of having perf stat.
> > 
> > What do you think?
> 
> I think it'd be better if we can share code as much as possible.  
> And it'd much better if we can forget about the difference in 
> options. :)

Agreed - see the --show-<xyz> pattern I suggested above.

It could be different as well, sort-key alike:

   --show +stat,-hist,+debug

Thanks,

	Ingo

Re: [RFC 0/3] perf tools: Show time info (v1)

[Andi Kleen]

On Mon, Dec 02, 2013 at 03:53:16PM +0900, Namhyung Kim wrote:
> Hi,
> 
> Sometimes users might want to see time information along with the
> performance result but the perf cannot provide it currently.
> 
> In this patchset, I added such feature using sample->time.  When the
> perf processes sample events, it calculate time info and update last
> timestamp.  It keeps the last timestamp for each evsel (and for each
> cpu if it's a per-cpu session).

Does the sorting on arbitary fields work now?

I believe to make use of this you totally want to sort on it too,
but traditionally perf report could only sort on a single field.

Without sorting adding more and more fields is just confusing. 

-Andi

Re: [PATCH 2/3] perf tools: Record sampling time for each entry

[Arnaldo Carvalho de Melo]

Em Mon, Dec 02, 2013 at 11:57:44PM +0900, Namhyung Kim escreveu:
> 2013-12-02 (월), 09:39 -0300, Arnaldo Carvalho de Melo:
> > Em Mon, Dec 02, 2013 at 03:53:18PM +0900, Namhyung Kim escreveu:
> > > From: Namhyung Kim <namhyung.kim@lge.com>
> > > 
> > > Calculate elapsed time for each sample and record it.  The elapsed
> > > time is a diff between current sample->time and previous sample->time
> > > which was saved for each evsel and cpu.
> > 
> > Can you elaborate on why this is interesting to have? What meaning can
> > one get from the sample->time - prev_sample->time?
> > 
> > We need clearer changelogs...
> 
> Sorry about that.. how about this?
> 
> Sometimes users might want see a relation between value and time of a
> sample.  And the time itself is a very important information to have.
> As the sample->period value is a diff of counter values between samples
> it might make sense to add time-diff between samples into a hist entry.
> 
> To do that, calculate elapsed time for each sample and record it.  The
> elapsed time is the diff between current sample->time and previous
> sample->time which was saved for each evsel.

Much better! Thanks, and please consider adding this to the man page as
well, in a followup patch.

I'll add the above explanation to the patch, that, as I could read seems
to not have had any nak, right?

- Arnaldo

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

[Arnaldo Carvalho de Melo]

Em Tue, Dec 03, 2013 at 12:05:49AM +0900, Namhyung Kim escreveu:
> Hi Ingo,
> 
> 2013-12-02 (월), 13:45 +0100, Ingo Molnar:
> > * Namhyung Kim <namhyung@kernel.org> wrote:
> > 
> > > 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)
> > 
> > Btw., would it make sense to output it using the 'perf stat' print-out 
> > machinery?
> > 
> > If the 'count' of every event sampled is saved in the perf.data, 
> > including elapsed time, at the beginning and at the end, then all 
> > information is there to output things in perf stat style.
> 
> Yeah, it'd be great if we can share same code in the end.

I guess we'll basically just process all samples, accumulating stuff
where the builtin-stat code finds them, in struct perf_evsel, then just
hand it to that code.

- Arnaldo

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

[Arnaldo Carvalho de Melo]

Em Mon, Dec 02, 2013 at 05:36:20PM +0100, Ingo Molnar escreveu:
> * Namhyung Kim <namhyung@kernel.org> wrote:
> > 2013-12-02 (월), 13:57 +0100, Ingo Molnar:
> > > So basically, in the end I think it should be possible to have the 
> > > following behavior:

> > >    perf record -a -e cycles sleep 1

> > >    perf report stat              # Reports as if we ran: 'perf stat -a -e cycles sleep 1'
> > >    perf report                   # Reports the usual histogram

> > >    perf report --stat            # Reports the perf stat output and the histogram

> > > or so.

> > I don't think we need both of 'perf report stat' and 'perf report
> > --stat'.  At least it looks somewhat confusing to users IMHO.
 
> Okay. Maybe the --stat option would be the more logical choice, 
> because '--' options can be added arbitrarily, while it would be weird 
> to add multiple subcommand options.
 
> So basically there would be two options:
 
>    --show-stat         [--no-show-stat]
>    --show-histogram    [--no-show-histogram]
 
> Today --show-histogram is the only one enabled by default.
 
> Running:
 
>    perf report --no-show-histogram --show-stat

Why not:

perf stat -i perf.data

and make it be an optional argument, so plain:

perf stat -i

would process perf.data, i.e. would get the samples, accrue the periods,
calculate the time, etc and then present it as 'perf stat <some
target>'.

Right now 'perf stat -i' i used for '--no-inherit', perhaps we can just
have --no-inherit have no short option and grab -i to have the same
meaning as in 'report', 'script', etc.

- Arnaldo

Re: [RFC 0/3] perf tools: Show time info (v1)

[Namhyung Kim]

Hi Pekka,

On Mon, 02 Dec 2013 11:35:04 +0200, Pekka Enberg wrote:
> On 12/02/2013 08:53 AM, Namhyung Kim wrote:
>> Any comments are welcome, thanks
>
> Reviewed-by: Pekka Enberg <penberg@kernel.org>
>
> for the whole series.

Thank you very much!
Namhyung

Re: [RFC 0/3] perf tools: Show time info (v1)

[Namhyung Kim]

Hi Andi,

On Mon, 2 Dec 2013 18:04:48 +0100, Andi Kleen wrote:
> On Mon, Dec 02, 2013 at 03:53:16PM +0900, Namhyung Kim wrote:
>> Hi,
>> 
>> Sometimes users might want to see time information along with the
>> performance result but the perf cannot provide it currently.
>> 
>> In this patchset, I added such feature using sample->time.  When the
>> perf processes sample events, it calculate time info and update last
>> timestamp.  It keeps the last timestamp for each evsel (and for each
>> cpu if it's a per-cpu session).
>
> Does the sorting on arbitary fields work now?
>
> I believe to make use of this you totally want to sort on it too,
> but traditionally perf report could only sort on a single field.
>
> Without sorting adding more and more fields is just confusing. 

Yeah, that's the plan that I also have.  As Ingo requested, we'll have
more flexible field and sort-key selection options.  I'll work on that
as soon as the on-going works find their way to inclusion.

Thanks,
Namhyung

Re: [PATCH 2/3] perf tools: Record sampling time for each entry

[Namhyung Kim]

Hi Arnaldo,

On Mon, 2 Dec 2013 15:49:05 -0300, Arnaldo Carvalho de Melo wrote:
> Em Mon, Dec 02, 2013 at 11:57:44PM +0900, Namhyung Kim escreveu:
>> 2013-12-02 (월), 09:39 -0300, Arnaldo Carvalho de Melo:
>> > Em Mon, Dec 02, 2013 at 03:53:18PM +0900, Namhyung Kim escreveu:
>> > > From: Namhyung Kim <namhyung.kim@lge.com>
>> > > 
>> > > Calculate elapsed time for each sample and record it.  The elapsed
>> > > time is a diff between current sample->time and previous sample->time
>> > > which was saved for each evsel and cpu.
>> > 
>> > Can you elaborate on why this is interesting to have? What meaning can
>> > one get from the sample->time - prev_sample->time?
>> > 
>> > We need clearer changelogs...
>> 
>> Sorry about that.. how about this?
>> 
>> Sometimes users might want see a relation between value and time of a
>> sample.  And the time itself is a very important information to have.
>> As the sample->period value is a diff of counter values between samples
>> it might make sense to add time-diff between samples into a hist entry.
>> 
>> To do that, calculate elapsed time for each sample and record it.  The
>> elapsed time is the diff between current sample->time and previous
>> sample->time which was saved for each evsel.
>
> Much better! Thanks, and please consider adding this to the man page as
> well, in a followup patch.

Okay.

>
> I'll add the above explanation to the patch, that, as I could read seems
> to not have had any nak, right?

Right.  So will you merge this into your tree with new changelog?  I
found that it break build on an old system due to shadowing 'time'
symbol with local one.

I'll send v2 soon with a fix.

Thanks,
Namhyung

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

[Namhyung Kim]

Hi Ingo,

On Mon, 2 Dec 2013 17:36:20 +0100, Ingo Molnar wrote:
> * Namhyung Kim <namhyung@kernel.org> wrote:
>
>> 2013-12-02 (월), 13:57 +0100, Ingo Molnar:
>> > So basically, in the end I think it should be possible to have the 
>> > following behavior:
>> > 
>> >    perf record -a -e cycles sleep 1
>> > 
>> >    perf report stat              # Reports as if we ran: 'perf stat -a -e cycles sleep 1'
>> >    perf report                   # Reports the usual histogram
>> > 
>> >    perf report --stat            # Reports the perf stat output and the histogram
>> > 
>> > or so.
>> 
>> I don't think we need both of 'perf report stat' and 'perf report
>> --stat'.  At least it looks somewhat confusing to users IMHO.
>
> Okay. Maybe the --stat option would be the more logical choice, 
> because '--' options can be added arbitrarily, while it would be weird 
> to add multiple subcommand options.
>
> So basically there would be two options:
>
>    --show-stat         [--no-show-stat]
>    --show-histogram    [--no-show-histogram]
>
> Today --show-histogram is the only one enabled by default.

Hmm.. okay, this is possible.  But we have some --show-* options already
mostly for enabling more columns so it won't be symmetric to this level
of control.  What about using plain --stat nad --historam then?

Or we can deprecate those existing --show-* options and convert them to
suggested -F <fields> option and then use your proposal above.

>
> Running:
>
>    perf report --no-show-histogram --show-stat
>
> would give perf-stat output.

Right.

>
> This --show-* pattern could be used in the future, for example to 
> express debug output:
>
>   perf report --show-debug
>
> Or to show other details that are off by default.
>
> 'perf report --show' should perhaps list all --show options that are 
> available currently.

You can do similar with shell completion. :)

>
> Maybe the syntax should be similar to the sort option?
>
> What's your preference?

Well, I think it's good to have separate options (like --[show-]stat,
--[show-]histogram, etc) if they won't grow to many.  But if there's a
possiblity of growing, it'd be more convenient to have single option can
receive multiple values like the sort option does.

>
>> For perf report stat usage, I think there's not much thing we can do 
>> for a single event - the most case.  We can simple show total count 
>> and elapsed (or sampled time) for the event, but it's already in the 
>> header with this patch.
>> 
>>       # Samples: 4K of event 'cycles'
>>       # Event count (approx.): 4087481688
>>       # Total sampling time  : 1.001260 (sec)
>
> That's what I mean, instead of 'this patch' we should utilize perf 
> stat output mode. That will solve your particular feature request 
> here, plus gives us much more: it gives perf stat integration into 
> report.

Let me clarify.  The first two lines were already there before this
patch and I just added last sampling time line.  Those lines are
displayed right above the usual histogram for each event.  They are
displayed by default on --stdio output.

And you want to make it look like perf stat, right?

So what should perf report --[show-]stat do (say there're two events)?

1. display perf stat-like output at the beginning or end of usual output
and remove those per-event info in the header

2. same as 1 but keep the original per-event info

3. same as 1 but also change per-event info to perf stat-like output

4. just change per-event info to perf stat-like output

>
>> If an user really want to see perf stat-like output (without the 
>> usual histogram) for a recorded session, it'd be better to have 
>> 'perf record --stat' do the job (like git diff --stat) IMHO.
>
> Why? Showing the result is a reporting feature really. Firstly we 
> record everything, then we 'analyze', looking at various details of 
> data.
>
> Getting perf stat output could be used to get a first, rough, high 
> level overview.

Yes, but perf report already provides such high level information per
event so I just thought the --[show-]stat can be used to see the whole
picture only.  But I won't insist it strongly - sometimes it might be
useful to see both information together.

>
>> > i.e. a perf.data file would by default always carry enough information 
>> > to enable the extraction of the 'perf stat' data.
>> > 
>> > At that point visualizing it is purely report-time logic, it does not 
>> > need any record-time options.
>> > 
>> > This would work for multi-event sampling as well, if we do:
>> > 
>> >    perf record -a -e cycles -e branches sleep 1
>> > 
>> > then 'perf report stat' would output the same as:
>> > 
>> >  $ perf stat -e cycles -e branches -a sleep 1
>> > 
>> >  Performance counter stats for 'system wide':
>> > 
>> >         34,174,518      cycles                    [100.00%]
>> >          3,155,677      branches                                                    
>> > 
>> >        1.000802852 seconds time elapsed
>> > 
>> 
>> Yeah, it'd be good to have same output both for perf stat and perf 
>> report --stat (or stat if you want).  But I don't think it's 
>> possible to determine multiplexed counter values like perf stat does 
>> unless we use PERF_SAMPLE_READ for recoding.
>
> That's my point: is there any reason why we shouldn't turn on 
> PERF_SAMPLE_READ for these events, and read them at the beginning and 
> at the end of a sampling session?

But adding PERF_SAMPLE_READ to attr.sample_type will result in every
sample has read record in the output, right?

>
> ( some people might even want periodic samples emitted inbetween, to 
>   be able to see a time flow representation of samples, but that's for 
>   the future. )
>
>> > Another neat feature this kind of workflo enables is the integration 
>> > of --repeat to perf record, so something like:
>> > 
>> >     perf record --repeat 3 -a -e cycles -e branches sleep 1
>> > 
>> > would save 3 samples after each other, and would allow extraction of 
>> > the statistical stability of the measurement, and 'perf report stat' 
>> > would print the same result as a raw perf stat run would:
>> > 
>> >  $ perf stat --repeat 3 -e cycles -e branches -e instructions -a sleep 1
>> > 
>> >  Performance counter stats for 'system wide' (3 runs):
>> > 
>> >     28,975,150,642      cycles                     ( +-  0.43% ) [100.00%]
>> >     10,740,235,371      branches                                                      ( +-  0.47% ) [100.00%]
>> >     44,535,464,754      instructions              #    1.54  insns per cycle          ( +-  0.47% )
>> > 
>> >        1.005718027 seconds time elapsed                                          ( +-  0.43% )
>> 
>> Yeah, but it can be used only for a new forked workload.
>
> Well, it can be used for anything that perf record can do today, 
> except maybe the Ctrl-C method of measurement, right?

I'm not sure I understood you correctly.  How do you repeat if you
attach to an existing process (as it can be terminated in the middle)?

>
>> > Or something like that. At that point we share reporting between 
>> > perf stat and perf report, no special ad-hoc options are needed to 
>> > just measure and report timestamps, it would all be a 'natural' 
>> > side effect of having perf stat.
>> > 
>> > What do you think?
>> 
>> I think it'd be better if we can share code as much as possible.  
>> And it'd much better if we can forget about the difference in 
>> options. :)
>
> Agreed - see the --show-<xyz> pattern I suggested above.
>
> It could be different as well, sort-key alike:
>
>    --show +stat,-hist,+debug
>

See my comment above.

Thanks,
Namhyung

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

[Namhyung Kim]

On Mon, 2 Dec 2013 17:24:59 -0300, Arnaldo Carvalho de Melo wrote:
> Em Mon, Dec 02, 2013 at 05:36:20PM +0100, Ingo Molnar escreveu:
>> * Namhyung Kim <namhyung@kernel.org> wrote:
>> > 2013-12-02 (월), 13:57 +0100, Ingo Molnar:
>> > > So basically, in the end I think it should be possible to have the 
>> > > following behavior:
>
>> > >    perf record -a -e cycles sleep 1
>
>> > >    perf report stat              # Reports as if we ran: 'perf stat -a -e cycles sleep 1'
>> > >    perf report                   # Reports the usual histogram
>
>> > >    perf report --stat            # Reports the perf stat output and the histogram
>
>> > > or so.
>
>> > I don't think we need both of 'perf report stat' and 'perf report
>> > --stat'.  At least it looks somewhat confusing to users IMHO.
>  
>> Okay. Maybe the --stat option would be the more logical choice, 
>> because '--' options can be added arbitrarily, while it would be weird 
>> to add multiple subcommand options.
>  
>> So basically there would be two options:
>  
>>    --show-stat         [--no-show-stat]
>>    --show-histogram    [--no-show-histogram]
>  
>> Today --show-histogram is the only one enabled by default.
>  
>> Running:
>  
>>    perf report --no-show-histogram --show-stat
>
> Why not:
>
> perf stat -i perf.data
>
> and make it be an optional argument, so plain:
>
> perf stat -i
>
> would process perf.data, i.e. would get the samples, accrue the periods,
> calculate the time, etc and then present it as 'perf stat <some
> target>'.

Yeah, actually this came into my head too.  But how about just making
"perf stat" read from perf.data and print output - I mean without the -i
option like other commands do.  Currently perf stat doesn't allow no
argument given it won't confuse existing users.

It should produce same output as Ingo suggested with "perf report
--show-stat --no-show-histogram".

>
> Right now 'perf stat -i' i used for '--no-inherit', perhaps we can just
> have --no-inherit have no short option and grab -i to have the same
> meaning as in 'report', 'script', etc.

Agreed.  Maybe we could change it to plain --inherit.

Thanks,
Namhyung

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

[David Ahern]

On 12/2/13, 10:44 PM, Namhyung Kim wrote:
>> Right now 'perf stat -i' i used for '--no-inherit', perhaps we can just
>> have --no-inherit have no short option and grab -i to have the same
>> meaning as in 'report', 'script', etc.
>
> Agreed.  Maybe we could change it to plain --inherit.

yes: https://lkml.org/lkml/2013/11/19/330

David

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

[Ingo Molnar]

* David Ahern <dsahern@gmail.com> wrote:

> On 12/2/13, 10:44 PM, Namhyung Kim wrote:
> >>Right now 'perf stat -i' i used for '--no-inherit', perhaps we can just
> >>have --no-inherit have no short option and grab -i to have the same
> >>meaning as in 'report', 'script', etc.
> >
> >Agreed.  Maybe we could change it to plain --inherit.
> 
> yes: https://lkml.org/lkml/2013/11/19/330

agreed.

Thanks,

	Ingo

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

[Ingo Molnar]

* Arnaldo Carvalho de Melo <acme@ghostprotocols.net> wrote:

> Em Mon, Dec 02, 2013 at 05:36:20PM +0100, Ingo Molnar escreveu:
> > * Namhyung Kim <namhyung@kernel.org> wrote:
> > > 2013-12-02 (월), 13:57 +0100, Ingo Molnar:
> > > > So basically, in the end I think it should be possible to have the 
> > > > following behavior:
> 
> > > >    perf record -a -e cycles sleep 1
> 
> > > >    perf report stat              # Reports as if we ran: 'perf stat -a -e cycles sleep 1'
> > > >    perf report                   # Reports the usual histogram
> 
> > > >    perf report --stat            # Reports the perf stat output and the histogram
> 
> > > > or so.
> 
> > > I don't think we need both of 'perf report stat' and 'perf report
> > > --stat'.  At least it looks somewhat confusing to users IMHO.
>  
> > Okay. Maybe the --stat option would be the more logical choice, 
> > because '--' options can be added arbitrarily, while it would be weird 
> > to add multiple subcommand options.
>  
> > So basically there would be two options:
>  
> >    --show-stat         [--no-show-stat]
> >    --show-histogram    [--no-show-histogram]
>  
> > Today --show-histogram is the only one enabled by default.
>  
> > Running:
>  
> >    perf report --no-show-histogram --show-stat
> 
> Why not:
> 
> perf stat -i perf.data
> 
> and make it be an optional argument, so plain:
> 
> perf stat -i
> 
> would process perf.data, i.e. would get the samples, accrue the periods,
> calculate the time, etc and then present it as 'perf stat <some
> target>'.
> 
> Right now 'perf stat -i' i used for '--no-inherit', perhaps we can just
> have --no-inherit have no short option and grab -i to have the same
> meaning as in 'report', 'script', etc.

Sounds good to me! It's (much) better than complicating the perf 
report UI with non-histogram formatting. perf record would have to be 
enhanced to make sure all events are 'perf stat' extractable by 
default, but that's it I think.

The only downside is that I now cannot get Namhyung to implement this 
nice feature as a side effect of the perf report feature he wants ;-)

Thanks,

	Ingo