WARNING: at arch/x86/kernel/cpu/perf_event.c:989

WARNING: at arch/x86/kernel/cpu/perf_event.c:989

[Markus Trippelsdorf]

The following warning is easily reproducible after todays
'perf-urgent-for-mingo' merge by just running "perf top":

------------[ cut here ]------------
WARNING: at arch/x86/kernel/cpu/perf_event.c:989 x86_pmu_start+0xa5/0x100()
Hardware name: System Product Name
Pid: 0, comm: swapper/2 Not tainted 3.3.0-rc2-00068-g24b36da-dirty #22
Call Trace:
 <IRQ>  [<ffffffff81054ba0>] ? warn_slowpath_common+0x60/0xa0
 [<ffffffff8103e1a5>] ? x86_pmu_start+0xa5/0x100
 [<ffffffff8109f062>] ? perf_adjust_freq_unthr_context.part.82+0xe2/0x140
 [<ffffffff8109f260>] ? perf_event_task_tick+0x1a0/0x280
 [<ffffffff81078be3>] ? scheduler_tick+0xc3/0x140
 [<ffffffff810615b5>] ? update_process_times+0x55/0x80
 [<ffffffff8108904d>] ? tick_sched_timer+0x4d/0xa0
 [<ffffffff81072d1b>] ? __run_hrtimer.isra.32+0x3b/0xc0
 [<ffffffff810735e5>] ? hrtimer_interrupt+0xc5/0x1e0
 [<ffffffff81045de3>] ? smp_apic_timer_interrupt+0x63/0xa0
 [<ffffffff8147768b>] ? apic_timer_interrupt+0x6b/0x70
 <EOI>  [<ffffffff81039100>] ? default_idle+0x20/0x40
 [<ffffffff81039172>] ? amd_e400_idle+0x52/0x100
 [<ffffffff81030156>] ? cpu_idle+0xb6/0xe0
---[ end trace 7dc3992f562261b6 ]---


-- 
Markus

Re: WARNING: at arch/x86/kernel/cpu/perf_event.c:989

[Markus Trippelsdorf]

On 2012.02.02 at 22:17 +0100, Markus Trippelsdorf wrote:
> The following warning is easily reproducible after todays
> 'perf-urgent-for-mingo' merge by just running "perf top":
> 
> ------------[ cut here ]------------
> WARNING: at arch/x86/kernel/cpu/perf_event.c:989 x86_pmu_start+0xa5/0x100()
> Hardware name: System Product Name
> Pid: 0, comm: swapper/2 Not tainted 3.3.0-rc2-00068-g24b36da-dirty #22
> Call Trace:
>  <IRQ>  [<ffffffff81054ba0>] ? warn_slowpath_common+0x60/0xa0
>  [<ffffffff8103e1a5>] ? x86_pmu_start+0xa5/0x100
>  [<ffffffff8109f062>] ? perf_adjust_freq_unthr_context.part.82+0xe2/0x140
>  [<ffffffff8109f260>] ? perf_event_task_tick+0x1a0/0x280
>  [<ffffffff81078be3>] ? scheduler_tick+0xc3/0x140
>  [<ffffffff810615b5>] ? update_process_times+0x55/0x80
>  [<ffffffff8108904d>] ? tick_sched_timer+0x4d/0xa0
>  [<ffffffff81072d1b>] ? __run_hrtimer.isra.32+0x3b/0xc0
>  [<ffffffff810735e5>] ? hrtimer_interrupt+0xc5/0x1e0
>  [<ffffffff81045de3>] ? smp_apic_timer_interrupt+0x63/0xa0
>  [<ffffffff8147768b>] ? apic_timer_interrupt+0x6b/0x70
>  <EOI>  [<ffffffff81039100>] ? default_idle+0x20/0x40
>  [<ffffffff81039172>] ? amd_e400_idle+0x52/0x100
>  [<ffffffff81030156>] ? cpu_idle+0xb6/0xe0
> ---[ end trace 7dc3992f562261b6 ]---

Most likely caused by e050e3f0a71b :
 perf: Fix broken interrupt rate throttling

CCing Stephane.

-- 
Markus

Re: WARNING: at arch/x86/kernel/cpu/perf_event.c:989

[Stephane Eranian]

Thanks for the bug report.
I did fix a couple of those in intel_ds.c and intel_lbr.c, obviously
there is another one in x86_pmu_start().
I'll post a patch to remove that warning.


On Thu, Feb 2, 2012 at 10:32 PM, Markus Trippelsdorf
<markus@trippelsdorf.de> wrote:
> On 2012.02.02 at 22:17 +0100, Markus Trippelsdorf wrote:
>> The following warning is easily reproducible after todays
>> 'perf-urgent-for-mingo' merge by just running "perf top":
>>
>> ------------[ cut here ]------------
>> WARNING: at arch/x86/kernel/cpu/perf_event.c:989 x86_pmu_start+0xa5/0x100()
>> Hardware name: System Product Name
>> Pid: 0, comm: swapper/2 Not tainted 3.3.0-rc2-00068-g24b36da-dirty #22
>> Call Trace:
>>  <IRQ>  [<ffffffff81054ba0>] ? warn_slowpath_common+0x60/0xa0
>>  [<ffffffff8103e1a5>] ? x86_pmu_start+0xa5/0x100
>>  [<ffffffff8109f062>] ? perf_adjust_freq_unthr_context.part.82+0xe2/0x140
>>  [<ffffffff8109f260>] ? perf_event_task_tick+0x1a0/0x280
>>  [<ffffffff81078be3>] ? scheduler_tick+0xc3/0x140
>>  [<ffffffff810615b5>] ? update_process_times+0x55/0x80
>>  [<ffffffff8108904d>] ? tick_sched_timer+0x4d/0xa0
>>  [<ffffffff81072d1b>] ? __run_hrtimer.isra.32+0x3b/0xc0
>>  [<ffffffff810735e5>] ? hrtimer_interrupt+0xc5/0x1e0
>>  [<ffffffff81045de3>] ? smp_apic_timer_interrupt+0x63/0xa0
>>  [<ffffffff8147768b>] ? apic_timer_interrupt+0x6b/0x70
>>  <EOI>  [<ffffffff81039100>] ? default_idle+0x20/0x40
>>  [<ffffffff81039172>] ? amd_e400_idle+0x52/0x100
>>  [<ffffffff81030156>] ? cpu_idle+0xb6/0xe0
>> ---[ end trace 7dc3992f562261b6 ]---
>
> Most likely caused by e050e3f0a71b :
>  perf: Fix broken interrupt rate throttling
>
> CCing Stephane.
>
> --
> Markus

Re: WARNING: at arch/x86/kernel/cpu/perf_event.c:989

[Ingo Molnar]

there's yet another one triggering at:

