Re: pmu::read() called erroneously in v4.13-rc{3,4}

[Mark Rutland]

On Thu, Aug 10, 2017 at 12:03:55PM -0700, Andi Kleen wrote:
> > [  230.909172] ------------[ cut here ]------------
> > [  230.913796] WARNING: CPU: 1 PID: 3637 at arch/x86/events/core.c:75 x86_perf_event_update+0xbd/0xd0
> > [  230.922739] Modules linked in:
> > [  230.925798] CPU: 1 PID: 3637 Comm: wrong-counter Tainted: G        W       4.13.0-rc4+ #230
> > [  230.934132] Hardware name: LENOVO 7484A3G/LENOVO, BIOS 5CKT54AUS 09/07/2009
> > [  230.941080] task: ffff9ad5b0232640 task.stack: ffffb2f001aac000
> > [  230.946989] RIP: 0010:x86_perf_event_update+0xbd/0xd0
> > [  230.952038] RSP: 0018:ffffb2f001aaf978 EFLAGS: 00010282
> > [  230.957257] RAX: 0000000000000020 RBX: ffffb2f001aafa48 RCX: 0000000000000000
> > [  230.964378] RDX: 0000000000000001 RSI: ffff9ad5a9d33400 RDI: ffff9ad5a9d32800
> > [  230.971498] RBP: ffffb2f001aaf9a0 R08: 0000000000000000 R09: 0000000000000028
> > [  230.978622] R10: ffff9ad5b0232640 R11: ffff9ad5a9cd4840 R12: 0000000000000002
> > [  230.985745] R13: 0000000000000018 R14: 0000000000000001 R15: ffff9ad5a9d32800
> > [  230.992866] FS:  0000000000000000(0000) GS:ffff9ad5bec80000(0000) knlGS:0000000000000000
> > [  231.000939] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [  231.006680] CR2: 00007f26cba069d0 CR3: 0000000085a0a000 CR4: 00000000000406e0
> > [  231.013802] Call Trace:
> > [  231.016254]  x86_pmu_read+0x9/0x10
> > [  231.019656]  perf_output_read+0x19f/0x410
> > [  231.023665]  ? __alloc_pages_nodemask+0xe8/0x1f0
> > [  231.028274]  perf_event_read_event+0xd2/0x110
> > [  231.032628]  ? x86_pmu_del+0x3e/0x130
> > [  231.036290]  ? __intel_pmu_enable_all.isra.12+0x27/0x90
> > [  231.041512]  ? intel_pmu_enable_all+0xb/0x10
> > [  231.045779]  ? x86_pmu_enable+0x25e/0x2f0
> > [  231.049787]  ? group_sched_out+0x8c/0xd0
> > [  231.053708]  ? perf_pmu_enable+0x22/0x30
> > [  231.057629]  ? update_group_times+0x13/0x40
> > [  231.061812]  ? list_del_event+0x66/0xc0
> > [  231.065647]  perf_event_exit_task+0x2fa/0x380
> 
> I suspect the problem is that exit schedules before it calls
> perf_event_exit_task. 

I'm not sure I follow; could you elaborate?

> We could just move it up to the beginning of exit. Untested
> patch here. Does that help?

I see the same behaviour with the patch below applied.

Thanks,
Mark.

> diff --git a/kernel/exit.c b/kernel/exit.c
> index 516acdb0e0ec..9a6f5f299588 100644
> --- a/kernel/exit.c
> +++ b/kernel/exit.c
> @@ -779,6 +779,14 @@ void __noreturn do_exit(long code)
>  	int group_dead;
>  	TASKS_RCU(int tasks_rcu_i);
>  
> +	/*
> +	 * Flush inherited counters to the parent - before the parent
> +	 * gets woken up by child-exit notifications.
> +	 *
> +	 * because of cgroup mode, must be called before cgroup_exit()
> +	 */
> +	perf_event_exit_task(tsk);
> +
>  	profile_task_exit(tsk);
>  	kcov_task_exit(tsk);
>  
> @@ -878,14 +886,6 @@ void __noreturn do_exit(long code)
>  	exit_task_work(tsk);
>  	exit_thread(tsk);
>  
> -	/*
> -	 * Flush inherited counters to the parent - before the parent
> -	 * gets woken up by child-exit notifications.
> -	 *
> -	 * because of cgroup mode, must be called before cgroup_exit()
> -	 */
> -	perf_event_exit_task(tsk);
> -
>  	sched_autogroup_exit_task(tsk);
>  	cgroup_exit(tsk);
>  
>