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

[Arnaldo Carvalho de Melo <acme@ghostprotocols.net>]

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