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

[Jiri Olsa]

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