Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751646AbdGZBr5 (ORCPT ); Tue, 25 Jul 2017 21:47:57 -0400 Received: from mail-io0-f196.google.com ([209.85.223.196]:36571 "EHLO mail-io0-f196.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751460AbdGZBrz (ORCPT ); Tue, 25 Jul 2017 21:47:55 -0400 From: Vince Weaver X-Google-Original-From: Vince Weaver Date: Tue, 25 Jul 2017 21:47:52 -0400 (EDT) X-X-Sender: vince@macbook-air To: linux-kernel@vger.kernel.org cc: Peter Zijlstra , Ingo Molnar , Arnaldo Carvalho de Melo , Stephane Eranian Subject: [patch] perf wrong enabled time after attach/enable/enable Message-ID: User-Agent: Alpine 2.20 (DEB 67 2015-01-07) MIME-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 1750 Lines: 44 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;