2019-06-20 02:19:47

by Chen, Rong A

[permalink] [raw]
Subject: [x86/hotplug] e1056a25da: WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC

FYI, we noticed the following commit (built with gcc-7):

commit: e1056a25daa6460c95e92d7d6853d05ad62458f7 ("x86/hotplug: Silence APIC and NMI when CPU is dead")
https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git WIP.x86/ipi

in testcase: locktorture
with following parameters:

runtime: 300s
test: cpuhotplug

test-description: This torture test consists of creating a number of kernel threads which acquire the lock and hold it for specific amount of time, thus simulating different critical region behaviors.
test-url: https://www.kernel.org/doc/Documentation/locking/locktorture.txt


on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 2G

caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):


+----------------------------------------------------------+------------+------------+
| | c1257b49b9 | e1056a25da |
+----------------------------------------------------------+------------+------------+
| boot_successes | 8 | 6 |
| boot_failures | 51 | 48 |
| BUG:kernel_reboot-without-warning_in_test_stage | 50 | 22 |
| BUG:soft_lockup-CPU##stuck_for#s | 1 | |
| RIP:__memcpy | 1 | |
| Kernel_panic-not_syncing:softlockup:hung_tasks | 1 | |
| WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC | 0 | 26 |
| RIP:setup_local_APIC | 0 | 26 |
+----------------------------------------------------------+------------+------------+


If you fix the issue, kindly add following tag
Reported-by: kernel test robot <[email protected]>


[ 216.682229] WARNING: CPU: 0 PID: 0 at arch/x86/kernel/apic/apic.c:1473 setup_local_APIC+0x250/0x3b0
[ 216.724190] Modules linked in: locktorture torture sr_mod cdrom ata_generic pata_acpi bochs_drm ttm ppdev drm_kms_helper ata_piix syscopyarea snd_pcm sysfillrect sysimgblt libata fb_sys_fops snd_timer snd drm crc32c_intel soundcore joydev serio_raw pcspkr i2c_piix4 parport_pc parport floppy
[ 216.771348] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.2.0-rc5-00003-ge1056a2 #1
[ 216.785027] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 216.800351] RIP: 0010:setup_local_APIC+0x250/0x3b0
[ 216.809104] Code: 30 8b 0d eb 78 7d 01 85 c9 74 26 0f 31 c1 e1 0a 48 c1 e2 20 41 89 ce 4c 03 34 24 48 09 d0 49 29 c6 4d 85 f6 0f 8f 74 fe ff ff <0f> 0b e9 22 ff ff ff 49 83 ee 01 eb ea a9 00 00 01 00 8b 15 2c ac
[ 216.843098] RSP: 0000:ffffffff89a03ee0 EFLAGS: 00010082
[ 216.852617] RAX: 00000076a573f693 RBX: 0000000000000020 RCX: 0000000089ff6800
[ 216.865848] RDX: 0000007600000000 RSI: 0000000000000020 RDI: ffffffff89a03ef0
[ 216.878971] RBP: 0000000000000000 R08: ffffffff8a348de2 R09: 0000000000000032
[ 216.892080] R10: ffffffff89a03ee8 R11: 0000000000000000 R12: 00000000000000f0
[ 216.905019] R13: 0000000000001000 R14: fffffffffffc1cfb R15: 0000000000000000
[ 216.918205] FS: 0000000000000000(0000) GS:ffff89af74800000(0000) knlGS:0000000000000000
[ 216.941317] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 216.951812] CR2: 0000000057567184 CR3: 000000000ba0a000 CR4: 00000000000006f0
[ 216.964997] Call Trace:
[ 216.969667] apic_ap_setup+0xa/0x20
[ 216.976266] start_secondary+0x78/0x1e0
[ 216.983423] secondary_startup_64+0xb6/0xc0
[ 216.991271] ---[ end trace 06172ec0274b1dfa ]---


To reproduce:

# build kernel
cd linux
cp config-5.2.0-rc5-00003-ge1056a2 .config
make HOSTCC=gcc-7 CC=gcc-7 ARCH=x86_64 olddefconfig
make HOSTCC=gcc-7 CC=gcc-7 ARCH=x86_64 prepare
make HOSTCC=gcc-7 CC=gcc-7 ARCH=x86_64 modules_prepare
make HOSTCC=gcc-7 CC=gcc-7 ARCH=x86_64 SHELL=/bin/bash
make HOSTCC=gcc-7 CC=gcc-7 ARCH=x86_64 bzImage


git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
find lib/ | cpio -o -H newc --quiet | gzip > modules.cgz
bin/lkp qemu -k <bzImage> -m modules.cgz job-script # job-script is attached in this email




Thanks,
Rong Chen


Attachments:
(No filename) (4.27 kB)
config-5.2.0-rc5-00003-ge1056a2 (199.69 kB)
job-script (4.58 kB)
dmesg.xz (15.21 kB)
locktorture (2.70 kB)
Download all attachments

2019-06-21 19:10:38

by Thomas Gleixner

[permalink] [raw]
Subject: Re: [x86/hotplug] e1056a25da: WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC

On Thu, 20 Jun 2019, kernel test robot wrote:

> FYI, we noticed the following commit (built with gcc-7):
>
> commit: e1056a25daa6460c95e92d7d6853d05ad62458f7 ("x86/hotplug: Silence APIC and NMI when CPU is dead")
> https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git WIP.x86/ipi
>
> in testcase: locktorture
> with following parameters:
>
> runtime: 300s
> test: cpuhotplug
>
> test-description: This torture test consists of creating a number of kernel threads which acquire the lock and hold it for specific amount of time, thus simulating different critical region behaviors.
> test-url: https://www.kernel.org/doc/Documentation/locking/locktorture.txt
>
>
> on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 2G

