perf tools: Assorted fixes

Adding check_2 function to check 2 different files, the check function stays to check files that differs only in the prefix path.

The perf stat fallback for EACCES error sets exclude_kernel for event and repeats the open. In addition, it also changes the name of the event to reflect that change by adding the 'u' modifier.

But it does not take into account the '/' separator, so the event name can end up mangled, like:
(note the '/:' characters)

  $ perf stat -e cpu/cpu-cycles/ kill
  ...
             386,832      cpu/cpu-cycles/:u

Adding the code to check on the '/' separatos and set following event name:

  $ perf stat -e cpu/cpu-cycles/ kill
  ...
             388,548      cpu/cpu-cycles/u

Currently all the event parsing fails end up in the event_pmu rule, and display misleading help like:

  $ perf stat -e inst kill
  event syntax error: 'inst'
                       \___ Cannot find PMU `inst'. Missing kernel support?
  ...

The reason is that the event_pmu is too strong and match also single string. Changing it to force the '/' separators to be part of the rule, and getting the proper error now:

  $ perf stat -e inst kill
  event syntax error: 'inst'
                       \___ parser error
  Run 'perf list' for a list of valid events

...

Link http://lkml.kernel.org/n/[email protected] open here

Signed-off-by Jiri Olsa <[email protected]>

---
 tools/perf/util/parse-events.y | 8 ++++----
 1 file changed, 4 insertions(+), 4 deletions(-)

tools/perf/util/parse-events.y +4 -4

index 7afeb80cc39e..d14464c42714 100644
@@ -224,15 +224,15 @@ event_def: event_pmu |
 	   event_bpf_file
 
 event_pmu:
-PE_NAME opt_event_config
+PE_NAME '/' event_config '/'
 {
 	struct list_head *list, *orig_terms, *terms;
 
-	if (parse_events_copy_term_list($2, &orig_terms))
+	if (parse_events_copy_term_list($3, &orig_terms))
 		YYABORT;
 
 	ALLOC_LIST(list);
-	if (parse_events_add_pmu(_parse_state, list, $1, $2, false)) {
+	if (parse_events_add_pmu(_parse_state, list, $1, $3, false)) {
 		struct perf_pmu *pmu = NULL;
 		int ok = 0;
 		char *pattern;

@@ -262,7 +262,7 @@ PE_NAME opt_event_config
 		if (!ok)
 			YYABORT;
 	}
-	parse_events_terms__delete($2);
+	parse_events_terms__delete($3);
 	parse_events_terms__delete(orig_terms);
 	$$ = list;
 }

Signature · 1 line

2.13.6

Em Mon, Apr 23, 2018 at 11:08:18AM +0200, Jiri Olsa escreveu:

Quoted 14 lines

Currently all the event parsing fails end up in the event_pmu rule, and display misleading help like:

  $ perf stat -e inst kill
  event syntax error: 'inst'
                       \___ Cannot find PMU `inst'. Missing kernel support?
  ...

The reason is that the event_pmu is too strong and match also single string. Changing it to force the '/' separators to be part of the rule, and getting the proper error now:

Quoted 4 lines

  $ perf stat -e inst kill
  event syntax error: 'inst'
                       \___ parser error
  Run 'perf list' for a list of valid events

I added a Reported-by: Ingo after checking that that was the case in tha private conversation we had, but I think this has to be further
improved: do we have enough context at this point to change that into:

   $ perf stat -e inst kill
   event syntax error: 'inst'
                        \___ unknown event
   Run 'perf list' for a list of valid events

Instead of the generic "parser error"? That "list of valid events" helps tho, but if we're going to say something at that \___ MSG part...

.. and other related fields that do not need to be enabled for events that have sampling leader.

It fixes the perf top usage Ingo reported broken:

  # perf top -e '{cycles,msr/aperf/}:S'

The msr/aperf/ is configured for write_back sampling, which is not allowed by msr pmu, so it fails to create the event.

Adjusting related attr test.

It would be better if perf stat would display elapsed time with a precision adjusted to stddev, it should display at most 2 more significant digits than the stddev inaccuracy.

