[PATCH] perf evsel: Return exact sub event which failed with EPERM for wildcards

[PATCH] perf evsel: Return exact sub event which failed with EPERM for wildcards

[Jin Yao]

The kernel has a special check for irq_vectors trace event.

TRACE_EVENT_PERF_PERM(irq_work_exit,
	is_sampling_event(p_event) ? -EPERM : 0);

The perf-record is failed for irq_vectors event if using a wildcard.

root@skl:/tmp# perf record -a -e irq_vectors:* sleep 2
Error:
You may not have permission to collect system-wide stats.

Consider tweaking /proc/sys/kernel/perf_event_paranoid,
which controls use of the performance events system by
unprivileged users (without CAP_SYS_ADMIN).

The current value is 2:

  -1: Allow use of (almost) all events by all users
>= 0: Disallow raw tracepoint access by users without CAP_IOC_LOCK
>= 1: Disallow CPU event access by users without CAP_SYS_ADMIN
>= 2: Disallow kernel profiling by users without CAP_SYS_ADMIN

To make this setting permanent, edit /etc/sysctl.conf too, e.g.:

        kernel.perf_event_paranoid = -1

This patch prints out the exact sub event that failed with EPERM
for wildcards to help user understanding easily.

For example,

root@skl:/tmp# perf record -a -e irq_vectors:* sleep 2
Error:
No permission to enable irq_vectors:irq_work_exit event.

You may not have permission to collect system-wide stats.
......

Signed-off-by: Jin Yao <yao.jin@linux.intel.com>
---
 tools/perf/util/evsel.c | 8 +++++++-
 1 file changed, 7 insertions(+), 1 deletion(-)