[89214.962603] ------------[ cut here ]------------
[89214.967441] WARNING: at arch/x86/kernel/cpu/perf_event.c:995 x86_pmu_start+0x79/0xd4()
[89214.975825] Hardware name: X8DTN
[89214.979268] Modules linked in:
[89214.982560] Pid: 0, comm: swapper/6 Not tainted 3.3.0-rc2-tip+ #1
[89214.988865] Call Trace:
[89214.991533]  <IRQ>  [<ffffffff81065cc7>] warn_slowpath_common+0x7e/0x97
[89214.998379]  [<ffffffff81065cf5>] warn_slowpath_null+0x15/0x17
[89215.004428]  [<ffffffff8103f626>] x86_pmu_start+0x79/0xd4
[89215.010042]  [<ffffffff810e30d1>] perf_adjust_freq_unthr_context.part.63+0xef/0x123
[89215.018123]  [<ffffffff810e318c>] perf_event_task_tick+0x87/0x1c1
[89215.024463]  [<ffffffff810a2370>] ? tick_nohz_handler+0xda/0xda
[89215.030595]  [<ffffffff8108b819>] scheduler_tick+0xd1/0xf3
[89215.036296]  [<ffffffff810720b0>] update_process_times+0x5e/0x6f
[89215.042512]  [<ffffffff810a23e0>] tick_sched_timer+0x70/0x99
[89215.048387]  [<ffffffff810823f9>] __run_hrtimer+0x8c/0x148
[89215.054087]  [<ffffffff81082add>] hrtimer_interrupt+0xc1/0x18c

Thanks,

	Ingo

Re: WARNING: at arch/x86/kernel/cpu/perf_event.c:989

[Stephane Eranian]

I am working on it. It is hard to reproduce for me.

On Sat, Feb 4, 2012 at 2:51 PM, Ingo Molnar <mingo@elte.hu> wrote:
>
> there's yet another one triggering at:
>
> [89214.962603] ------------[ cut here ]------------
> [89214.967441] WARNING: at arch/x86/kernel/cpu/perf_event.c:995 x86_pmu_start+0x79/0xd4()
> [89214.975825] Hardware name: X8DTN
> [89214.979268] Modules linked in:
> [89214.982560] Pid: 0, comm: swapper/6 Not tainted 3.3.0-rc2-tip+ #1
> [89214.988865] Call Trace:
> [89214.991533]  <IRQ>  [<ffffffff81065cc7>] warn_slowpath_common+0x7e/0x97
> [89214.998379]  [<ffffffff81065cf5>] warn_slowpath_null+0x15/0x17
> [89215.004428]  [<ffffffff8103f626>] x86_pmu_start+0x79/0xd4
> [89215.010042]  [<ffffffff810e30d1>] perf_adjust_freq_unthr_context.part.63+0xef/0x123
> [89215.018123]  [<ffffffff810e318c>] perf_event_task_tick+0x87/0x1c1
> [89215.024463]  [<ffffffff810a2370>] ? tick_nohz_handler+0xda/0xda
> [89215.030595]  [<ffffffff8108b819>] scheduler_tick+0xd1/0xf3
> [89215.036296]  [<ffffffff810720b0>] update_process_times+0x5e/0x6f
> [89215.042512]  [<ffffffff810a23e0>] tick_sched_timer+0x70/0x99
> [89215.048387]  [<ffffffff810823f9>] __run_hrtimer+0x8c/0x148
> [89215.054087]  [<ffffffff81082add>] hrtimer_interrupt+0xc1/0x18c
>
> Thanks,
>
>        Ingo

Re: WARNING: at arch/x86/kernel/cpu/perf_event.c:989

[Stephane Eranian]

On Sat, Feb 4, 2012 at 7:09 PM, Stephane Eranian <eranian@google.com> wrote:
> I am working on it. It is hard to reproduce for me.
>
What did you run to trigger this warning? What system is this on?

> On Sat, Feb 4, 2012 at 2:51 PM, Ingo Molnar <mingo@elte.hu> wrote:
>>
>> there's yet another one triggering at:
>>
>> [89214.962603] ------------[ cut here ]------------
>> [89214.967441] WARNING: at arch/x86/kernel/cpu/perf_event.c:995 x86_pmu_start+0x79/0xd4()
>> [89214.975825] Hardware name: X8DTN
>> [89214.979268] Modules linked in:
>> [89214.982560] Pid: 0, comm: swapper/6 Not tainted 3.3.0-rc2-tip+ #1
>> [89214.988865] Call Trace:
>> [89214.991533]  <IRQ>  [<ffffffff81065cc7>] warn_slowpath_common+0x7e/0x97
>> [89214.998379]  [<ffffffff81065cf5>] warn_slowpath_null+0x15/0x17
>> [89215.004428]  [<ffffffff8103f626>] x86_pmu_start+0x79/0xd4
>> [89215.010042]  [<ffffffff810e30d1>] perf_adjust_freq_unthr_context.part.63+0xef/0x123
>> [89215.018123]  [<ffffffff810e318c>] perf_event_task_tick+0x87/0x1c1
>> [89215.024463]  [<ffffffff810a2370>] ? tick_nohz_handler+0xda/0xda
>> [89215.030595]  [<ffffffff8108b819>] scheduler_tick+0xd1/0xf3
>> [89215.036296]  [<ffffffff810720b0>] update_process_times+0x5e/0x6f
>> [89215.042512]  [<ffffffff810a23e0>] tick_sched_timer+0x70/0x99
>> [89215.048387]  [<ffffffff810823f9>] __run_hrtimer+0x8c/0x148
>> [89215.054087]  [<ffffffff81082add>] hrtimer_interrupt+0xc1/0x18c
>>
>> Thanks,
>>
>>        Ingo

Re: WARNING: at arch/x86/kernel/cpu/perf_event.c:989

[Eric Dumazet]

Le lundi 06 février 2012 à 10:54 +0100, Stephane Eranian a écrit :
> On Sat, Feb 4, 2012 at 7:09 PM, Stephane Eranian <eranian@google.com> wrote:
> > I am working on it. It is hard to reproduce for me.
> >
> What did you run to trigger this warning? What system is this on?
> 
> > On Sat, Feb 4, 2012 at 2:51 PM, Ingo Molnar <mingo@elte.hu> wrote:
> >>
> >> there's yet another one triggering at:
> >>
> >> [89214.962603] ------------[ cut here ]------------
> >> [89214.967441] WARNING: at arch/x86/kernel/cpu/perf_event.c:995 x86_pmu_start+0x79/0xd4()
> >> [89214.975825] Hardware name: X8DTN
> >> [89214.979268] Modules linked in:
> >> [89214.982560] Pid: 0, comm: swapper/6 Not tainted 3.3.0-rc2-tip+ #1
> >> [89214.988865] Call Trace:
> >> [89214.991533]  <IRQ>  [<ffffffff81065cc7>] warn_slowpath_common+0x7e/0x97
> >> [89214.998379]  [<ffffffff81065cf5>] warn_slowpath_null+0x15/0x17
> >> [89215.004428]  [<ffffffff8103f626>] x86_pmu_start+0x79/0xd4
> >> [89215.010042]  [<ffffffff810e30d1>] perf_adjust_freq_unthr_context.part.63+0xef/0x123
> >> [89215.018123]  [<ffffffff810e318c>] perf_event_task_tick+0x87/0x1c1
> >> [89215.024463]  [<ffffffff810a2370>] ? tick_nohz_handler+0xda/0xda
> >> [89215.030595]  [<ffffffff8108b819>] scheduler_tick+0xd1/0xf3
> >> [89215.036296]  [<ffffffff810720b0>] update_process_times+0x5e/0x6f
> >> [89215.042512]  [<ffffffff810a23e0>] tick_sched_timer+0x70/0x99
> >> [89215.048387]  [<ffffffff810823f9>] __run_hrtimer+0x8c/0x148
> >> [89215.054087]  [<ffffffff81082add>] hrtimer_interrupt+0xc1/0x18c
> >>
> >> Thanks,
> >>
> >>        Ingo

