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

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

[Arnaldo Carvalho de Melo]

Em Mon, Dec 02, 2013 at 11:38:20PM +0900, Namhyung Kim escreveu:
> 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
 
Hey, longer and more descriptive names _when required_, in that case I
thought that even being longer --show-task-events would be better, but
here using --show-time-info the 'info' part looks superfluous, at least
to me, hence my suggestion/question :-)

<SNIP>

> > > +++ 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.

I have not delved into the code, it was just a first impression, lemme
do that now...
 
- Arnaldo

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

[David Ahern]

On 12/2/13, 12:23 PM, Arnaldo Carvalho de Melo wrote:
> Em Mon, Dec 02, 2013 at 11:38:20PM +0900, Namhyung Kim escreveu:
>> 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
>
> Hey, longer and more descriptive names _when required_, in that case I
> thought that even being longer --show-task-events would be better, but
> here using --show-time-info the 'info' part looks superfluous, at least
> to me, hence my suggestion/question :-)
>

I thought -t/--time is going to be used to specify a time interval? 
Collect data for N-seconds, analyze some middle M-seconds.

David

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

[Arnaldo Carvalho de Melo]

Em Mon, Dec 02, 2013 at 12:25:26PM -0700, David Ahern escreveu:
> On 12/2/13, 12:23 PM, Arnaldo Carvalho de Melo wrote:
> >Em Mon, Dec 02, 2013 at 11:38:20PM +0900, Namhyung Kim escreveu:
> >>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

> >Hey, longer and more descriptive names _when required_, in that case I
> >thought that even being longer --show-task-events would be better, but
> >here using --show-time-info the 'info' part looks superfluous, at least
> >to me, hence my suggestion/question :-)

> I thought -t/--time is going to be used to specify a time interval?
> Collect data for N-seconds, analyze some middle M-seconds.

Can you suggest a better name for the option being discussed?

Perhaps one of:

--show-event-time
--event-time

?

As a policy I think we should go on adding just long options and only
after there is a really strong case we should use a short option for
really, really popular options.

- Arnaldo

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

[David Ahern]

On 12/2/13, 12:38 PM, Arnaldo Carvalho de Melo wrote:
> Can you suggest a better name for the option being discussed?
>
> Perhaps one of:
>
> --show-event-time
> --event-time
>
> ?

Why not just --event-time?

Really should have dropped the 'show' from the recent perf-script change 
(just --task-events and --mmap-events).

>
> As a policy I think we should go on adding just long options and only
> after there is a really strong case we should use a short option for
> really, really popular options.

And adding options to .perfconfig. Need to use that more.

David

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

[Arnaldo Carvalho de Melo]

Em Mon, Dec 02, 2013 at 12:58:35PM -0700, David Ahern escreveu:
> On 12/2/13, 12:38 PM, Arnaldo Carvalho de Melo wrote:
> >Can you suggest a better name for the option being discussed?

> >Perhaps one of:

> >--show-event-time
> >--event-time

> >?
> 
> Why not just --event-time?

 
> Really should have dropped the 'show' from the recent perf-script
> change (just --task-events and --mmap-events).

Probably, yeah, Ingo made some point about using --show- for some reason,
Ingo?

One I can think of is that, in general, plain --feature can mean, at
least, one of --enable-feature and --show-feature, so perhaps that is
the point.

But then, perhaps that may be implied by the context, i.e.  when
recording, --feature means enable it, while when reporting, what we're
doing is basically _showing_ things, so --feature means just that.

- Arnaldo
 
> >
> >As a policy I think we should go on adding just long options and only
> >after there is a really strong case we should use a short option for
> >really, really popular options.
> 
> And adding options to .perfconfig. Need to use that more.
> 
> David

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

[David Ahern]

On 12/2/13, 1:17 PM, Arnaldo Carvalho de Melo wrote:
> Probably, yeah, Ingo made some point about using --show- for some reason,
> Ingo?
>
> One I can think of is that, in general, plain --feature can mean, at
> least, one of --enable-feature and --show-feature, so perhaps that is
> the point.
>
> But then, perhaps that may be implied by the context, i.e.  when
> recording, --feature means enable it, while when reporting, what we're
> doing is basically_showing_  things, so --feature means just that.

exactly. perf has just --call-graph for both record and report, not 
enable-call-graph and show-call-graph.

David

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

[Ingo Molnar]

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