I cannot reproduce that issue. What's the underlying hardware machine?

Thanks,

tglx

2019-06-25 04:09:45

by Chen, Rong A

[permalink] [raw]
Subject: Re: [x86/hotplug] e1056a25da: WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC

On 6/22/19 3:08 AM, Thomas Gleixner wrote:
> On Thu, 20 Jun 2019, kernel test robot wrote:
>
>> FYI, we noticed the following commit (built with gcc-7):
>>
>> commit: e1056a25daa6460c95e92d7d6853d05ad62458f7 ("x86/hotplug: Silence APIC and NMI when CPU is dead")
>> https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git WIP.x86/ipi
>>
>> in testcase: locktorture
>> with following parameters:
>>
>> runtime: 300s
>> test: cpuhotplug
>>
>> test-description: This torture test consists of creating a number of kernel threads which acquire the lock and hold it for specific amount of time, thus simulating different critical region behaviors.
>> test-url: https://www.kernel.org/doc/Documentation/locking/locktorture.txt
>>
>>
>> on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 2G
> I cannot reproduce that issue. What's the underlying hardware machine?

brand: Genuine Intel(R) CPU 000 @ 2.27GHz
model: Westmere-EX
memory: 256G
nr_node: 4
nr_cpu: 80

Best Regards,
Rong Chen


>
> Thanks,
>
> tglx

2019-06-25 07:39:31

by Thomas Gleixner

[permalink] [raw]
Subject: Re: [x86/hotplug] e1056a25da: WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC

Rong,

On Tue, 25 Jun 2019, Rong Chen wrote:
> On 6/22/19 3:08 AM, Thomas Gleixner wrote:
> > >
> > > on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m
> > > 2G
> > I cannot reproduce that issue. What's the underlying hardware machine?
>
> brand: Genuine Intel(R) CPU 000 @ 2.27GHz
> model: Westmere-EX
> memory: 256G
> nr_node: 4
> nr_cpu: 80

Ok. I'll try to find something similar. Can please you rerun that test on
that particular configuration with the updated branch?

git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git WIP.x86/ipi

please?

Thanks,

tglx

2019-06-25 08:41:21

by Chen, Rong A

[permalink] [raw]
Subject: Re: [LKP] [x86/hotplug] e1056a25da: WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC

On 6/25/19 2:24 PM, Thomas Gleixner wrote:
> Rong,
>
> On Tue, 25 Jun 2019, Rong Chen wrote:
>> On 6/22/19 3:08 AM, Thomas Gleixner wrote:
>>>> on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m
>>>> 2G
>>> I cannot reproduce that issue. What's the underlying hardware machine?
>> brand: Genuine Intel(R) CPU 000 @ 2.27GHz
>> model: Westmere-EX
>> memory: 256G
>> nr_node: 4
>> nr_cpu: 80
> Ok. I'll try to find something similar. Can please you rerun that test on
> that particular configuration with the updated branch?
>
> git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git WIP.x86/ipi
>
Hi tglx,