Stephane, I trigger this as well very easily on my machine, 32bit
kernel, using the following :


perf record -a -g hackbench 10 thread 4000


[ 1205.338006] ------------[ cut here ]------------
[ 1205.338028] WARNING: at arch/x86/kernel/cpu/perf_event.c:989
x86_pmu_start+0xba/0xf0()
[ 1205.338044] Hardware name: ProLiant BL460c G1
[ 1205.338053] Modules linked in: xt_hashlimit af_packet tg3 bonding
[ 1205.338076] Pid: 0, comm: swapper/5 Not tainted
3.3.0-rc2-00172-g23783f8 #55
[ 1205.338090] Call Trace:
[ 1205.338100]  [<c0609e06>] ? printk+0x1d/0x1f
[ 1205.338111]  [<c022b012>] warn_slowpath_common+0x72/0xa0
[ 1205.338123]  [<c021072a>] ? x86_pmu_start+0xba/0xf0
[ 1205.338134]  [<c021072a>] ? x86_pmu_start+0xba/0xf0
[ 1205.338145]  [<c022b062>] warn_slowpath_null+0x22/0x30
[ 1205.338157]  [<c021072a>] x86_pmu_start+0xba/0xf0
[ 1205.338170]  [<c02aba7b>] perf_adjust_freq_unthr_context.part.75
+0xfb/0x180
[ 1205.338185]  [<c02abd21>] perf_event_task_tick+0x221/0x290
[ 1205.338199]  [<c0258dee>] ? update_cpu_load+0xbe/0xf0
[ 1205.338210]  [<c0259728>] scheduler_tick+0x98/0xf0
[ 1205.338222]  [<c0239c6a>] update_process_times+0x5a/0x70
[ 1205.338235]  [<c026bb10>] tick_sched_timer+0x60/0x1f0
[ 1205.338248]  [<c024f1c0>] ? __remove_hrtimer+0x40/0xa0
[ 1205.338260]  [<c024f3f7>] __run_hrtimer+0x67/0x1e0
[ 1205.338270]  [<c026bab0>] ? tick_init_highres+0x20/0x20
[ 1205.338297]  [<c02501b0>] hrtimer_interrupt+0xe0/0x260
[ 1205.338323]  [<c025c207>] ? sched_clock_cpu+0xd7/0x160
[ 1205.338350]  [<c025c841>] ? set_next_entity+0x31/0x70
[ 1205.338380]  [<c0610804>] smp_apic_timer_interrupt+0x54/0x88
[ 1205.338407]  [<c060fcda>] apic_timer_interrupt+0x2a/0x30
[ 1205.338439]  [<c0209efc>] ? mwait_idle+0x7c/0x1d0
[ 1205.338470]  [<c0201606>] cpu_idle+0x66/0xa0
[ 1205.338495]  [<c060500f>] start_secondary+0x1bf/0x1c5
[ 1205.338520] ---[ end trace 94f790d96c8679f1 ]---
[ 1211.617012] Uhhuh. NMI received for unknown reason 21 on CPU 0.
[ 1211.617049] Do you have a strange power saving mode enabled?
[ 1211.617075] Dazed and confused, but trying to continue
[ 1211.970013] Uhhuh. NMI received for unknown reason 31 on CPU 7.
[ 1211.970050] Do you have a strange power saving mode enabled?
[ 1211.970076] Dazed and confused, but trying to continue
[ 1214.440012] Uhhuh. NMI received for unknown reason 21 on CPU 3.
[ 1214.440048] Do you have a strange power saving mode enabled?
[ 1214.440074] Dazed and confused, but trying to continue
[ 1214.634012] Uhhuh. NMI received for unknown reason 31 on CPU 4.
[ 1214.634047] Do you have a strange power saving mode enabled?
[ 1214.634073] Dazed and confused, but trying to continue
[ 1216.568016] Uhhuh. NMI received for unknown reason 31 on CPU 1.
[ 1216.568052] Do you have a strange power saving mode enabled?
[ 1216.568078] Dazed and confused, but trying to continue
[ 1217.309010] Uhhuh. NMI received for unknown reason 31 on CPU 2.
[ 1217.309044] Do you have a strange power saving mode enabled?
[ 1217.309070] Dazed and confused, but trying to continue




processor	: 7
vendor_id	: GenuineIntel
cpu family	: 6
model		: 23
model name	: Intel(R) Xeon(R) CPU           E5450  @ 3.00GHz
stepping	: 6

Re: WARNING: at arch/x86/kernel/cpu/perf_event.c:989

[Stephane Eranian]

On Mon, Feb 6, 2012 at 11:12 AM, Eric Dumazet <eric.dumazet@gmail.com> wrote:
> Le lundi 06 février 2012 à 10:54 +0100, Stephane Eranian a écrit :
>> On Sat, Feb 4, 2012 at 7:09 PM, Stephane Eranian <eranian@google.com> wrote:
>> > I am working on it. It is hard to reproduce for me.
>> >
>> What did you run to trigger this warning? What system is this on?
>>
>> > On Sat, Feb 4, 2012 at 2:51 PM, Ingo Molnar <mingo@elte.hu> wrote:
>> >>
>> >> there's yet another one triggering at:
>> >>
>> >> [89214.962603] ------------[ cut here ]------------
>> >> [89214.967441] WARNING: at arch/x86/kernel/cpu/perf_event.c:995 x86_pmu_start+0x79/0xd4()
>> >> [89214.975825] Hardware name: X8DTN
>> >> [89214.979268] Modules linked in:
>> >> [89214.982560] Pid: 0, comm: swapper/6 Not tainted 3.3.0-rc2-tip+ #1
>> >> [89214.988865] Call Trace:
>> >> [89214.991533]  <IRQ>  [<ffffffff81065cc7>] warn_slowpath_common+0x7e/0x97
>> >> [89214.998379]  [<ffffffff81065cf5>] warn_slowpath_null+0x15/0x17
>> >> [89215.004428]  [<ffffffff8103f626>] x86_pmu_start+0x79/0xd4
>> >> [89215.010042]  [<ffffffff810e30d1>] perf_adjust_freq_unthr_context.part.63+0xef/0x123
>> >> [89215.018123]  [<ffffffff810e318c>] perf_event_task_tick+0x87/0x1c1
>> >> [89215.024463]  [<ffffffff810a2370>] ? tick_nohz_handler+0xda/0xda
>> >> [89215.030595]  [<ffffffff8108b819>] scheduler_tick+0xd1/0xf3
>> >> [89215.036296]  [<ffffffff810720b0>] update_process_times+0x5e/0x6f
>> >> [89215.042512]  [<ffffffff810a23e0>] tick_sched_timer+0x70/0x99
>> >> [89215.048387]  [<ffffffff810823f9>] __run_hrtimer+0x8c/0x148
>> >> [89215.054087]  [<ffffffff81082add>] hrtimer_interrupt+0xc1/0x18c
>> >>
>> >> Thanks,
>> >>
>> >>        Ingo
>
> Stephane, I trigger this as well very easily on my machine, 32bit
> kernel, using the following :
>
>
> perf record -a -g hackbench 10 thread 4000
>
I tried that on my Nehalem 64-bit running 3.3.0-rc2 where I reverted
that chunck of commit 84f2b9b:

--- a/arch/x86/kernel/cpu/perf_event.c
+++ b/arch/x86/kernel/cpu/perf_event.c
@@ -986,9 +986,6 @@ static void x86_pmu_start(struct perf_event
*event, int flags)
        struct cpu_hw_events *cpuc = &__get_cpu_var(cpu_hw_events);
        int idx = event->hw.idx;

-       if (WARN_ON_ONCE(!(event->hw.state & PERF_HES_STOPPED)))
-               return;
-
        if (WARN_ON_ONCE(idx == -1))
                return;

I have an explanation for the other two WARN_ON_ONCE() but not for that
one. Friday, I was able to track this down to a situation where from unthr
we call pmu->stop() but because the event is already marked as not active
in cpuc->active_mask,  PERF_HES_STOPPED is not set, then
x86_pmu_start() complains. It happens during frequency adjustments and
not unthrottling.

This is odd because the only place where cpuc->active_mask is cleared
(for the event) is x86_pmu_stop(). So looks like we get into a situation where
cpuc->active_mask[b] == 0 && event->state != HES_STOPPED. But I don't
know where this could happen.


>
> [ 1205.338006] ------------[ cut here ]------------
> [ 1205.338028] WARNING: at arch/x86/kernel/cpu/perf_event.c:989
> x86_pmu_start+0xba/0xf0()
> [ 1205.338044] Hardware name: ProLiant BL460c G1
> [ 1205.338053] Modules linked in: xt_hashlimit af_packet tg3 bonding
> [ 1205.338076] Pid: 0, comm: swapper/5 Not tainted
> 3.3.0-rc2-00172-g23783f8 #55
> [ 1205.338090] Call Trace:
> [ 1205.338100]  [<c0609e06>] ? printk+0x1d/0x1f
> [ 1205.338111]  [<c022b012>] warn_slowpath_common+0x72/0xa0
> [ 1205.338123]  [<c021072a>] ? x86_pmu_start+0xba/0xf0
> [ 1205.338134]  [<c021072a>] ? x86_pmu_start+0xba/0xf0
> [ 1205.338145]  [<c022b062>] warn_slowpath_null+0x22/0x30
> [ 1205.338157]  [<c021072a>] x86_pmu_start+0xba/0xf0
> [ 1205.338170]  [<c02aba7b>] perf_adjust_freq_unthr_context.part.75
> +0xfb/0x180
> [ 1205.338185]  [<c02abd21>] perf_event_task_tick+0x221/0x290
> [ 1205.338199]  [<c0258dee>] ? update_cpu_load+0xbe/0xf0
> [ 1205.338210]  [<c0259728>] scheduler_tick+0x98/0xf0
> [ 1205.338222]  [<c0239c6a>] update_process_times+0x5a/0x70
> [ 1205.338235]  [<c026bb10>] tick_sched_timer+0x60/0x1f0
> [ 1205.338248]  [<c024f1c0>] ? __remove_hrtimer+0x40/0xa0
> [ 1205.338260]  [<c024f3f7>] __run_hrtimer+0x67/0x1e0
> [ 1205.338270]  [<c026bab0>] ? tick_init_highres+0x20/0x20
> [ 1205.338297]  [<c02501b0>] hrtimer_interrupt+0xe0/0x260
> [ 1205.338323]  [<c025c207>] ? sched_clock_cpu+0xd7/0x160
> [ 1205.338350]  [<c025c841>] ? set_next_entity+0x31/0x70
> [ 1205.338380]  [<c0610804>] smp_apic_timer_interrupt+0x54/0x88
> [ 1205.338407]  [<c060fcda>] apic_timer_interrupt+0x2a/0x30
> [ 1205.338439]  [<c0209efc>] ? mwait_idle+0x7c/0x1d0
> [ 1205.338470]  [<c0201606>] cpu_idle+0x66/0xa0
> [ 1205.338495]  [<c060500f>] start_secondary+0x1bf/0x1c5
> [ 1205.338520] ---[ end trace 94f790d96c8679f1 ]---
> [ 1211.617012] Uhhuh. NMI received for unknown reason 21 on CPU 0.
> [ 1211.617049] Do you have a strange power saving mode enabled?
> [ 1211.617075] Dazed and confused, but trying to continue
> [ 1211.970013] Uhhuh. NMI received for unknown reason 31 on CPU 7.
> [ 1211.970050] Do you have a strange power saving mode enabled?
> [ 1211.970076] Dazed and confused, but trying to continue
> [ 1214.440012] Uhhuh. NMI received for unknown reason 21 on CPU 3.
> [ 1214.440048] Do you have a strange power saving mode enabled?
> [ 1214.440074] Dazed and confused, but trying to continue
> [ 1214.634012] Uhhuh. NMI received for unknown reason 31 on CPU 4.
> [ 1214.634047] Do you have a strange power saving mode enabled?
> [ 1214.634073] Dazed and confused, but trying to continue
> [ 1216.568016] Uhhuh. NMI received for unknown reason 31 on CPU 1.
> [ 1216.568052] Do you have a strange power saving mode enabled?
> [ 1216.568078] Dazed and confused, but trying to continue
> [ 1217.309010] Uhhuh. NMI received for unknown reason 31 on CPU 2.
> [ 1217.309044] Do you have a strange power saving mode enabled?
> [ 1217.309070] Dazed and confused, but trying to continue
>
>
>
>
> processor       : 7
> vendor_id       : GenuineIntel
> cpu family      : 6
> model           : 23
> model name      : Intel(R) Xeon(R) CPU           E5450  @ 3.00GHz
> stepping        : 6
>
>

Re: WARNING: at arch/x86/kernel/cpu/perf_event.c:989

[Eric Dumazet]