I.e. in the above case 0.39% is 0.109, so we only have accuracy for 1 digit, and so we should only display 3:

27.988 seconds time elapsed ( +- 0.39% )

Small output style nit - I think it would be nice if with --repeat the stddev was also displayed in absolute values, besides percentage:

      27.988 +- 0.109 seconds time elapsed   ( +- 0.39% )

Ingo suggested to display elapsed time for multirun workload (perf stat -e) with precision based on the precision of the standard deviation.

In his own words:

Adding --table option to display time for each
run (-r option), like:

Em Mon, Apr 23, 2018 at 11:08:21AM +0200, Jiri Olsa escreveu:

Quoted 2 lines

Adding --table option to display time for each
run (-r option), like:

You forgot to add this to 'perf stat's man page, I'm doing it this time,

Adding the support to read rusage data once the
workload is finished and display the system/user
time values:

  $ perf stat --null ./perf bench sched pipe
  ...

   Performance counter stats for './perf bench sched pipe':

       5.342599256 seconds time elapsed

       2.544434000 seconds user
       4.549691000 seconds sys

It works only in non -r mode.

Suggested-by Ingo Molnar <[email protected]>

Link http://lkml.kernel.org/n/[email protected] open here

Signed-off-by Jiri Olsa <[email protected]>

---
 tools/perf/builtin-stat.c | 28 +++++++++++++++++++++++++++-
 1 file changed, 27 insertions(+), 1 deletion(-)

tools/perf/builtin-stat.c +27 -1

index 2137c7d11767..9c987617c8e7 100644
@@ -80,6 +80,9 @@
 #include <sys/stat.h>
 #include <sys/wait.h>
 #include <unistd.h>
+#include <sys/time.h>
+#include <sys/resource.h>
+#include <sys/wait.h>
 
 #include "sane_ctype.h"
 

@@ -174,6 +177,8 @@ static const char		*output_name;
 static int			output_fd;
 static int			print_free_counters_hint;
 static u64			*walltime_run;
+static bool			ru_display			= false;
+static struct rusage		ru_data;
 
 struct perf_stat {
 	bool			 record;

@@ -725,7 +730,7 @@ static int __run_perf_stat(int argc, const char **argv, int run_idx)
 					break;
 			}
 		}
-		waitpid(child_pid, &status, 0);
+		wait4(child_pid, &status, 0, &ru_data);
 
 		if (workload_exec_errno) {
 			const char *emsg = str_error_r(workload_exec_errno, msg, sizeof(msg));

@@ -1773,6 +1778,11 @@ static void print_table(FILE *output, int precision, double avg)
 	fprintf(output, "\n%*s# Final result:\n", indent, "");
 }
 