I have tested commit e0b179bc1a ("x86/apic/x2apic: Add conditional IPI
shorthands support"), the problem is still exist.

Best Regards,
Rong Chen


Attachments:
dmesg.xz (14.85 kB)

2019-06-25 13:05:31

by Thomas Gleixner

[permalink] [raw]
Subject: Re: [LKP] [x86/hotplug] e1056a25da: WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC

Rong,

On Tue, 25 Jun 2019, Rong Chen wrote:
> On 6/25/19 2:24 PM, Thomas Gleixner wrote:
> > > On 6/22/19 3:08 AM, Thomas Gleixner wrote:
> > > > > on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp
> > > > > 2 -m
> > > > > 2G
> > > > I cannot reproduce that issue. What's the underlying hardware machine?
> > > brand: Genuine Intel(R) CPU 000 @ 2.27GHz
> > > model: Westmere-EX
> > > memory: 256G
> > > nr_node: 4
> > > nr_cpu: 80
> > Ok. I'll try to find something similar. Can please you rerun that test on
> > that particular configuration with the updated branch?
> >
> > git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git WIP.x86/ipi
> >
> I have tested commit e0b179bc1a ("x86/apic/x2apic: Add conditional IPI
> shorthands support"), the problem is still exist.

the head of that branch is:

4f3f6d6a7f8e ("x86/apic/x2apic: Add conditional IPI shorthands support")

This is WIP and force pushed. There are no incremental changes. Could you
please check again?

Thanks,

tglx

2019-06-26 01:20:07

by Chen, Rong A

[permalink] [raw]
Subject: Re: [LKP] [x86/hotplug] e1056a25da: WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC

On 6/25/19 7:32 PM, Thomas Gleixner wrote:
> Rong,
>
> On Tue, 25 Jun 2019, Rong Chen wrote:
>> On 6/25/19 2:24 PM, Thomas Gleixner wrote:
>>>> On 6/22/19 3:08 AM, Thomas Gleixner wrote:
>>>>>> on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp
>>>>>> 2 -m
>>>>>> 2G
>>>>> I cannot reproduce that issue. What's the underlying hardware machine?
>>>> brand: Genuine Intel(R) CPU 000 @ 2.27GHz
>>>> model: Westmere-EX
>>>> memory: 256G
>>>> nr_node: 4
>>>> nr_cpu: 80
>>> Ok. I'll try to find something similar. Can please you rerun that test on
>>> that particular configuration with the updated branch?
>>>
>>> git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git WIP.x86/ipi
>>>
>> I have tested commit e0b179bc1a ("x86/apic/x2apic: Add conditional IPI
>> shorthands support"), the problem is still exist.
> the head of that branch is:
>
> 4f3f6d6a7f8e ("x86/apic/x2apic: Add conditional IPI shorthands support")
>
> This is WIP and force pushed. There are no incremental changes. Could you
> please check again?

The problem is still exist.

Best Regards,
Rong Chen


>
> Thanks,
>
> tglx
> _______________________________________________
> LKP mailing list
> [email protected]
> https://lists.01.org/mailman/listinfo/lkp


Attachments:
dmesg.xz (14.98 kB)

2019-06-27 14:28:09

by Thomas Gleixner

[permalink] [raw]
Subject: Re: [LKP] [x86/hotplug] e1056a25da: WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC

Rong, Fengguang,

On Wed, 26 Jun 2019, Rong Chen wrote:
> On 6/25/19 7:32 PM, Thomas Gleixner wrote:
> > > I have tested commit e0b179bc1a ("x86/apic/x2apic: Add conditional IPI
> > > shorthands support"), the problem is still exist.
> > the head of that branch is:
> >
> > 4f3f6d6a7f8e ("x86/apic/x2apic: Add conditional IPI shorthands
> > support")
> >
> > This is WIP and force pushed. There are no incremental changes. Could you
> > please check again?
>
> The problem is still exist.

I went through hoops and loops to get that lkp muck running, but as many
different machines I tried on it never reproduced.

So I need a bit of help from you folks. Can you please provide me:

1) The exact host kernel version
2) The config file
3) The exact kvm-qemu version

Also it would be interesting whether 4f3f6d6a7f8e from that WIP.x86/ipi
branch in tip has the same issue on other host machines.

Another data point would be whether it depends on a particular compiler
version.

Thanks in advance,

tglx

P.S: the instructions for reproducing the issue in that robot mail are
incomplete because there is no information how to bring the module into
that initrd... I somehow figured it out.

2019-06-28 06:34:11

by Feng Tang

[permalink] [raw]
Subject: Re: [LKP] [x86/hotplug] e1056a25da: WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC

Hi Thomas,

On Tue, Jun 25, 2019 at 07:32:03PM +0800, Thomas Gleixner wrote:
> Rong,
>
> On Tue, 25 Jun 2019, Rong Chen wrote:
> > On 6/25/19 2:24 PM, Thomas Gleixner wrote:
> > > > On 6/22/19 3:08 AM, Thomas Gleixner wrote:
> > > > > > on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp
> > > > > > 2 -m
> > > > > > 2G
> > > > > I cannot reproduce that issue. What's the underlying hardware machine?
> > > > brand: Genuine Intel(R) CPU 000 @ 2.27GHz
> > > > model: Westmere-EX
> > > > memory: 256G
> > > > nr_node: 4
> > > > nr_cpu: 80
> > > Ok. I'll try to find something similar. Can please you rerun that test on
> > > that particular configuration with the updated branch?
> > >
> > > git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git WIP.x86/ipi
> > >
> > I have tested commit e0b179bc1a ("x86/apic/x2apic: Add conditional IPI
> > shorthands support"), the problem is still exist.
>
> the head of that branch is:
>
> 4f3f6d6a7f8e ("x86/apic/x2apic: Add conditional IPI shorthands support")
>
> This is WIP and force pushed. There are no incremental changes. Could you
> please check again?

Since you can't reproduce it yet, we've added some debug hook to get more
info, like dmesg below:

[ 288.865969] kvm-clock: cpu 0, msr 6d201001, secondary cpu clock
[ 288.866069] IRR[7]: 0x1000
[ 289.890274] WARNING: CPU: 0 PID: 0 at arch/x86/kernel/apic/apic.c:1502 setup_local_APIC+0x2d1/0x4f0
[ 289.911792] Modules linked in: locktorture torture sr_mod cdrom ata_generic pata_acpi bochs_drm ppdev ttm ata_piix drm_kms_helper snd_pcm libata syscopyarea sysfillrect snd_timer snd sysimgblt soundcore fb_sys_fops joydev crc32c_intel drm serio_raw pcspkr parport_pc i2c_piix4 floppy parport
[ 289.959629] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.2.0-rc5-00493-g1965704 #1
[ 289.975340] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 289.990568] RIP: 0010:setup_local_APIC+0x2d1/0x4f0
[ 290.000361] Code: 7a 7d 01 85 c9 0f 84 a9 00 00 00 0f 31 c1 e1 0a 48 c1 e2 20 41 89 ce 4c 03 34 24 48 09 d0 49 29 c6 4d 85 f6 0f 8f a1 fe ff ff <0f> 0b 48 c7 c7 09 08 cc 8e 89 ea 44 89 ee bb 07 00 00 00 48 c7 c5
[ 290.035653] RSP: 0000:ffffffff8f003ee0 EFLAGS: 00010086
[ 290.044854] RAX: 0000009c7aa7aeb4 RBX: 0000000000000020 RCX: 000000008a001800
[ 290.057690] RDX: 0000009c00000000 RSI: 0000000000000020 RDI: ffffffff8f003ef0
[ 290.070711] RBP: 0000000000000000 R08: 0000000000000341 R09: 000000000000001d
[ 290.083680] R10: ffff943bcf49b740 R11: ffffffff8f003d90 R12: 00000000000000f0
[ 290.096414] R13: 0000000000001000 R14: fffffffffffc581b R15: 0000000000000000
[ 290.109369] FS: 0000000000000000(0000) GS:ffff943c32400000(0000) knlGS:0000000000000000
[ 290.124123] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 290.134558] CR2: 00000000f7ec7710 CR3: 000000006c60a000 CR4: 00000000000006f0
[ 290.147451] Call Trace:
[ 290.152154] apic_ap_setup+0xa/0x20
[ 290.158663] start_secondary+0x78/0x1e0
[ 290.165411] secondary_startup_64+0xb6/0xc0
[ 290.173158] ---[ end trace bfefeb8bcdb1b9e3 ]---
[ 290.182418] queued = 0x1000 acked = 0
[ 290.189159] IRR[7]: 0x1000

Which shows the IRR[7] was set 0x1000, IIUC, it means vector
0xec, which is for LAPIC timer, and ISRs are all 0 before and
after the loop.


The debug code is as follows:
diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
index 197a150..38e0851 100644
--- a/arch/x86/kernel/apic/apic.c
+++ b/arch/x86/kernel/apic/apic.c
@@ -1447,6 +1447,22 @@ static void apic_pending_intr_clear(void)

if (boot_cpu_has(X86_FEATURE_TSC))
tsc = rdtsc();
+
+ {
+ for (i = APIC_ISR_NR - 1; i >= 0; i--) {
+ queued = apic_read(APIC_IRR + i*0x10);
+
+ if (queued)
+ printk("IRR[%d]: 0x%x\n", i, queued);
+ }
+
+ for (i = APIC_ISR_NR - 1; i >= 0; i--) {
+ value = apic_read(APIC_ISR + i*0x10);
+ if (value)
+ printk("ISR[%d]: 0x%lx\n", i, value);
+ }
+ }
+
/*
* After a crash, we no longer service the interrupts and a pending
* interrupt from previous kernel might still have ISR bit set.
@@ -1484,6 +1500,25 @@ static void apic_pending_intr_clear(void)
}
} while (queued && max_loops > 0);
WARN_ON(max_loops <= 0);
+
+ if (max_loops <= 0) {
+ printk("queued = 0x%x acked = %d\n", queued, acked);
+
+ queued = 0;
+ for (i = APIC_ISR_NR - 1; i >= 0; i--) {
+ queued = apic_read(APIC_IRR + i*0x10);
+
+ if (queued)
+ printk("IRR[%d]: 0x%x\n", i, queued);
+ }
+
+ for (i = APIC_ISR_NR - 1; i >= 0; i--) {
+ value = apic_read(APIC_ISR + i*0x10);
+ if (value)
+ printk("ISR[%d]: 0x%lx\n", i, value);
+
+ }
+ }
}

/**


Thanks,
Feng

2019-06-28 08:53:12

by Chen, Rong A

[permalink] [raw]
Subject: Re: [LKP] [x86/hotplug] e1056a25da: WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC

On 6/27/19 10:26 PM, Thomas Gleixner wrote:
> Rong, Fengguang,
>
> On Wed, 26 Jun 2019, Rong Chen wrote:
>> On 6/25/19 7:32 PM, Thomas Gleixner wrote:
>>>> I have tested commit e0b179bc1a ("x86/apic/x2apic: Add conditional IPI
>>>> shorthands support"), the problem is still exist.
>>> the head of that branch is:
>>>
>>> 4f3f6d6a7f8e ("x86/apic/x2apic: Add conditional IPI shorthands
>>> support")
>>>
>>> This is WIP and force pushed. There are no incremental changes. Could you
>>> please check again?
>> The problem is still exist.
> I went through hoops and loops to get that lkp muck running, but as many
> different machines I tried on it never reproduced.
>
> So I need a bit of help from you folks. Can you please provide me:
>
> 1) The exact host kernel version
# uname -r
4.20.0


> 2) The config file

attached ("config-5.2.0-rc5-00003-ge1056a2")


> 3) The exact kvm-qemu version

# qemu-system-x86_64 --version
QEMU emulator version 3.1.0 (Debian 1:3.1+dfsg-8)
Copyright (c) 2003-2018 Fabrice Bellard and the QEMU Project developers


>
> Also it would be interesting whether 4f3f6d6a7f8e from that WIP.x86/ipi
> branch in tip has the same issue on other host machines.

yes. it has the same issue.


>
> Another data point would be whether it depends on a particular compiler
> version.

the issue could be reproduced too when built with gcc-8


>
> Thanks in advance,
>
> tglx
>
> P.S: the instructions for reproducing the issue in that robot mail are
> incomplete because there is no information how to bring the module into
> that initrd... I somehow figured it out.

Thanks for the input, we'll improve the tips.

Best Regards,
Rong Chen


Attachments:
config-5.2.0-rc5-00003-ge1056a2 (191.79 kB)

2019-06-28 09:19:46

by Thomas Gleixner

[permalink] [raw]
Subject: Re: [LKP] [x86/hotplug] e1056a25da: WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC

Feng,

On Fri, 28 Jun 2019, Feng Tang wrote:
> On Tue, Jun 25, 2019 at 07:32:03PM +0800, Thomas Gleixner wrote:
> > the head of that branch is:
> >
> > 4f3f6d6a7f8e ("x86/apic/x2apic: Add conditional IPI shorthands support")
> >
> > This is WIP and force pushed. There are no incremental changes. Could you
> > please check again?
>
> Since you can't reproduce it yet, we've added some debug hook to get more
> info, like dmesg below:
>
> [ 288.866069] IRR[7]: 0x1000
> [ 289.890274] WARNING: CPU: 0 PID: 0 at arch/x86/kernel/apic/apic.c:1502 setup_local_APIC+0x2d1/0x4f0

> [ 290.182418] queued = 0x1000 acked = 0
> [ 290.189159] IRR[7]: 0x1000
>
> Which shows the IRR[7] was set 0x1000, IIUC, it means vector
> 0xec, which is for LAPIC timer, and ISRs are all 0 before and
> after the loop.

Ahhhh. That makes a lot of sense now.

That interrupt is in the IRR, but not in the ISR. So the acknowledge
attempts are useless because the ack only clears an pending ISR and the IRR
is not propagated because in the state in which this happens the entry is
masked.

That function just 'works' by chance not by design. I'll stare into it and
fix it up for real.

Thank you very much for that information. Your debug was spot on!

tglx

2019-06-29 07:16:56

by Thomas Gleixner

[permalink] [raw]
Subject: Re: [LKP] [x86/hotplug] e1056a25da: WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC

Feng,

On Fri, 28 Jun 2019, Thomas Gleixner wrote:
> On Fri, 28 Jun 2019, Feng Tang wrote:
> > On Tue, Jun 25, 2019 at 07:32:03PM +0800, Thomas Gleixner wrote:
> > > the head of that branch is:
> > >
> > > 4f3f6d6a7f8e ("x86/apic/x2apic: Add conditional IPI shorthands support")
> > >
> > > This is WIP and force pushed. There are no incremental changes. Could you
> > > please check again?
> >
> > Since you can't reproduce it yet, we've added some debug hook to get more
> > info, like dmesg below:
> >
> > [ 288.866069] IRR[7]: 0x1000
> > [ 289.890274] WARNING: CPU: 0 PID: 0 at arch/x86/kernel/apic/apic.c:1502 setup_local_APIC+0x2d1/0x4f0
>
> > [ 290.182418] queued = 0x1000 acked = 0
> > [ 290.189159] IRR[7]: 0x1000
> >
> > Which shows the IRR[7] was set 0x1000, IIUC, it means vector
> > 0xec, which is for LAPIC timer, and ISRs are all 0 before and
> > after the loop.
>
> Ahhhh. That makes a lot of sense now.
>
> That interrupt is in the IRR, but not in the ISR. So the acknowledge
> attempts are useless because the ack only clears an pending ISR and the IRR
> is not propagated because in the state in which this happens the entry is
> masked.
>
> That function just 'works' by chance not by design. I'll stare into it and
> fix it up for real.
>
> Thank you very much for that information. Your debug was spot on!

I rewrote that function so it actually handles that case correctly along
with some other things which were broken and force pushed the WIP.x86/ipi
branch.

Can you please run exactly that test again against that new version and
verify that this is fixed now?

Thanks,

tglx

2019-06-30 11:37:58

by Thomas Gleixner

[permalink] [raw]
Subject: Re: [LKP] [x86/hotplug] e1056a25da: WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC

On Sat, 29 Jun 2019, Thomas Gleixner wrote:
> On Fri, 28 Jun 2019, Thomas Gleixner wrote:
> > On Fri, 28 Jun 2019, Feng Tang wrote:
> > That function just 'works' by chance not by design. I'll stare into it and
> > fix it up for real.
> >
> > Thank you very much for that information. Your debug was spot on!
>
> I rewrote that function so it actually handles that case correctly along
> with some other things which were broken and force pushed the WIP.x86/ipi
> branch.
>
> Can you please run exactly that test again against that new version and
> verify that this is fixed now?

Just found another issue with that thing. Don't waste your time on it. I'll
come back to you when I'm done.

Thanks,

tglx

2019-06-30 13:04:17

by Feng Tang

[permalink] [raw]
Subject: Re: [LKP] [x86/hotplug] e1056a25da: WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC

Hi Thomas,

On Sun, Jun 30, 2019 at 01:35:39PM +0200, Thomas Gleixner wrote:
> On Sat, 29 Jun 2019, Thomas Gleixner wrote:
> > On Fri, 28 Jun 2019, Thomas Gleixner wrote:
> > > On Fri, 28 Jun 2019, Feng Tang wrote:
> > > That function just 'works' by chance not by design. I'll stare into it and
> > > fix it up for real.
> > >
> > > Thank you very much for that information. Your debug was spot on!
> >
> > I rewrote that function so it actually handles that case correctly along
> > with some other things which were broken and force pushed the WIP.x86/ipi
> > branch.
> >
> > Can you please run exactly that test again against that new version and
> > verify that this is fixed now?
>
> Just found another issue with that thing. Don't waste your time on it. I'll
> come back to you when I'm done.

Ok. I noticed that the ipi branch has been merged to tip/master.

Thanks,
Feng

>
> Thanks,
>
> tglx

2019-06-30 18:25:19

by Thomas Gleixner

[permalink] [raw]
Subject: Re: [LKP] [x86/hotplug] e1056a25da: WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC

On Sun, 30 Jun 2019, Feng Tang wrote:
> On Sun, Jun 30, 2019 at 01:35:39PM +0200, Thomas Gleixner wrote:
> > On Sat, 29 Jun 2019, Thomas Gleixner wrote:
> > > On Fri, 28 Jun 2019, Thomas Gleixner wrote:
> > > > On Fri, 28 Jun 2019, Feng Tang wrote:
> > > > That function just 'works' by chance not by design. I'll stare into it and
> > > > fix it up for real.
> > > >
> > > > Thank you very much for that information. Your debug was spot on!
> > >
> > > I rewrote that function so it actually handles that case correctly along
> > > with some other things which were broken and force pushed the WIP.x86/ipi
> > > branch.
> > >
> > > Can you please run exactly that test again against that new version and
> > > verify that this is fixed now?
> >
> > Just found another issue with that thing. Don't waste your time on it. I'll
> > come back to you when I'm done.
>
> Ok. I noticed that the ipi branch has been merged to tip/master.

Yes, but it will be zapped there as well.

Thanks,

tglx

2019-07-01 07:50:18

by Thomas Gleixner

[permalink] [raw]
Subject: Re: [LKP] [x86/hotplug] e1056a25da: WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC

Feng,

On Sun, 30 Jun 2019, Thomas Gleixner wrote:
> On Sun, 30 Jun 2019, Feng Tang wrote:
> > On Sun, Jun 30, 2019 at 01:35:39PM +0200, Thomas Gleixner wrote:
> > > On Sat, 29 Jun 2019, Thomas Gleixner wrote:
> > > > On Fri, 28 Jun 2019, Thomas Gleixner wrote:
> > > > > On Fri, 28 Jun 2019, Feng Tang wrote:
> > > > > That function just 'works' by chance not by design. I'll stare into it and
> > > > > fix it up for real.
> > > > >
> > > > > Thank you very much for that information. Your debug was spot on!
> > > >
> > > > I rewrote that function so it actually handles that case correctly along
> > > > with some other things which were broken and force pushed the WIP.x86/ipi
> > > > branch.
> > > >
> > > > Can you please run exactly that test again against that new version and
> > > > verify that this is fixed now?
> > >
> > > Just found another issue with that thing. Don't waste your time on it. I'll
> > > come back to you when I'm done.
> >
> > Ok. I noticed that the ipi branch has been merged to tip/master.
>
> Yes, but it will be zapped there as well.

In case you still have your debug version (that old tree which triggered
the warn) around, could you please run that again and add

'lapic=notscdeadline'

to the kernel command line please?

Thanks,

tglx

2019-07-01 09:14:09

by Feng Tang

[permalink] [raw]
Subject: Re: [LKP] [x86/hotplug] e1056a25da: WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC

Hi Thomas,

On Mon, Jul 01, 2019 at 09:13:54AM +0200, Thomas Gleixner wrote:
> Feng,
>
> On Sun, 30 Jun 2019, Thomas Gleixner wrote:
> > On Sun, 30 Jun 2019, Feng Tang wrote:
> > > On Sun, Jun 30, 2019 at 01:35:39PM +0200, Thomas Gleixner wrote:
> > > > On Sat, 29 Jun 2019, Thomas Gleixner wrote:
> > > > > On Fri, 28 Jun 2019, Thomas Gleixner wrote:
> > > > > > On Fri, 28 Jun 2019, Feng Tang wrote:
> > > > > > That function just 'works' by chance not by design. I'll stare into it and
> > > > > > fix it up for real.
> > > > > >
> > > > > > Thank you very much for that information. Your debug was spot on!
> > > > >
> > > > > I rewrote that function so it actually handles that case correctly along
> > > > > with some other things which were broken and force pushed the WIP.x86/ipi
> > > > > branch.
> > > > >
> > > > > Can you please run exactly that test again against that new version and
> > > > > verify that this is fixed now?
> > > >
> > > > Just found another issue with that thing. Don't waste your time on it. I'll
> > > > come back to you when I'm done.
> > >
> > > Ok. I noticed that the ipi branch has been merged to tip/master.
> >
> > Yes, but it will be zapped there as well.
>
> In case you still have your debug version (that old tree which triggered
> the warn) around, could you please run that again and add
>
> 'lapic=notscdeadline'
>
> to the kernel command line please?

After adding the boot paramter, the result is the same. The dmesg is attached.

Thanks,
Feng


Attachments:
(No filename) (1.51 kB)
dmesg.xz (15.13 kB)
Download all attachments

2019-07-01 09:26:47

by Thomas Gleixner

[permalink] [raw]
Subject: Re: [LKP] [x86/hotplug] e1056a25da: WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC

Feng,

On Mon, 1 Jul 2019, Feng Tang wrote:
> On Mon, Jul 01, 2019 at 09:13:54AM +0200, Thomas Gleixner wrote:
> > On Sun, 30 Jun 2019, Thomas Gleixner wrote:
> > In case you still have your debug version (that old tree which triggered
> > the warn) around, could you please run that again and add
> >
> > 'lapic=notscdeadline'
> >
> > to the kernel command line please?
>
> After adding the boot paramter, the result is the same. The dmesg is attached.

thanks for running that. I'm still puzzled by this.

I've updated my machine to roughly match your setup but I'm still unable to
reproduce.

Is there anything special on the host kernel configuration? Can you provide
me that please?

Thanks,

tglx


2019-07-01 10:54:15

by Chen, Rong A

[permalink] [raw]
Subject: Re: [LKP] [x86/hotplug] e1056a25da: WARNING:at_arch/x86/kernel/apic/apic.c:#setup_local_APIC

On 7/1/19 5:26 PM, Thomas Gleixner wrote:
> Feng,
>
> On Mon, 1 Jul 2019, Feng Tang wrote:
>> On Mon, Jul 01, 2019 at 09:13:54AM +0200, Thomas Gleixner wrote:
>>> On Sun, 30 Jun 2019, Thomas Gleixner wrote:
>>> In case you still have your debug version (that old tree which triggered
>>> the warn) around, could you please run that again and add
>>>
>>> 'lapic=notscdeadline'
>>>
>>> to the kernel command line please?
>> After adding the boot paramter, the result is the same. The dmesg is attached.
> thanks for running that. I'm still puzzled by this.
>
> I've updated my machine to roughly match your setup but I'm still unable to
> reproduce.
>
> Is there anything special on the host kernel configuration? Can you provide
> me that please?

Hi Thomas,

Attached please find the kconfig of host kernel.

Best Regards,
Rong Chen


Attachments:
config-4.20.0 (164.18 kB)

2019-07-01 22:42:53

by Thomas Gleixner

[permalink] [raw]
Subject: [BUG] kvm: APIC emulation problem - was Re: [LKP] [x86/hotplug] ...

Folks,

after chasing a 0-day test failure for a couple of days, I was finally able
to reproduce the issue.

Background:

In preparation of supporting IPI shorthands I changed the CPU offline
code to software disable the local APIC instead of just masking it.
That's done by clearing the APIC_SPIV_APIC_ENABLED bit in the APIC_SPIV
register.

Failure:

When the CPU comes back online the startup code triggers occasionally
the warning in apic_pending_intr_clear(). That complains that the IRRs
are not empty.

The offending vector is the local APIC timer vector who's IRR bit is set
and stays set.

It took me quite some time to reproduce the issue locally, but now I can
see what happens.

It requires apicv_enabled=0, i.e. full apic emulation. With apicv_enabled=1
(and hardware support) it behaves correctly.

Here is the series of events:

Guest CPU

goes down

native_cpu_disable()

apic_soft_disable();

play_dead()

....

startup()

if (apic_enabled())
apic_pending_intr_clear() <- Not taken

enable APIC

apic_pending_intr_clear() <- Triggers warning because IRR is stale

When this happens then the deadline timer or the regular APIC timer -
happens with both, has fired shortly before the APIC is disabled, but the
interrupt was not serviced because the guest CPU was in an interrupt
disabled region at that point.

The state of the timer vector ISR/IRR bits:

ISR IRR
before apic_soft_disable() 0 1
after apic_soft_disable() 0 1

On startup 0 1

Now one would assume that the IRR is cleared after the INIT reset, but this
happens only on CPU0.

Why?

Because our CPU0 hotplug is just for testing to make sure nothing breaks
and goes through an NMI wakeup vehicle because INIT would send it through
the boots-trap code which is not really working if that CPU was not
physically unplugged.

Now looking at a real world APIC the situation in that case is:

ISR IRR
before apic_soft_disable() 0 1
after apic_soft_disable() 0 1

On startup 0 0

Why?

Once the dying CPU reenables interrupts the pending interrupt gets
delivered as a spurious interupt and then the state is clear.

While that CPU0 hotplug test case is surely an esoteric issue, the APIC
emulation is still wrong, Even if the play_dead() code would not enable
interrupts then the pending IRR bit would turn into an ISR .. interrupt
when the APIC is reenabled on startup.

Thanks,

tglx










2019-07-02 05:29:58

by Wanpeng Li

[permalink] [raw]
Subject: Re: [BUG] kvm: APIC emulation problem - was Re: [LKP] [x86/hotplug] ...

Hi Thomas,
On Tue, 2 Jul 2019 at 06:44, Thomas Gleixner <[email protected]> wrote:
>
> Folks,
>
> after chasing a 0-day test failure for a couple of days, I was finally able
> to reproduce the issue.
>
> Background:
>
> In preparation of supporting IPI shorthands I changed the CPU offline
> code to software disable the local APIC instead of just masking it.
> That's done by clearing the APIC_SPIV_APIC_ENABLED bit in the APIC_SPIV
> register.
>
> Failure:
>
> When the CPU comes back online the startup code triggers occasionally
> the warning in apic_pending_intr_clear(). That complains that the IRRs
> are not empty.
>
> The offending vector is the local APIC timer vector who's IRR bit is set
> and stays set.
>
> It took me quite some time to reproduce the issue locally, but now I can
> see what happens.
>
> It requires apicv_enabled=0, i.e. full apic emulation. With apicv_enabled=1
> (and hardware support) it behaves correctly.
>
> Here is the series of events:
>
> Guest CPU
>
> goes down
>
> native_cpu_disable()
>
> apic_soft_disable();
>
> play_dead()
>
> ....
>
> startup()
>
> if (apic_enabled())
> apic_pending_intr_clear() <- Not taken
>
> enable APIC
>
> apic_pending_intr_clear() <- Triggers warning because IRR is stale
>
> When this happens then the deadline timer or the regular APIC timer -
> happens with both, has fired shortly before the APIC is disabled, but the
> interrupt was not serviced because the guest CPU was in an interrupt
> disabled region at that point.
>
> The state of the timer vector ISR/IRR bits:
>
> ISR IRR
> before apic_soft_disable() 0 1
> after apic_soft_disable() 0 1
>
> On startup 0 1
>
> Now one would assume that the IRR is cleared after the INIT reset, but this
> happens only on CPU0.
>
> Why?
>
> Because our CPU0 hotplug is just for testing to make sure nothing breaks
> and goes through an NMI wakeup vehicle because INIT would send it through
> the boots-trap code which is not really working if that CPU was not
> physically unplugged.
>
> Now looking at a real world APIC the situation in that case is:
>
> ISR IRR
> before apic_soft_disable() 0 1
> after apic_soft_disable() 0 1
>
> On startup 0 0
>
> Why?
>
> Once the dying CPU reenables interrupts the pending interrupt gets
> delivered as a spurious interupt and then the state is clear.
>
> While that CPU0 hotplug test case is surely an esoteric issue, the APIC
> emulation is still wrong, Even if the play_dead() code would not enable
> interrupts then the pending IRR bit would turn into an ISR .. interrupt
> when the APIC is reenabled on startup.

From SDM 10.4.7.2 Local APIC State After It Has Been Software Disabled
* Pending interrupts in the IRR and ISR registers are held and require
masking or handling by the CPU.

In your testing, hardware cpu will not respect soft disable APIC when
IRR has already been set or APICv posted-interrupt is in flight, so we
can skip soft disable APIC checking when clearing IRR and set ISR,
continue to respect soft disable APIC when attempting to set IRR.
Could you try below fix?

diff --git a/arch/x86/kvm/lapic.c b/arch/x86/kvm/lapic.c
index 05d8934..f857a12 100644
--- a/arch/x86/kvm/lapic.c
+++ b/arch/x86/kvm/lapic.c
@@ -2376,7 +2376,7 @@ int kvm_apic_has_interrupt(struct kvm_vcpu *vcpu)
struct kvm_lapic *apic = vcpu->arch.apic;
u32 ppr;

- if (!apic_enabled(apic))
+ if (!kvm_apic_hw_enabled(apic))
return -1;

__apic_update_ppr(apic, &ppr);

Regards,
Wanpeng Li

2019-07-02 06:41:20

by Thomas Gleixner

[permalink] [raw]
Subject: Re: [BUG] kvm: APIC emulation problem - was Re: [LKP] [x86/hotplug] ...

Wanpeng,

On Tue, 2 Jul 2019, Wanpeng Li wrote:
> On Tue, 2 Jul 2019 at 06:44, Thomas Gleixner <[email protected]> wrote:
> >
> > While that CPU0 hotplug test case is surely an esoteric issue, the APIC
> > emulation is still wrong, Even if the play_dead() code would not enable
> > interrupts then the pending IRR bit would turn into an ISR .. interrupt
> > when the APIC is reenabled on startup.
>
> >From SDM 10.4.7.2 Local APIC State After It Has Been Software Disabled
> * Pending interrupts in the IRR and ISR registers are held and require
> masking or handling by the CPU.

Correct.

> In your testing, hardware cpu will not respect soft disable APIC when
> IRR has already been set or APICv posted-interrupt is in flight, so we
> can skip soft disable APIC checking when clearing IRR and set ISR,
> continue to respect soft disable APIC when attempting to set IRR.
> Could you try below fix?

> diff --git a/arch/x86/kvm/lapic.c b/arch/x86/kvm/lapic.c
> index 05d8934..f857a12 100644
> --- a/arch/x86/kvm/lapic.c
> +++ b/arch/x86/kvm/lapic.c
> @@ -2376,7 +2376,7 @@ int kvm_apic_has_interrupt(struct kvm_vcpu *vcpu)
> struct kvm_lapic *apic = vcpu->arch.apic;
> u32 ppr;
>
> - if (!apic_enabled(apic))
> + if (!kvm_apic_hw_enabled(apic))
> return -1;
>
> __apic_update_ppr(apic, &ppr);

Yes. That fixes it and works as expected. Thanks for the quick
resolution. I surely stared at that function, but was not sure how to fix
it proper.

Tested-by: Thomas Gleixner <[email protected]>

Please add a Cc: stable... tag when you post the patch.

Thanks,

tglx

2019-07-02 09:45:27

by Wanpeng Li

[permalink] [raw]
Subject: Re: [BUG] kvm: APIC emulation problem - was Re: [LKP] [x86/hotplug] ...

On Tue, 2 Jul 2019 at 14:40, Thomas Gleixner <[email protected]> wrote:
>
> Wanpeng,
>
> On Tue, 2 Jul 2019, Wanpeng Li wrote:
> > On Tue, 2 Jul 2019 at 06:44, Thomas Gleixner <[email protected]> wrote:
> > >
> > > While that CPU0 hotplug test case is surely an esoteric issue, the APIC
> > > emulation is still wrong, Even if the play_dead() code would not enable
> > > interrupts then the pending IRR bit would turn into an ISR .. interrupt
> > > when the APIC is reenabled on startup.
> >
> > >From SDM 10.4.7.2 Local APIC State After It Has Been Software Disabled
> > * Pending interrupts in the IRR and ISR registers are held and require
> > masking or handling by the CPU.
>
> Correct.
>
> > In your testing, hardware cpu will not respect soft disable APIC when
> > IRR has already been set or APICv posted-interrupt is in flight, so we
> > can skip soft disable APIC checking when clearing IRR and set ISR,
> > continue to respect soft disable APIC when attempting to set IRR.
> > Could you try below fix?
>
> > diff --git a/arch/x86/kvm/lapic.c b/arch/x86/kvm/lapic.c
> > index 05d8934..f857a12 100644
> > --- a/arch/x86/kvm/lapic.c
> > +++ b/arch/x86/kvm/lapic.c
> > @@ -2376,7 +2376,7 @@ int kvm_apic_has_interrupt(struct kvm_vcpu *vcpu)
> > struct kvm_lapic *apic = vcpu->arch.apic;
> > u32 ppr;
> >
> > - if (!apic_enabled(apic))
> > + if (!kvm_apic_hw_enabled(apic))
> > return -1;
> >
> > __apic_update_ppr(apic, &ppr);
>
> Yes. That fixes it and works as expected. Thanks for the quick resolution.

No problem. :)

> I surely stared at that function, but was not sure how to fix
> it proper.
>
> Tested-by: Thomas Gleixner <[email protected]>
>
> Please add a Cc: stable... tag when you post the patch.

Ok.

Regards,
Wanpeng Li