diff --git a/tools/perf/util/evsel.c b/tools/perf/util/evsel.c
index 9dc7e2d..8f5d86b 100644
--- a/tools/perf/util/evsel.c
+++ b/tools/perf/util/evsel.c
@@ -2457,11 +2457,17 @@ int perf_evsel__open_strerror(struct perf_evsel *evsel, struct target *target,
 			      int err, char *msg, size_t size)
 {
 	char sbuf[STRERR_BUFSIZE];
+	int printed = 0;
 
 	switch (err) {
 	case EPERM:
 	case EACCES:
-		return scnprintf(msg, size,
+		if (err == EPERM)
+			printed = scnprintf(msg, size,
+				"No permission to enable %s event.\n\n",
+				perf_evsel__name(evsel));
+
+		return scnprintf(msg + printed, size - printed,
 		 "You may not have permission to collect %sstats.\n\n"
 		 "Consider tweaking /proc/sys/kernel/perf_event_paranoid,\n"
 		 "which controls use of the performance events system by\n"
-- 
2.7.4

[tip:perf/core] perf evsel: Return exact sub event which failed with EPERM for wildcards

[tip-bot for Jin Yao]

Commit-ID:  32ccb130f5325abc81b32b1a538390f46e4860f6
Gitweb:     http://git.kernel.org/tip/32ccb130f5325abc81b32b1a538390f46e4860f6
Author:     Jin Yao <yao.jin@linux.intel.com>
AuthorDate: Fri, 7 Apr 2017 20:08:52 +0800
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Tue, 11 Apr 2017 08:45:10 -0300

perf evsel: Return exact sub event which failed with EPERM for wildcards

The kernel has a special check for a specific irq_vectors trace event.

TRACE_EVENT_PERF_PERM(irq_work_exit,
	is_sampling_event(p_event) ? -EPERM : 0);

The perf-record fails for this irq_vectors event when it is present,
like when using a wildcard:

  root@skl:/tmp# perf record -a -e irq_vectors:* sleep 2
  Error:
  You may not have permission to collect system-wide stats.

  Consider tweaking /proc/sys/kernel/perf_event_paranoid,
  which controls use of the performance events system by
  unprivileged users (without CAP_SYS_ADMIN).

  The current value is 2:

    -1: Allow use of (almost) all events by all users
  >= 0: Disallow raw tracepoint access by users without CAP_IOC_LOCK
  >= 1: Disallow CPU event access by users without CAP_SYS_ADMIN
  >= 2: Disallow kernel profiling by users without CAP_SYS_ADMIN

  To make this setting permanent, edit /etc/sysctl.conf too, e.g.:

        kernel.perf_event_paranoid = -1

This patch prints out the exact sub event that failed with EPERM for
wildcards to help in understanding what went wrong when this event is
present:

After the patch:

  root@skl:/tmp# perf record -a -e irq_vectors:* sleep 2
  Error:
  No permission to enable irq_vectors:irq_work_exit event.

  You may not have permission to collect system-wide stats.
  ......

Committer notes:

So we have a lot of irq_vectors events:

  [root@jouet ~]# perf list irq_vectors:*

  List of pre-defined events (to be used in -e):

    irq_vectors:call_function_entry                    [Tracepoint event]
    irq_vectors:call_function_exit                     [Tracepoint event]
    irq_vectors:call_function_single_entry             [Tracepoint event]
    irq_vectors:call_function_single_exit              [Tracepoint event]
    irq_vectors:deferred_error_apic_entry              [Tracepoint event]
    irq_vectors:deferred_error_apic_exit               [Tracepoint event]
    irq_vectors:error_apic_entry                       [Tracepoint event]
    irq_vectors:error_apic_exit                        [Tracepoint event]
    irq_vectors:irq_work_entry                         [Tracepoint event]
    irq_vectors:irq_work_exit                          [Tracepoint event]
    irq_vectors:local_timer_entry                      [Tracepoint event]
    irq_vectors:local_timer_exit                       [Tracepoint event]
    irq_vectors:reschedule_entry                       [Tracepoint event]
    irq_vectors:reschedule_exit                        [Tracepoint event]
    irq_vectors:spurious_apic_entry                    [Tracepoint event]
    irq_vectors:spurious_apic_exit                     [Tracepoint event]
    irq_vectors:thermal_apic_entry                     [Tracepoint event]
    irq_vectors:thermal_apic_exit                      [Tracepoint event]
    irq_vectors:threshold_apic_entry                   [Tracepoint event]
    irq_vectors:threshold_apic_exit                    [Tracepoint event]
    irq_vectors:x86_platform_ipi_entry                 [Tracepoint event]
    irq_vectors:x86_platform_ipi_exit                  [Tracepoint event]
  #

And some may be sampled:

  [root@jouet ~]# perf record -e irq_vectors:local* sleep 20s
  [ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 0.020 MB perf.data (2 samples) ]
  [root@jouet ~]# perf report -D | egrep 'stats:|events:'
  Aggregated stats:
             TOTAL events:        155
              MMAP events:        144
              COMM events:          2
              EXIT events:          1
            SAMPLE events:          2
             MMAP2 events:          4
    FINISHED_ROUND events:          1
         TIME_CONV events:          1
  irq_vectors:local_timer_entry stats:
             TOTAL events:          1
            SAMPLE events:          1
  irq_vectors:local_timer_exit stats:
             TOTAL events:          1
            SAMPLE events:          1
  [root@jouet ~]#

But, as shown in the tracepoint definition at the start of this message,
some, like "irq_vectors:irq_work_exit", may not be sampled, just counted,
i.e. if we try to sample, as when using 'perf record', we get an error:

  [root@jouet ~]# perf record -e irq_vectors:irq_work_exit
  Error:
  You may not have permission to collect system-wide stats.

  Consider tweaking /proc/sys/kernel/perf_event_paranoid,
<SNIP>

The error message is misleading, this patch will help in pointing out
what is the event causing such an error, but the error message needs
improvement, i.e. we need to figure out a way to check if a tracepoint
is counting only, like this one, when all we can do is to count it with
'perf stat', at most printing the delta using interval printing, as in:

   [root@jouet ~]# perf stat -I 5000 -e irq_vectors:irq_work_*
  #           time             counts unit events
       5.000168871                  0      irq_vectors:irq_work_entry
       5.000168871                  0      irq_vectors:irq_work_exit
      10.000676730                  0      irq_vectors:irq_work_entry
      10.000676730                  0      irq_vectors:irq_work_exit
      15.001122415                  0      irq_vectors:irq_work_entry
      15.001122415                  0      irq_vectors:irq_work_exit
      20.001298051                  0      irq_vectors:irq_work_entry
      20.001298051                  0      irq_vectors:irq_work_exit
      25.001485020                  1      irq_vectors:irq_work_entry
      25.001485020                  1      irq_vectors:irq_work_exit
      30.001658706                  0      irq_vectors:irq_work_entry
      30.001658706                  0      irq_vectors:irq_work_exit
  ^C    32.045711878                  0      irq_vectors:irq_work_entry
      32.045711878                  0      irq_vectors:irq_work_exit

  [root@jouet ~]#

But at least, when we use a wildcard, this patch helps a bit.

Signed-off-by: Yao Jin <yao.jin@linux.intel.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Andi Kleen <ak@linux.intel.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Kan Liang <kan.liang@intel.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/1491566932-503-1-git-send-email-yao.jin@linux.intel.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/util/evsel.c | 8 +++++++-
 1 file changed, 7 insertions(+), 1 deletion(-)

diff --git a/tools/perf/util/evsel.c b/tools/perf/util/evsel.c
index 9dc7e2d..8f5d86b 100644
--- a/tools/perf/util/evsel.c
+++ b/tools/perf/util/evsel.c
@@ -2457,11 +2457,17 @@ int perf_evsel__open_strerror(struct perf_evsel *evsel, struct target *target,
 			      int err, char *msg, size_t size)
 {
 	char sbuf[STRERR_BUFSIZE];
+	int printed = 0;
 
 	switch (err) {
 	case EPERM:
 	case EACCES:
-		return scnprintf(msg, size,
+		if (err == EPERM)
+			printed = scnprintf(msg, size,
+				"No permission to enable %s event.\n\n",
+				perf_evsel__name(evsel));
+
+		return scnprintf(msg + printed, size - printed,
 		 "You may not have permission to collect %sstats.\n\n"
 		 "Consider tweaking /proc/sys/kernel/perf_event_paranoid,\n"
 		 "which controls use of the performance events system by\n"