Le lundi 06 février 2012 à 11:40 +0100, Stephane Eranian a écrit :
> On Mon, Feb 6, 2012 at 11:12 AM, Eric Dumazet <eric.dumazet@gmail.com> wrote:
> > Le lundi 06 février 2012 à 10:54 +0100, Stephane Eranian a écrit :
> >> On Sat, Feb 4, 2012 at 7:09 PM, Stephane Eranian <eranian@google.com> wrote:
> >> > I am working on it. It is hard to reproduce for me.
> >> >
> >> What did you run to trigger this warning? What system is this on?
> >>
> >> > On Sat, Feb 4, 2012 at 2:51 PM, Ingo Molnar <mingo@elte.hu> wrote:
> >> >>
> >> >> there's yet another one triggering at:
> >> >>
> >> >> [89214.962603] ------------[ cut here ]------------
> >> >> [89214.967441] WARNING: at arch/x86/kernel/cpu/perf_event.c:995 x86_pmu_start+0x79/0xd4()
> >> >> [89214.975825] Hardware name: X8DTN
> >> >> [89214.979268] Modules linked in:
> >> >> [89214.982560] Pid: 0, comm: swapper/6 Not tainted 3.3.0-rc2-tip+ #1
> >> >> [89214.988865] Call Trace:
> >> >> [89214.991533]  <IRQ>  [<ffffffff81065cc7>] warn_slowpath_common+0x7e/0x97
> >> >> [89214.998379]  [<ffffffff81065cf5>] warn_slowpath_null+0x15/0x17
> >> >> [89215.004428]  [<ffffffff8103f626>] x86_pmu_start+0x79/0xd4
> >> >> [89215.010042]  [<ffffffff810e30d1>] perf_adjust_freq_unthr_context.part.63+0xef/0x123
> >> >> [89215.018123]  [<ffffffff810e318c>] perf_event_task_tick+0x87/0x1c1
> >> >> [89215.024463]  [<ffffffff810a2370>] ? tick_nohz_handler+0xda/0xda
> >> >> [89215.030595]  [<ffffffff8108b819>] scheduler_tick+0xd1/0xf3
> >> >> [89215.036296]  [<ffffffff810720b0>] update_process_times+0x5e/0x6f
> >> >> [89215.042512]  [<ffffffff810a23e0>] tick_sched_timer+0x70/0x99
> >> >> [89215.048387]  [<ffffffff810823f9>] __run_hrtimer+0x8c/0x148
> >> >> [89215.054087]  [<ffffffff81082add>] hrtimer_interrupt+0xc1/0x18c
> >> >>
> >> >> Thanks,
> >> >>
> >> >>        Ingo
> >
> > Stephane, I trigger this as well very easily on my machine, 32bit
> > kernel, using the following :
> >
> >
> > perf record -a -g hackbench 10 thread 4000
> >
> I tried that on my Nehalem 64-bit running 3.3.0-rc2 where I reverted
> that chunck of commit 84f2b9b:
> 
> --- a/arch/x86/kernel/cpu/perf_event.c
> +++ b/arch/x86/kernel/cpu/perf_event.c
> @@ -986,9 +986,6 @@ static void x86_pmu_start(struct perf_event
> *event, int flags)
>         struct cpu_hw_events *cpuc = &__get_cpu_var(cpu_hw_events);
>         int idx = event->hw.idx;
> 
> -       if (WARN_ON_ONCE(!(event->hw.state & PERF_HES_STOPPED)))
> -               return;
> -
>         if (WARN_ON_ONCE(idx == -1))
>                 return;
> 
> I have an explanation for the other two WARN_ON_ONCE() but not for that
> one. Friday, I was able to track this down to a situation where from unthr
> we call pmu->stop() but because the event is already marked as not active
> in cpuc->active_mask,  PERF_HES_STOPPED is not set, then
> x86_pmu_start() complains. It happens during frequency adjustments and
> not unthrottling.
> 
> This is odd because the only place where cpuc->active_mask is cleared
> (for the event) is x86_pmu_stop(). So looks like we get into a situation where
> cpuc->active_mask[b] == 0 && event->state != HES_STOPPED. But I don't
> know where this could happen.
> 
> 

I forgot to say my other dev machine, Nehalem 64bit, doesnt trigger the
WARN_ON_ONCE with exact same kernel version, unless I force threads on
same socket...

perf record -a -g taskset 5555 hackbench 10 thread 40000

[95402.265521] ------------[ cut here ]------------
[95402.265528] WARNING: at arch/x86/kernel/cpu/perf_event.c:989
x86_pmu_start+0xdc/0x110()
[95402.265530] Hardware name: ProLiant BL460c G6
[95402.265531] Modules linked in: ipmi_devintf nfsd exportfs ipmi_si
hpilo bnx2x crc32c libcrc32c mdio [last unloaded: scsi_wait_scan]
[95402.265540] Pid: 0, comm: swapper/5 Not tainted 3.3.0-rc2+ #633
[95402.265541] Call Trace:
[95402.265543]  <IRQ>  [<ffffffff81037b9f>] warn_slowpath_common
+0x7f/0xc0
[95402.265549]  [<ffffffff81037bfa>] warn_slowpath_null+0x1a/0x20
[95402.265551]  [<ffffffff810127fc>] x86_pmu_start+0xdc/0x110
[95402.265559]  [<ffffffff810e78fa>]
perf_adjust_freq_unthr_context.part.75+0xda/0x150
[95402.265562]  [<ffffffff810e7b71>] perf_event_task_tick+0x201/0x2b0
[95402.265566]  [<ffffffff8106bf49>] scheduler_tick+0xe9/0x160
[95402.265571]  [<ffffffff8104964e>] update_process_times+0x6e/0x90
[95402.265575]  [<ffffffff8108c084>] tick_sched_timer+0x64/0xc0
[95402.265579]  [<ffffffff8105ffb4>] __run_hrtimer+0x84/0x1f0
[95402.265581]  [<ffffffff8108c020>] ? tick_nohz_handler+0xf0/0xf0
[95402.265584]  [<ffffffff810608e3>] hrtimer_interrupt+0xf3/0x220
[95402.265588]  [<ffffffff8170c049>] smp_apic_timer_interrupt+0x69/0x99
[95402.265593]  [<ffffffff8170af8b>] apic_timer_interrupt+0x6b/0x70
[95402.265594]  <EOI>  [<ffffffff8100ab2e>] ? mwait_idle+0xae/0x280
[95402.265601]  [<ffffffff810011df>] cpu_idle+0x8f/0xd0
[95402.265605]  [<ffffffff816f3ccc>] start_secondary+0x1d6/0x1da
[95402.265607] ---[ end trace 5e345a2582bb0ea3 ]---

Re: WARNING: at arch/x86/kernel/cpu/perf_event.c:989

[Stephane Eranian]

Ok, I found the problem!

it comes from perf_adjust_freq_unthr_context() vs perf_adjust_period().
The latter can under certain condition stop and restart the event. So we
had:

      stop()
      if (delta > 0) {
           perf_adjust_period() {
               if (period > 8*...) {
                   stop()
                   ...
                   start()
               }
           }
       }
       start()

Could have a double stop() and double start(), thus triggering the warning in
x86_pmu_start().

Will post a patch shortly to fix this.