> Em Mon, Dec 02, 2013 at 12:58:35PM -0700, David Ahern escreveu:
> > On 12/2/13, 12:38 PM, Arnaldo Carvalho de Melo wrote:
> > >Can you suggest a better name for the option being discussed?
> 
> > >Perhaps one of:
> 
> > >--show-event-time
> > >--event-time
> 
> > >?
> > 
> > Why not just --event-time?
> 
>  
> > Really should have dropped the 'show' from the recent perf-script
> > change (just --task-events and --mmap-events).
> 
> Probably, yeah, Ingo made some point about using --show- for some reason,
> Ingo?

So the reason for my suggestion was that I've noticed a proliferation 
of such flags in perf report. To reduce namespace pollution it's 
always good to bring a certain kind of hierarchy into command line 
options.

Options that work alike should spell alike. Users shouldn't be 
required to memorize every naming quirk of the various disjunct 
'display this extra data' options.

So if we expect more --show options in the future (and in particular 
if there are existing oddball options that could be changed to the 
--show-xyz pattern) then I'd suggest to do it unified. For example 
there's --show-nr-samples and --show-info already which follows this 
pattern.

This pattern would distinguish this option from the other perf report 
options, such as --vmlinux, --force, --sort, etc.

It might even make sense to unify it all into a single --show option. 
That would allow the following current mismash of options:

       --task-events --mmap-events --show-nr-samples --show-info

to be replaced by a much more obvious, much more coherent looking 
option sequence:

	--show task-events,mmap-events,nr-samples,info

an added bonus would be that '--show help' could be implemented as 
well, to list all displayable extra data.

(I'm not married to the specific naming, it could be something else as 
well, like --display or --report.)

Or something like that.

Thanks,

	Ingo

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

[Arnaldo Carvalho de Melo]

Em Wed, Dec 04, 2013 at 11:11:17AM +0100, Ingo Molnar escreveu:
> * Arnaldo Carvalho de Melo <acme@ghostprotocols.net> wrote:
> > Em Mon, Dec 02, 2013 at 12:58:35PM -0700, David Ahern escreveu:
> > > On 12/2/13, 12:38 PM, Arnaldo Carvalho de Melo wrote:
> > > Why not just --event-time?

> > > Really should have dropped the 'show' from the recent perf-script
> > > change (just --task-events and --mmap-events).

> > Probably, yeah, Ingo made some point about using --show- for some reason,
> > Ingo?
 
> So the reason for my suggestion was that I've noticed a proliferation 
> of such flags in perf report. To reduce namespace pollution it's 
> always good to bring a certain kind of hierarchy into command line 
> options.
 
> Options that work alike should spell alike. Users shouldn't be 
> required to memorize every naming quirk of the various disjunct 
> 'display this extra data' options.
 
> So if we expect more --show options in the future (and in particular 
> if there are existing oddball options that could be changed to the 
> --show-xyz pattern) then I'd suggest to do it unified. For example 
> there's --show-nr-samples and --show-info already which follows this 
> pattern.
 
> This pattern would distinguish this option from the other perf report 
> options, such as --vmlinux, --force, --sort, etc.
 
> It might even make sense to unify it all into a single --show option. 
> That would allow the following current mismash of options:
 
>        --task-events --mmap-events --show-nr-samples --show-info
 
> to be replaced by a much more obvious, much more coherent looking 
> option sequence:
 
> 	--show task-events,mmap-events,nr-samples,info

Excellent idea, agreed, we should probably try to implement this as a
generic facility to be used accross all the tools.

This, together with the other options processing code should be a
natural candidate for a tools/lib/opt/ directory, implemented in the way
we discussed: a .a for tools that want all the options processing, but
also as untangled as possible so that tools that want just specific bits
can chew them individually.

So, in summary, we _will_ be dropping the 'show-' prefix from all those
options, and those options as well, that then just become a single (top
level) option with entries in a bitmask that are set via some OPT_
callback that receives some struct with a string table and has a bitmask
that it will set.

> an added bonus would be that '--show help' could be implemented as 
> well, to list all displayable extra data.

Right, the string table I mentioned in fact should be a struct table
that in turn has two strings, the --show bitname and bithelp.
 
> (I'm not married to the specific naming, it could be something else as 
> well, like --display or --report.)

I think 'show' is ok, 4 letters, shorter than 'display', already used in
several places.

- Arnaldo

[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 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: [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 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