[patch] perf wrong enabled time after attach/enable/enable

From: Vince Weaver
Date: Tue Jul 25 2017 - 21:48:15 EST


Hello

It took a long time to track down this bug. This causes a failure in the
PAPI regression tests.

The problem happens with the following:
fork a child, put it to sleep with SIGSTOP
perf_event_open(), attaching to the pid of the child
ENABLE/DISABLE/ENABLE/DISABLE/ENABLE
read the results with the enabled/running multiplexing fields

Your "enabled" time will be a huge negative number, which will confuse any
code depening on it (especially the rdpmc scaling code).

>From what I can tell, when you DISABLE an event that's in a
PERF_EVENT_STATE_INACTIVE state, currently it exits early without
updating event->tstamp_stopped. So later when calculating the
enabled time it is wrong and you get the negative number.

The following quick hack fixes things, it just abuses the existing code
that was there to handle a similar case when a filter failed. The proper
fix might be to just put the event->tstamp_stopped update before the
early out code, but the commit log for the change that introduced that
makes it sound a bit scary.

Anyway a reproducible test case for this is in my pref_event_tests tree,
the "tests/rdpmc/rdpmc_attach_multi_enable" test.

Vince

diff --git a/kernel/events/core.c b/kernel/events/core.c
index 426c2ffba16d..18eadc3b37d5 100644
--- a/kernel/events/core.c
+++ b/kernel/events/core.c
@@ -1812,8 +1812,7 @@ event_sched_out(struct perf_event *event,
* maintained, otherwise bogus information is return
* via read() for time_enabled, time_running:
*/
- if (event->state == PERF_EVENT_STATE_INACTIVE &&
- !event_filter_match(event)) {
+ if (event->state == PERF_EVENT_STATE_INACTIVE) {
delta = tstamp - event->tstamp_stopped;
event->tstamp_running += delta;
event->tstamp_stopped = tstamp;