On Mon, Feb 6, 2012 at 12:11 PM, Eric Dumazet <eric.dumazet@gmail.com> wrote:
> Le lundi 06 février 2012 à 11:40 +0100, Stephane Eranian a écrit :
>> On Mon, Feb 6, 2012 at 11:12 AM, Eric Dumazet <eric.dumazet@gmail.com> wrote:
>> > Le lundi 06 février 2012 à 10:54 +0100, Stephane Eranian a écrit :
>> >> On Sat, Feb 4, 2012 at 7:09 PM, Stephane Eranian <eranian@google.com> wrote:
>> >> > I am working on it. It is hard to reproduce for me.
>> >> >
>> >> What did you run to trigger this warning? What system is this on?
>> >>
>> >> > On Sat, Feb 4, 2012 at 2:51 PM, Ingo Molnar <mingo@elte.hu> wrote:
>> >> >>
>> >> >> there's yet another one triggering at:
>> >> >>
>> >> >> [89214.962603] ------------[ cut here ]------------
>> >> >> [89214.967441] WARNING: at arch/x86/kernel/cpu/perf_event.c:995 x86_pmu_start+0x79/0xd4()
>> >> >> [89214.975825] Hardware name: X8DTN
>> >> >> [89214.979268] Modules linked in:
>> >> >> [89214.982560] Pid: 0, comm: swapper/6 Not tainted 3.3.0-rc2-tip+ #1
>> >> >> [89214.988865] Call Trace:
>> >> >> [89214.991533]  <IRQ>  [<ffffffff81065cc7>] warn_slowpath_common+0x7e/0x97
>> >> >> [89214.998379]  [<ffffffff81065cf5>] warn_slowpath_null+0x15/0x17
>> >> >> [89215.004428]  [<ffffffff8103f626>] x86_pmu_start+0x79/0xd4
>> >> >> [89215.010042]  [<ffffffff810e30d1>] perf_adjust_freq_unthr_context.part.63+0xef/0x123
>> >> >> [89215.018123]  [<ffffffff810e318c>] perf_event_task_tick+0x87/0x1c1
>> >> >> [89215.024463]  [<ffffffff810a2370>] ? tick_nohz_handler+0xda/0xda
>> >> >> [89215.030595]  [<ffffffff8108b819>] scheduler_tick+0xd1/0xf3
>> >> >> [89215.036296]  [<ffffffff810720b0>] update_process_times+0x5e/0x6f
>> >> >> [89215.042512]  [<ffffffff810a23e0>] tick_sched_timer+0x70/0x99
>> >> >> [89215.048387]  [<ffffffff810823f9>] __run_hrtimer+0x8c/0x148
>> >> >> [89215.054087]  [<ffffffff81082add>] hrtimer_interrupt+0xc1/0x18c
>> >> >>
>> >> >> Thanks,
>> >> >>
>> >> >>        Ingo
>> >
>> > Stephane, I trigger this as well very easily on my machine, 32bit
>> > kernel, using the following :
>> >
>> >
>> > perf record -a -g hackbench 10 thread 4000
>> >
>> I tried that on my Nehalem 64-bit running 3.3.0-rc2 where I reverted
>> that chunck of commit 84f2b9b:
>>
>> --- a/arch/x86/kernel/cpu/perf_event.c
>> +++ b/arch/x86/kernel/cpu/perf_event.c
>> @@ -986,9 +986,6 @@ static void x86_pmu_start(struct perf_event
>> *event, int flags)
>>         struct cpu_hw_events *cpuc = &__get_cpu_var(cpu_hw_events);
>>         int idx = event->hw.idx;
>>
>> -       if (WARN_ON_ONCE(!(event->hw.state & PERF_HES_STOPPED)))
>> -               return;
>> -
>>         if (WARN_ON_ONCE(idx == -1))
>>                 return;
>>
>> I have an explanation for the other two WARN_ON_ONCE() but not for that
>> one. Friday, I was able to track this down to a situation where from unthr
>> we call pmu->stop() but because the event is already marked as not active
>> in cpuc->active_mask,  PERF_HES_STOPPED is not set, then
>> x86_pmu_start() complains. It happens during frequency adjustments and
>> not unthrottling.
>>
>> This is odd because the only place where cpuc->active_mask is cleared
>> (for the event) is x86_pmu_stop(). So looks like we get into a situation where
>> cpuc->active_mask[b] == 0 && event->state != HES_STOPPED. But I don't
>> know where this could happen.
>>
>>
>
> I forgot to say my other dev machine, Nehalem 64bit, doesnt trigger the
> WARN_ON_ONCE with exact same kernel version, unless I force threads on
> same socket...
>
> perf record -a -g taskset 5555 hackbench 10 thread 40000
>
> [95402.265521] ------------[ cut here ]------------
> [95402.265528] WARNING: at arch/x86/kernel/cpu/perf_event.c:989
> x86_pmu_start+0xdc/0x110()
> [95402.265530] Hardware name: ProLiant BL460c G6
> [95402.265531] Modules linked in: ipmi_devintf nfsd exportfs ipmi_si
> hpilo bnx2x crc32c libcrc32c mdio [last unloaded: scsi_wait_scan]
> [95402.265540] Pid: 0, comm: swapper/5 Not tainted 3.3.0-rc2+ #633
> [95402.265541] Call Trace:
> [95402.265543]  <IRQ>  [<ffffffff81037b9f>] warn_slowpath_common
> +0x7f/0xc0
> [95402.265549]  [<ffffffff81037bfa>] warn_slowpath_null+0x1a/0x20
> [95402.265551]  [<ffffffff810127fc>] x86_pmu_start+0xdc/0x110
> [95402.265559]  [<ffffffff810e78fa>]
> perf_adjust_freq_unthr_context.part.75+0xda/0x150
> [95402.265562]  [<ffffffff810e7b71>] perf_event_task_tick+0x201/0x2b0
> [95402.265566]  [<ffffffff8106bf49>] scheduler_tick+0xe9/0x160
> [95402.265571]  [<ffffffff8104964e>] update_process_times+0x6e/0x90
> [95402.265575]  [<ffffffff8108c084>] tick_sched_timer+0x64/0xc0
> [95402.265579]  [<ffffffff8105ffb4>] __run_hrtimer+0x84/0x1f0
> [95402.265581]  [<ffffffff8108c020>] ? tick_nohz_handler+0xf0/0xf0
> [95402.265584]  [<ffffffff810608e3>] hrtimer_interrupt+0xf3/0x220
> [95402.265588]  [<ffffffff8170c049>] smp_apic_timer_interrupt+0x69/0x99
> [95402.265593]  [<ffffffff8170af8b>] apic_timer_interrupt+0x6b/0x70
> [95402.265594]  <EOI>  [<ffffffff8100ab2e>] ? mwait_idle+0xae/0x280
> [95402.265601]  [<ffffffff810011df>] cpu_idle+0x8f/0xd0
> [95402.265605]  [<ffffffff816f3ccc>] start_secondary+0x1d6/0x1da
> [95402.265607] ---[ end trace 5e345a2582bb0ea3 ]---
>
>

Re: WARNING: at arch/x86/kernel/cpu/perf_event.c:989

[Peter Zijlstra]

On Mon, 2012-02-06 at 15:13 +0100, Stephane Eranian wrote:
> Ok, I found the problem!
> 
> it comes from perf_adjust_freq_unthr_context() vs perf_adjust_period().
> The latter can under certain condition stop and restart the event. So we
> had:
> 
>       stop()
>       if (delta > 0) {
>            perf_adjust_period() {
>                if (period > 8*...) {
>                    stop()
>                    ...
>                    start()
>                }
>            }
>        }
>        start()
> 
> Could have a double stop() and double start(), thus triggering the warning in
> x86_pmu_start().
> 
> Will post a patch shortly to fix this. 

Nice, thanks for looking at this!

Re: WARNING: at arch/x86/kernel/cpu/perf_event.c:989

[Stephane Eranian]

