Re: IRQ behaivour has been changed from v4.14 to v4.15-rc1

[Andy Shevchenko <andriy.shevchenko@linux.intel.com>]

On Thu, 2017-12-28 at 21:18 +0100, Thomas Gleixner wrote:
> On Thu, 28 Dec 2017, Andy Shevchenko wrote:
> > On Thu, 2017-12-28 at 18:44 +0100, Thomas Gleixner wrote:
> > > On Thu, 28 Dec 2017, Andy Shevchenko wrote:
> > > > On Thu, 2017-12-28 at 18:21 +0100, Thomas Gleixner wrote:
> > > > > > [   85.167061] spurious APIC interrupt through vector ff on
> > > > > > CPU#0,
> > > > > > should never happen.
> > > > > > [   85.199886] atomisp-isp2 0000:00:03.0: stream[0] started.
> > > > > > 
> > > > > > and Ctrl+C does NOT work. Machine just hangs.
> > > > > > 
> > > > > > It might be related to this:
> > > > > > https://lkml.org/lkml/2017/12/22/697
> > > > > 
> > > > > I don't think so.
> > > > > 
> > > > > Does the patch below cure it?
> > > > 
> > > > Unfortunately, no.
> > > > 
> > > > Same behaviour.
> > > > 
> > > > Tell me if I need to provide some debug before it hangs. For now
> > > > I
> > > > have
> > > > apic=debug (AFAIR it doesn't affect this).
> > > 
> > > The interesting question is why that spurious APIC interrupt
> > > through
> > > vector
> > > ff happens. Can you please add the following to the kernel command
> > > line:
> > > 
> > >  'trace_events=irq_vectors:* ftrace_dump_on_oops'
> > > 
> > > and apply the patch below. That should spill out the trace over
> > > serial
> > > (I
> > > hope you have that ...)
> > 
> > With or without CONFIG_FUNCTION_TRACER=y I have got
> > 
> > 
> > [   28.977918] Dumping ftrace buffer:
> > [   28.988115]    (ftrace buffer empty)
> > 
> > followed by BUG() output.
> > 
> > ...
> > [   28.930154] RIP: 0010:smp_spurious_interrupt+0x67/0xb0
> > ...
> > 
> > 
> > Anything I missed?
> 
> Yes, you missed the typo in the command line. It should be:
> 
>  'trace_event=irq_vectors:* ftrace_dump_on_oops'

Indeed.

So, I had to disable LOCAL_TIMER_VECTOR, CALL_FUNCTION_VECTOR and
RESCHDULE_VECTOR tracing, otherwise I got a lot of spam and RCU stalls.

The result w/o above is (full log is available here https://pastebin.com
/J5yaTbM9):

[   38.570130]   <idle>-0       0d...    0us : vector_clear: irq=1
vector=49 cpu=0 prev_vector=0 prev_cpu=0

[   38.606969]   <idle>-0       0d...    0us : vector_reserve: irq=1
ret=0

[   38.627799]   <idle>-0       0d...    0us : vector_config: irq=1
vector=239 cpu=0 apicdest=0x00000001

[   38.665139]   <idle>-0       0....    0us : vector_setup: irq=1
is_legacy=0 ret=0

[   38.687383]   <idle>-0       0d...    0us : vector_setup: irq=0
is_legacy=1 ret=0

[   38.709354]   <idle>-0       0d...    0us : vector_config: irq=0
vector=48 cpu=0 apicdest=0x00000001

[   38.746192]   <idle>-0       0d...    0us : vector_clear: irq=3
vector=51 cpu=0 prev_vector=0 prev_cpu=0

[   38.783535]   <idle>-0       0d...    0us : vector_reserve: irq=3
ret=0

[   38.804574]   <idle>-0       0d...    0us : vector_config: irq=3
vector=239 cpu=0 apicdest=0x00000001

[   38.842397]   <idle>-0       0....    0us : vector_setup: irq=3
is_legacy=0 ret=0

...

so on up to 
[   40.329523]   <idle>-0       0d...    0us : vector_clear: irq=15
vector=63 cpu=0 prev_vector=0 prev_cpu=0

[   40.372425]   <idle>-0       0d...    0us : vector_reserve: irq=15
ret=0

[   40.396045]   <idle>-0       0d...    0us : vector_config: irq=15
vector=239 cpu=0 apicdest=0x00000001

[   40.438357]   <idle>-0       0....    0us : vector_setup: irq=15
is_legacy=0 ret=0

[   40.463002]   <idle>-0       0d...    0us : vector_deactivate: irq=0
is_managed=0 can_reserve=0 early=0

[   40.505473]   <idle>-0       0d...    0us : vector_activate: irq=0
is_managed=0 can_reserve=0 early=0


Then several times (for different tasks)

[   40.548017]  kauditd-32      0d.h. 307277us :
call_function_single_entry: vector=251

[   40.572984]  kauditd-32      0dNh. 307281us :
call_function_single_exit: vector=251

...


[   40.792078] swapper/-1       0d... 390605us : vector_activate: irq=9
is_managed=0 can_reserve=1 early=0

[   40.832953] swapper/-1       0d... 390611us : vector_update: irq=9
vector=33 cpu=0 prev_vector=0 prev_cpu=0

[   40.874548] swapper/-1       0d... 390613us : vector_alloc: irq=9
vector=33 reserved=1 ret=0

[   40.899551] swapper/-1       0d... 390614us : vector_config: irq=9
vector=33 cpu=0 apicdest=0x00000001

[   40.940771] swapper/-1       0d... 390620us : vector_config: irq=9
vector=33 cpu=0 apicdest=0x00000001

...

For irq=24-29, 47, 49:


[   41.071806] swapper/-1       1d... 989092us : vector_reserve: irq=24
ret=0

[   41.088297] swapper/-1       1d... 989096us : vector_config: irq=24
vector=239 cpu=0 apicdest=0x00000001

[   41.125772] swapper/-1       1.... 989097us : vector_setup: irq=24
is_legacy=0 ret=0

...

[   48.242842]     mdev-1450    3d.h. 20327793us :
call_function_single_entry: vector=251

[   48.269120]     mdev-1450    3d.h. 20327800us :
call_function_single_exit: vector=251

[   48.295319] modprobe-1348    0d... 20444228us : vector_activate:
irq=42 is_managed=0 can_reserve=1 early=0

[   48.341248] modprobe-1348    0d... 20444235us : vector_update: irq=42
vector=52 cpu=0 prev_vector=0 prev_cpu=0

[   48.387914] modprobe-1348    0d... 20444237us : vector_alloc: irq=42
vector=52 reserved=1 ret=0

[   48.415547] modprobe-1348    0d... 20444238us : vector_config: irq=42
vector=52 cpu=0 apicdest=0x00000001

[   48.461465] modprobe-1348    0d... 20444243us : vector_config: irq=42
vector=52 cpu=0 apicdest=0x00000001

[   48.507688] modprobe-1348    0d... 20484235us : vector_activate:
irq=43 is_managed=0 can_reserve=1 early=0

[   48.554044] modprobe-1348    0d... 20484241us : vector_update: irq=43
vector=53 cpu=0 prev_vector=0 prev_cpu=0

[   48.600812] modprobe-1348    0d... 20484243us : vector_alloc: irq=43
vector=53 reserved=1 ret=0

[   48.628494] modprobe-1348    0d... 20484244us : vector_config: irq=43
vector=53 cpu=0 apicdest=0x00000001

[   48.674508] modprobe-1348    0d... 20484248us : vector_config: irq=43
vector=53 cpu=0 apicdest=0x00000001

[   48.720830]   <idle>-0       1d.h. 20591763us :
call_function_single_entry: vector=251

[   48.747573]   <idle>-0       1d.h. 20591768us :
call_function_single_exit: vector=251

[   48.774025] modprobe-1348    1d... 20831415us : vector_reserve:
irq=150 ret=0

[   48.799631] modprobe-1348    1d... 20831419us : vector_config:
irq=150 vector=239 cpu=0 apicdest=0x00000001

[   48.845791] modprobe-1348    1.... 20831420us : vector_setup: irq=150
is_legacy=0 ret=0

[   48.872515] modprobe-1348    1.... 20831427us : vector_activate:
irq=150 is_managed=0 can_reserve=1 early=1

[   48.918432] modprobe-1348    1d... 20831428us : vector_config:
irq=150 vector=239 cpu=0 apicdest=0x00000001

[   48.964534] modprobe-1348    1d... 21152409us : vector_activate:
irq=150 is_managed=0 can_reserve=1 early=0

[   49.010805] modprobe-1348    1d... 21152415us : vector_update:
irq=150 vector=54 cpu=0 prev_vector=0 prev_cpu=0

[   49.057553] modprobe-1348    1d... 21152417us : vector_alloc: irq=150
vector=54 reserved=1 ret=0

[   49.085503] modprobe-1348    1d... 21152418us : vector_config:
irq=150 vector=54 cpu=0 apicdest=0x00000001

[   49.132545] modprobe-1348    1d... 21152428us : vector_config:
irq=150 vector=54 cpu=0 apicdest=0x00000001

[   49.180426]   <idle>-0       2d.h. 21227397us :
call_function_single_entry: vector=251

[   49.208066]   <idle>-0       2d.h. 21227403us :
call_function_single_exit: vector=251

[   49.235397]   <idle>-0       3d.h. 21229548us :
call_function_single_entry: vector=251

[   49.262625]   <idle>-0       3d.h. 21229551us :
call_function_single_exit: vector=251

[   49.289544]   <idle>-0       0d.h. 21231514us :
call_function_single_entry: vector=251

[   49.316365]   <idle>-0       0d.h. 21231519us :
call_function_single_exit: vector=251

[   49.343015]   <idle>-0       1d.h. 21238805us :
call_function_single_entry: vector=251

[   49.369550]   <idle>-0       1d.h. 21238809us :
call_function_single_exit: vector=251

[   49.395774]   <idle>-0       3d.h. 24735137us :
call_function_single_entry: vector=251

[   49.421902]   <idle>-0       3d.h. 24735143us :
call_function_single_exit: vector=251

[   49.447720]   <idle>-0       0d.h. 38913766us : spurious_apic_entry:
vector=255





-- 
Andy Shevchenko <andriy.shevchenko@linux.intel.com>
Intel Finland Oy