Re: IRQ behaivour has been changed from v4.14 to v4.15-rc1
From: Andy Shevchenko
Date: Thu Dec 28 2017 - 16:05:24 EST
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@xxxxxxxxxxxxxxx>
Intel Finland Oy