linux-kernel - Re: perf: wrong event->count report (Was: perf basic-test-aarch64 failures)

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <20160217093539.GC10042@krava.brq.redhat.com>
Date:	Wed, 17 Feb 2016 10:35:39 +0100
From:	Jiri Olsa <jolsa@...hat.com>
To:	Oleg Nesterov <oleg@...hat.com>
Cc:	Pratyush Anand <panand@...hat.com>,
	Peter Zijlstra <peterz@...radead.org>,
	Jeff Bastian <jbastian@...hat.com>,
	Michael Petlan <mpetlan@...hat.com>,
	linux-kernel@...r.kernel.org, arm-devel@...hat.com
Subject: Re: perf: wrong event->count report (Was: perf basic-test-aarch64
 failures)

On Wed, Feb 17, 2016 at 04:34:16AM +0100, Oleg Nesterov wrote:
> Finally I reproduced... let me add CC's and reply to initial message. This has
> nothing to do with arm/uprobes.
> 
> I simply can't understand how perf calculates ->total_time_enabled/running.
> At all. But the problem is that
> 
> 	1. perf_event_enable_on_exec() does enable first, then event_sched_in().
> 
> 	   After that tstamp_enabled < tstamp_running
> 
> 	2. This means that after the next update_event_times()
>            total_time_running < total_time_enabled
> 
>            again, I fail to understand these calculations, but this is what
>            perf_event_read_value() reports to user-space.
> 
> 	3. /usr/bin/perf calls perf_counts_values__scale() which does
> 
> 		else if (count->run < count->ena) {
> 			scaled = 1;
> 			count->val = (u64)((double) count->val * count->ena / count->run + 0.5);
> 		}
> 
> 	   and this is why you see the wrong number. count->val was correct but
> 	   wrongly updated because  total_time_running < total_time_enabled.
> 
> I leave this to Peter and Jiri ;)

I did not notice the ther conversation wasn't public, reposting ;-)

jirka

---
ouch, I tested with fedora kernel.. I can reproduce with 4.5

Pratyush bisected this into following commit:
[3e349507d12de93b08b0aa814fc2aa0dee91c5ba] perf: Fix perf_enable_on_exec() event scheduling

it seems the commit above introduced unwanted difference between
counter's enabled and running times.. I'm checking on that ;-)

as a workaround you could use --no-scale option to disable
scaling:

  # perf stat --no-scale -x';' -e 'probe_exact:*' ./exact_counts
  65535;;probe_exact:f_65535x;0;100.00
  997;;probe_exact:f_997x;0;100.00
  103;;probe_exact:f_103x;0;100.00
  3;;probe_exact:f_3x;0;100.00
  2;;probe_exact:f_2x;0;100.00
  1;;probe_exact:f_1x;0;100.00