+static double timeval2double(struct timeval *t)
+{
+	return t->tv_sec + (double) t->tv_usec/USEC_PER_SEC;
+}
+
 static void print_footer(void)
 {
 	double avg = avg_stats(&walltime_nsecs_stats) / NSEC_PER_SEC;

@@ -1784,6 +1794,15 @@ static void print_footer(void)
 
 	if (run_count == 1) {
 		fprintf(output, " %17.9f seconds time elapsed", avg);
+
+		if (ru_display) {
+			double utime = timeval2double(&ru_data.ru_utime);
+			double stime = timeval2double(&ru_data.ru_stime);
+
+			fprintf(output, "\n\n");
+			fprintf(output, " %17.9f seconds user\n", utime);
+			fprintf(output, " %17.9f seconds sys\n", stime);
+		}
 	} else {
 		double sd = stddev_stats(&walltime_nsecs_stats) / NSEC_PER_SEC;
 		/*

@@ -2869,6 +2888,13 @@ int cmd_stat(int argc, const char **argv)
 		goto out;
 	}
 
+	/*
+	 * Display user/system times only for single
+	 * run and when there's specified tracee.
+	 */
+	if ((run_count == 1) && target__none(&target))
+		ru_display = true;
+
 	if (output_fd < 0) {
 		fprintf(stderr, "argument to --log-fd must be a > 0\n");
 		parse_options_usage(stat_usage, stat_options, "log-fd", 0);

Signature · 1 line

2.13.6

Em Mon, Apr 23, 2018 at 11:08:23AM +0200, Jiri Olsa escreveu:

Quoted 9 lines

Adding the support to read rusage data once the
workload is finished and display the system/user
time values:

  $ perf stat --null ./perf bench sched pipe
  ...

Performance counter stats for './perf bench sched pipe':

Quoted 4 lines

       5.342599256 seconds time elapsed

       2.544434000 seconds user
       4.549691000 seconds sys

Please write a setence or two explaining the above three timings, do it nicely so that we can add it to the man page and avoid people scratching heads :-)

All the other patches were applied, some to perf/urgent (fixes) the remaining ones, new features, added to perf/core, up to Ingo to decide where to merge when I get to ask him to pull.

- Arnaldo

Quoted 85 lines

It works only in non -r mode.

Suggested-by Ingo Molnar <[email protected]>

Link http://lkml.kernel.org/n/[email protected] open here

Signed-off-by Jiri Olsa <[email protected]>

---
 tools/perf/builtin-stat.c | 28 +++++++++++++++++++++++++++-
 1 file changed, 27 insertions(+), 1 deletion(-)

tools/perf/builtin-stat.c +27 -1

index 2137c7d11767..9c987617c8e7 100644
@@ -80,6 +80,9 @@
 #include <sys/stat.h>
 #include <sys/wait.h>
 #include <unistd.h>
+#include <sys/time.h>
+#include <sys/resource.h>
+#include <sys/wait.h>
 
 #include "sane_ctype.h"
 

@@ -174,6 +177,8 @@ static const char		*output_name;
 static int			output_fd;
 static int			print_free_counters_hint;
 static u64			*walltime_run;
+static bool			ru_display			= false;
+static struct rusage		ru_data;
 
 struct perf_stat {
 	bool			 record;

@@ -725,7 +730,7 @@ static int __run_perf_stat(int argc, const char **argv, int run_idx)
 					break;
 			}
 		}
-		waitpid(child_pid, &status, 0);
+		wait4(child_pid, &status, 0, &ru_data);
 
 		if (workload_exec_errno) {
 			const char *emsg = str_error_r(workload_exec_errno, msg, sizeof(msg));

@@ -1773,6 +1778,11 @@ static void print_table(FILE *output, int precision, double avg)
 	fprintf(output, "\n%*s# Final result:\n", indent, "");
 }
 
+static double timeval2double(struct timeval *t)
+{
+	return t->tv_sec + (double) t->tv_usec/USEC_PER_SEC;
+}
+
 static void print_footer(void)
 {
 	double avg = avg_stats(&walltime_nsecs_stats) / NSEC_PER_SEC;

@@ -1784,6 +1794,15 @@ static void print_footer(void)
 
 	if (run_count == 1) {
 		fprintf(output, " %17.9f seconds time elapsed", avg);
+
+		if (ru_display) {
+			double utime = timeval2double(&ru_data.ru_utime);
+			double stime = timeval2double(&ru_data.ru_stime);
+
+			fprintf(output, "\n\n");
+			fprintf(output, " %17.9f seconds user\n", utime);
+			fprintf(output, " %17.9f seconds sys\n", stime);
+		}
 	} else {
 		double sd = stddev_stats(&walltime_nsecs_stats) / NSEC_PER_SEC;
 		/*

@@ -2869,6 +2888,13 @@ int cmd_stat(int argc, const char **argv)
 		goto out;
 	}
 
+	/*
+	 * Display user/system times only for single
+	 * run and when there's specified tracee.
+	 */
+	if ((run_count == 1) && target__none(&target))
+		ru_display = true;
+
 	if (output_fd < 0) {
 		fprintf(stderr, "argument to --log-fd must be a > 0\n");
 		parse_options_usage(stat_usage, stat_options, "log-fd", 0);

Signature · 1 line

2.13.6

hi,
sending assorted general fixes that queued
up in my other branches.

Arnaldo,
I added wait4 call in the last patch and am wondering if it will pass your all-distros-docker test ;-) If not I'll need to put some build detection code.