On Mon, Feb 6, 2012 at 3:29 PM, Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:
> On Mon, 2012-02-06 at 15:13 +0100, Stephane Eranian wrote:
>> Ok, I found the problem!
>>
>> it comes from perf_adjust_freq_unthr_context() vs perf_adjust_period().
>> The latter can under certain condition stop and restart the event. So we
>> had:
>>
>>       stop()
>>       if (delta > 0) {
>>            perf_adjust_period() {
>>                if (period > 8*...) {
>>                    stop()
>>                    ...
>>                    start()
>>                }
>>            }
>>        }
>>        start()
>>
>> Could have a double stop() and double start(), thus triggering the warning in
>> x86_pmu_start().
>>
>> Will post a patch shortly to fix this.
>
> Nice, thanks for looking at this!
>
I am wondering why we stop and restart the code in perf_adjust_period()
when it's called from __perf_event_overflow(). Isn't it supposed to be stopped
already by the model specific interrupt handler. Looks like we do stop/start,
just to get the reload aspect of start. Is that right?

Re: WARNING: at arch/x86/kernel/cpu/perf_event.c:989

[Ingo Molnar]

* Stephane Eranian <eranian@google.com> wrote:

> Ok, I found the problem!
> 
> it comes from perf_adjust_freq_unthr_context() vs perf_adjust_period().
> The latter can under certain condition stop and restart the event. So we
> had:
> 
>       stop()
>       if (delta > 0) {
>            perf_adjust_period() {
>                if (period > 8*...) {
>                    stop()
>                    ...
>                    start()
>                }
>            }
>        }
>        start()
> 
> Could have a double stop() and double start(), thus triggering the warning in
> x86_pmu_start().
> 
> Will post a patch shortly to fix this.

Please send a patch against tip:master (or perf/urgent), on top 
of:

  84f2b9b2edc0: perf: Remove deprecated WARN_ON_ONCE()

Note that I updated that patch to removed one more WARN_ON() 
than you originally sent - please add it back as appropriate, in 
the delta fix patch.

Thanks,

	Ingo

Re: WARNING: at arch/x86/kernel/cpu/perf_event.c:989

[Stephane Eranian]

On Mon, Feb 6, 2012 at 3:38 PM, Ingo Molnar <mingo@elte.hu> wrote:
>
> * Stephane Eranian <eranian@google.com> wrote:
>
>> Ok, I found the problem!
>>
>> it comes from perf_adjust_freq_unthr_context() vs perf_adjust_period().
>> The latter can under certain condition stop and restart the event. So we
>> had:
>>
>>       stop()
>>       if (delta > 0) {
>>            perf_adjust_period() {
>>                if (period > 8*...) {
>>                    stop()
>>                    ...
>>                    start()
>>                }
>>            }
>>        }
>>        start()
>>
>> Could have a double stop() and double start(), thus triggering the warning in
>> x86_pmu_start().
>>
>> Will post a patch shortly to fix this.
>
> Please send a patch against tip:master (or perf/urgent), on top
> of:
>
>  84f2b9b2edc0: perf: Remove deprecated WARN_ON_ONCE()
>
> Note that I updated that patch to removed one more WARN_ON()
> than you originally sent - please add it back as appropriate, in
> the delta fix patch.
>
I have already added the warning back. Will send against tip:master

> Thanks,
>
>        Ingo

Re: WARNING: at arch/x86/kernel/cpu/perf_event.c:989

[Peter Zijlstra]

On Mon, 2012-02-06 at 15:32 +0100, Stephane Eranian wrote:
> I am wondering why we stop and restart the code in perf_adjust_period()
> when it's called from __perf_event_overflow(). Isn't it supposed to be stopped
> already by the model specific interrupt handler. Looks like we do stop/start,
> just to get the reload aspect of start. Is that right? 

Yes it is in order to deal with the case where an excessively long
period is programmed and we want to force load the new period without
having to wait for the old one to complete.

I hit that case several times with the adaptive code and events that
have very uneven rates.

Re: WARNING: at arch/x86/kernel/cpu/perf_event.c:989

[Ingo Molnar]

* Stephane Eranian <eranian@google.com> wrote:

> On Mon, Feb 6, 2012 at 3:38 PM, Ingo Molnar <mingo@elte.hu> wrote:
> >
> > * Stephane Eranian <eranian@google.com> wrote:
> >
> >> Ok, I found the problem!
> >>
> >> it comes from perf_adjust_freq_unthr_context() vs perf_adjust_period().
> >> The latter can under certain condition stop and restart the event. So we
> >> had:
> >>
> >>       stop()
> >>       if (delta > 0) {
> >>            perf_adjust_period() {
> >>                if (period > 8*...) {
> >>                    stop()
> >>                    ...
> >>                    start()
> >>                }
> >>            }
> >>        }
> >>        start()
> >>
> >> Could have a double stop() and double start(), thus triggering the warning in
> >> x86_pmu_start().
> >>
> >> Will post a patch shortly to fix this.
> >
> > Please send a patch against tip:master (or perf/urgent), on top
> > of:
> >
> >  84f2b9b2edc0: perf: Remove deprecated WARN_ON_ONCE()
> >
> > Note that I updated that patch to removed one more WARN_ON()
> > than you originally sent - please add it back as appropriate, in
> > the delta fix patch.
> >
> I have already added the warning back. Will send against tip:master

Great - thanks!

	Ingo

Re: WARNING: at arch/x86/kernel/cpu/perf_event.c:989

[Stephane Eranian]

Ok, I fixed the problem this time but in further testing I uncovered
another issue:


while true; do perf record -a -g hackbench 10 thread 4000; done &
while true; do perf record -a -g hackbench 10 thread 4000; done &

We hit:

[  765.034354] WARNING: at arch/x86/kernel/cpu/perf_event_intel.c:1029
intel_pmu_handle_irq+0x1df/0x2c0()
[  765.034356] Hardware name: System Product Name
[  765.034358] Modules linked in: binfmt_misc psmouse serio_raw
asus_atk0110 usbhid hid ahci pata_jmicron libahci r8169
[  765.034369] Pid: 8903, comm: hackbench Tainted: G        W
3.3.0-rc2-tip #35
[  765.034371] Call Trace:
[  765.034373]  <NMI>  [<ffffffff8104c15f>] warn_slowpath_common+0x7f/0xc0
[  765.034381]  [<ffffffff8104c1ba>] warn_slowpath_null+0x1a/0x20
[  765.034384]  [<ffffffff81027a0f>] intel_pmu_handle_irq+0x1df/0x2c0
[  765.034388]  [<ffffffff8148a606>] ? sock_aio_write+0x6/0x170
[  765.034392]  [<ffffffff81559171>] perf_event_nmi_handler+0x21/0x30
[  765.034395]  [<ffffffff81558a29>] do_nmi+0x129/0x3a0
[  765.034398]  [<ffffffff81557f7d>] restart_nmi+0x1a/0x1e
[  765.034402]  [<ffffffff8103abea>] ? native_write_msr_safe+0xa/0x10
[  765.034405]  [<ffffffff8103abea>] ? native_write_msr_safe+0xa/0x10
[  765.034408]  [<ffffffff8103abea>] ? native_write_msr_safe+0xa/0x10
[  765.034410]  <<EOE>>  <IRQ>  [<ffffffff81027447>]
intel_pmu_disable_event+0x87/0x100
[  765.034416]  [<ffffffff81022a16>] x86_pmu_stop+0x86/0xe0
[  765.034420]  [<ffffffff8110bc3b>]
perf_adjust_freq_unthr_context.part.67+0xeb/0x180
[  765.034423]  [<ffffffff8110bf50>] perf_event_task_tick+0x280/0x300
[  765.034427]  [<ffffffff8107f36f>] scheduler_tick+0xdf/0x150
[  765.034431]  [<ffffffff8105d66e>] update_process_times+0x6e/0x90
[  765.034435]  [<ffffffff810a0a34>] tick_sched_timer+0x64/0xc0
[  765.034438]  [<ffffffff81073286>] __run_hrtimer+0x76/0x1f0
[  765.034441]  [<ffffffff810a09d0>] ? tick_nohz_handler+0xf0/0xf0
[  765.034447]  [<ffffffff8101a3b9>] ? read_tsc+0x9/0x20
[  765.034450]  [<ffffffff81073b93>] hrtimer_interrupt+0xe3/0x200
[  765.034454]  [<ffffffff81560bdc>] ? call_softirq+0x1c/0x30
[  765.034457]  [<ffffffff81561529>] smp_apic_timer_interrupt+0x69/0x99
[  765.034461]  [<ffffffff815601de>] apic_timer_interrupt+0x6e/0x80
[  765.034462]  <EOI>  [<ffffffff811af082>] ? fsnotify+0x1d2/0x2b0
[  765.034470]  [<ffffffff81171085>] ? rw_verify_area+0x75/0xf0
[  765.034473]  [<ffffffff81171071>] ? rw_verify_area+0x61/0xf0
[  765.034475]  [<ffffffff811713a8>] vfs_write+0x88/0x180
[  765.034478]  [<ffffffff811716fa>] sys_write+0x4a/0x90
[  765.034481]  [<ffffffff8155f729>] system_call_fastpath+0x16/0x1b


Which is pointing to the Intel specific:

intel_pmu_handle_irq()
again:
        intel_pmu_ack_status(status);
        if (++loops > 100) {
                WARN_ONCE(1, "perfevents: irq loop stuck!\n");
                perf_event_print_debug();
                intel_pmu_reset();
                goto done;
        }

We are in a constant interrupt loop for a reason I don't yet understand.
Sure we have two counters going, bu given the callstack, one is being
stopped.

I know we talked about that a couple of weeks back, but after all, it may
be that it is not possible to run the frequency adjustment code without
stopping the entire PMU because of risk of interrupts. But it is not clear
to me what's causing this at this point.

I suggest we still apply my patch to fix the x86_pmu_start() first, then
I will submit a second patch to fix that one. Agreed?

On Mon, Feb 6, 2012 at 4:47 PM, Ingo Molnar <mingo@elte.hu> wrote:
>
> * Stephane Eranian <eranian@google.com> wrote:
>
>> On Mon, Feb 6, 2012 at 3:38 PM, Ingo Molnar <mingo@elte.hu> wrote:
>> >
>> > * Stephane Eranian <eranian@google.com> wrote:
>> >
>> >> Ok, I found the problem!
>> >>
>> >> it comes from perf_adjust_freq_unthr_context() vs perf_adjust_period().
>> >> The latter can under certain condition stop and restart the event. So we
>> >> had:
>> >>
>> >>       stop()
>> >>       if (delta > 0) {
>> >>            perf_adjust_period() {
>> >>                if (period > 8*...) {
>> >>                    stop()
>> >>                    ...
>> >>                    start()
>> >>                }
>> >>            }
>> >>        }
>> >>        start()
>> >>
>> >> Could have a double stop() and double start(), thus triggering the warning in
>> >> x86_pmu_start().
>> >>
>> >> Will post a patch shortly to fix this.
>> >
>> > Please send a patch against tip:master (or perf/urgent), on top
>> > of:
>> >
>> >  84f2b9b2edc0: perf: Remove deprecated WARN_ON_ONCE()
>> >
>> > Note that I updated that patch to removed one more WARN_ON()
>> > than you originally sent - please add it back as appropriate, in
>> > the delta fix patch.
>> >
>> I have already added the warning back. Will send against tip:master
>
> Great - thanks!
>
>        Ingo

Re: WARNING: at arch/x86/kernel/cpu/perf_event.c:989

[Peter Zijlstra]

On Mon, 2012-02-06 at 21:44 +0100, Stephane Eranian wrote:
> Which is pointing to the Intel specific:
> 
> intel_pmu_handle_irq()
> again:
>         intel_pmu_ack_status(status);
>         if (++loops > 100) {
>                 WARN_ONCE(1, "perfevents: irq loop stuck!\n");
>                 perf_event_print_debug();
>                 intel_pmu_reset();
>                 goto done;
>         }
> 
> We are in a constant interrupt loop for a reason I don't yet understand.
> Sure we have two counters going, bu given the callstack, one is being
> stopped.
> 
> I know we talked about that a couple of weeks back, but after all, it may
> be that it is not possible to run the frequency adjustment code without
> stopping the entire PMU because of risk of interrupts. But it is not clear
> to me what's causing this at this point.

There's Errata's on this, see AAK157 (SNB) BD106 (WSM) AAK157 (NHM).

Ingo and I talked about a 'fix' for that based on the text in the SNB
errata which explains why the reset works. Ingo I was under the
impression you were going to implement that?

> I suggest we still apply my patch to fix the x86_pmu_start() first, then
> I will submit a second patch to fix that one. Agreed? 

Yes.

Re: WARNING: at arch/x86/kernel/cpu/perf_event.c:989

[Stephane Eranian]

On Mon, Feb 6, 2012 at 9:58 PM, Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:
> On Mon, 2012-02-06 at 21:44 +0100, Stephane Eranian wrote:
>> Which is pointing to the Intel specific:
>>
>> intel_pmu_handle_irq()
>> again:
>>         intel_pmu_ack_status(status);
>>         if (++loops > 100) {
>>                 WARN_ONCE(1, "perfevents: irq loop stuck!\n");
>>                 perf_event_print_debug();
>>                 intel_pmu_reset();
>>                 goto done;
>>         }
>>
>> We are in a constant interrupt loop for a reason I don't yet understand.
>> Sure we have two counters going, bu given the callstack, one is being
>> stopped.
>>
>> I know we talked about that a couple of weeks back, but after all, it may
>> be that it is not possible to run the frequency adjustment code without
>> stopping the entire PMU because of risk of interrupts. But it is not clear
>> to me what's causing this at this point.
>
> There's Errata's on this, see AAK157 (SNB) BD106 (WSM) AAK157 (NHM).
>
Arg, I had forgotten about those.....
I'll check on this further with Intel.

> Ingo and I talked about a 'fix' for that based on the text in the SNB
> errata which explains why the reset works. Ingo I was under the
> impression you were going to implement that?
>
>> I suggest we still apply my patch to fix the x86_pmu_start() first, then
>> I will submit a second patch to fix that one. Agreed?
>
> Yes.
>