apic test in kvm-unit-test failed with timeout

[Po-Hsu Lin]

With Joshua's comment in bug 1719524: "Nested KVM can only be tried on instance sizes with nested Hypervisor support: Ev3 and Dv3.", although the instance name is E4v3 here but I can start a KVM on it.

Test apic will timeout on it.

Steps:
1. git clone --depth=1 https://git.kernel.org/pub/scm/virt/kvm/kvm-unit-tests.git
2. cd kvm-unit-tests; ./configure; make
3. Run the apic test as root:

# TESTNAME=apic TIMEOUT=30 ACCEL= ./x86/run x86/apic.flat -smp 2 -cpu qemu64,+x2apic,+tsc-deadline
timeout -k 1s --foreground 30 /usr/bin/qemu-system-x86_64 -nodefaults -device pc-testdev -device isa-debug-exit,iobase=0xf4,iosize=0x4 -vnc none -serial stdio -device pci-testdev -machine accel=kvm -kernel x86/apic.flat -smp 2 -cpu qemu64,+x2apic,+tsc-deadline # -initrd /tmp/tmp.onXtr5JVp7
enabling apic
enabling apic
paging enabled
cr0 = 80010011
cr3 = 459000
cr4 = 20
apic version: 1050014
PASS: apic existence
PASS: xapic id matches cpuid
PASS: writeable xapic id
PASS: non-writeable x2apic id
PASS: sane x2apic id
FAIL: x2apic id matches cpuid
PASS: correct xapic id after reset
PASS: apic_disable: Local apic enabled
PASS: apic_disable: CPUID.1H:EDX.APIC[bit 9] is set
PASS: apic_disable: Local apic disabled
PASS: apic_disable: CPUID.1H:EDX.APIC[bit 9] is clear
PASS: apic_disable: Local apic enabled
PASS: apic_disable: CPUID.1H:EDX.APIC[bit 9] is set
x2apic enabled
PASS: x2apic enabled to invalid state
PASS: x2apic enabled to apic enabled
PASS: disabled to invalid state
PASS: disabled to x2apic enabled
PASS: apic enabled to invalid state
PASS: apicbase: relocate apic
PASS: apicbase: reserved physaddr bits
PASS: apicbase: reserved low bits
PASS: self ipi
starting broadcast (x2apic)
PASS: APIC physical broadcast address
PASS: APIC physical broadcast shorthand
PASS: nmi-after-sti
qemu-system-x86_64: terminating on signal 15 from pid 7246

ProblemType: Bug
DistroRelease: Ubuntu 16.04
Package: linux-image-4.14.0-1004-azure-edge 4.14.0-1004.4
ProcVersionSignature: User Name 4.14.0-1004.4-username-edge 4.14.14
Uname: Linux 4.14.0-1004-azure-edge x86_64
ApportVersion: 2.20.1-0ubuntu2.15
Architecture: amd64
Date: Thu Feb 8 06:00:55 2018
ProcEnviron:
 TERM=xterm-256color
 PATH=(custom, no user)
 XDG_RUNTIME_DIR=<set>
 LANG=en_US.UTF-8
 SHELL=/bin/bash
SourcePackage: linux-azure-edge
UpgradeStatus: No upgrade log present (probably fresh install)
---
ApportVersion: 2.20.1-0ubuntu2.15
Architecture: amd64
DistroRelease: Ubuntu 16.04
Package: linux-azure-edge
PackageArchitecture: amd64
ProcEnviron:
 TERM=xterm-256color
 PATH=(custom, no user)
 XDG_RUNTIME_DIR=<set>
 LANG=en_US.UTF-8
 SHELL=/bin/bash
ProcVersionSignature: User Name 4.13.0-1009.12-username 4.13.13
Tags: xenial uec-images
Uname: Linux 4.13.0-1009-azure x86_64
UpgradeStatus: No upgrade log present (probably fresh install)
UserGroups: adm audio cdrom dialout dip floppy libvirtd lxd netdev plugdev sudo video
_MarkForUpload: True

[Po-Hsu Lin (cypressyew)]

apport information

[Po-Hsu Lin (cypressyew)]

apport information

[Po-Hsu Lin (cypressyew)]

apport information

[Ubuntu Kernel Bot (ubuntu-kernel-bot)]

This bug is missing log files that will aid in diagnosing the problem. While running an Ubuntu kernel (not a mainline or third-party kernel) please enter the following command in a terminal window:

apport-collect 1748103

and then change the status of the bug to 'Confirmed'.

If, due to the nature of the issue you have encountered, you are unable to run this command, please add a comment stating that fact and change the bug status to 'Confirmed'.

This change has been made by an automated script, maintained by the Ubuntu Kernel Team.

[Po-Hsu Lin (cypressyew)]

Can be seen on generic kernel as well.

[Sean Feole (sfeole)]

Also have seen this in the following Azure instances

Standard_D2_v3
Standard_D2s_v3
Standard_DC2s
Standard_E2s_v3

[Po-Hsu Lin (cypressyew)]

Didn't see this on B-OEM-OSP1 / Disco.

[Sean Feole (sfeole)]

Affects Oracle Disco 5.0.0-1003.4

[Po-Hsu Lin (cypressyew)]

Passed with B-Azure-5.0 Standard_F32s_v2

[Sean Feole (sfeole)]

In general this test fails usually across all clouds/metals Should be a higher priority to get this fixed,

12/03 21:30:32 DEBUG| utils:0116| Running 'kvm-ok'
12/03 21:30:32 DEBUG| utils:0153| [stdout] INFO: /dev/kvm exists
12/03 21:30:32 DEBUG| utils:0153| [stdout] KVM acceleration can be used
12/03 21:30:32 DEBUG| utils:0116| Running '/home/ubuntu/autotest/client/tmp/ubuntu_kvm_unit_tests/src/kvm-unit-tests/tests/apic'
12/03 21:30:32 DEBUG| utils:0153| [stdout] BUILD_HEAD=e2c275c4
12/03 21:30:33 DEBUG| utils:0153| [stdout] timeout -k 1s --foreground 30 /usr/bin/qemu-system-x86_64 -nodefaults -device pc-testdev -device isa-debug-exit,iobase=0xf4,iosize=0x4 -vnc none -serial stdio -device pci-testdev -machine accel=kvm -kernel /tmp/tmp.l8jZuQAnJV -smp 2 -cpu qemu64,+x2apic,+tsc-deadline # -initrd /tmp/tmp.97foJOgQOp
12/03 21:30:33 DEBUG| utils:0153| [stderr] qemu-system-x86_64: warning: host doesn't support requested feature: CPUID.80000001H:ECX.svm [bit 2]
12/03 21:30:33 DEBUG| utils:0153| [stderr] qemu-system-x86_64: warning: host doesn't support requested feature: CPUID.80000001H:ECX.svm [bit 2]
12/03 21:30:33 DEBUG| utils:0153| [stdout] enabling apic
12/03 21:30:33 DEBUG| utils:0153| [stdout] enabling apic
12/03 21:30:33 DEBUG| utils:0153| [stdout] paging enabled
12/03 21:30:33 DEBUG| utils:0153| [stdout] cr0 = 80010011
12/03 21:30:33 DEBUG| utils:0153| [stdout] cr3 = 45a000
12/03 21:30:33 DEBUG| utils:0153| [stdout] cr4 = 20
12/03 21:30:33 DEBUG| utils:0153| [stdout] apic version: 50014
12/03 21:30:33 DEBUG| utils:0153| [stdout] PASS: apic existence
12/03 21:30:33 DEBUG| utils:0153| [stdout] PASS: xapic id matches cpuid
12/03 21:30:33 DEBUG| utils:0153| [stdout] PASS: writeable xapic id
12/03 21:30:33 DEBUG| utils:0153| [stdout] PASS: non-writeable x2apic id
12/03 21:30:33 DEBUG| utils:0153| [stdout] PASS: sane x2apic id
12/03 21:30:33 DEBUG| utils:0153| [stdout] PASS: x2apic id matches cpuid
12/03 21:30:33 DEBUG| utils:0153| [stdout] PASS: correct xapic id after reset
12/03 21:30:33 DEBUG| utils:0153| [stdout] PASS: apic_disable: Local apic disabled
12/03 21:30:33 DEBUG| utils:0153| [stdout] PASS: apic_disable: CPUID.1H:EDX.APIC[bit 9] is clear
12/03 21:30:33 DEBUG| utils:0153| [stdout] PASS: apic_disable: *0xfee00030: ffffffff
12/03 21:30:33 DEBUG| utils:0153| [stdout] PASS: apic_disable: CR8: 0
12/03 21:30:33 DEBUG| utils:0153| [stdout] PASS: apic_disable: CR8: f
12/03 21:30:33 DEBUG| utils:0153| [stdout] PASS: apic_disable: *0xfee00080: ffffffff
12/03 21:30:33 DEBUG| utils:0153| [stdout] PASS: apic_disable: Local apic enabled in xAPIC mode
12/03 21:30:33 DEBUG| utils:0153| [stdout] PASS: apic_disable: CPUID.1H:EDX.APIC[bit 9] is set
12/03 21:30:33 DEBUG| utils:0153| [stdout] PASS: apic_disable: *0xfee00030: 50014
12/03 21:30:33 DEBUG| utils:0153| [stdout] PASS: apic_disable: *0xfee00080: 0
12/03 21:30:33 DEBUG| utils:0153| [stdout] PASS: apic_disable: *0xfee00080: f0
12/03 21:30:33 DEBUG| utils:0153| [stdout] PASS: apic_disable: Local apic enabled in x2APIC mode
12/03 21:30:33 DEBUG| utils:0153|...

[Sean Feole (sfeole)]

https://<email address hidden>/

[Sean Feole (sfeole)]

affects 4.15.0-1052.52 linux-kvm

[Po-Hsu Lin (cypressyew)]

Failed on T-4.4 / X-4.4 AMD64
Passed on X-4.15 / B-4.15 AMD64

[Po-Hsu Lin (cypressyew)]

Passed on E 5.3 AMD64

[Po-Hsu Lin (cypressyew)]

On E-KVM, the apic test will take about 1 minute to run:

SUMMARY: 51 tests, 1 unexpected failures
FAIL apic-split (51 tests, 1 unexpected failures)

real 1m7.991s
user 2m0.543s
sys 0m11.881s

On B-Oracle (VM.Standard2.16). the apic test will take about 3 minute to run:

SUMMARY: 51 tests, 1 unexpected failures, 1 skipped
FAIL apic (51 tests, 1 unexpected failures, 1 skipped)

real 2m59.177s
user 2m24.763s
sys 3m32.041s

[Kelsey Skunberg (kelsey-skunberg)]

spotted on Bionic/azure-4.15 : 4.15.0-1097.107 : amd64

[Po-Hsu Lin (cypressyew)]

Looks like it will take about 40 seconds to run on Azure Standard-D48-v3, bump the timeout threshold to 60 or 90 should be able to solve this bug.

06:48:28 INFO | START ubuntu_kvm_unit_tests.apic ubuntu_kvm_unit_tests.apic timestamp=1602571708 timeout=1800 localtime=Oct 13 06:48:28
06:48:28 DEBUG| Persistent state client._record_indent now set to 2
06:48:28 DEBUG| Persistent state client.unexpected_reboot now set to ('ubuntu_kvm_unit_tests.apic', 'ubuntu_kvm_unit_tests.apic')
06:48:28 DEBUG| Waiting for pid 20233 for 1800 seconds
06:48:28 DEBUG| Running 'kvm-ok'
06:48:28 DEBUG| [stdout] INFO: /dev/kvm exists
06:48:28 DEBUG| [stdout] KVM acceleration can be used
06:48:28 DEBUG| Running '/home/azure/autotest/client/tmp/ubuntu_kvm_unit_tests/src/kvm-unit-tests/tests/apic'
06:48:28 DEBUG| [stdout] BUILD_HEAD=4671e4ba
06:48:28 DEBUG| [stdout] timeout -k 1s --foreground 60 /usr/bin/qemu-system-x86_64 -nodefaults -device pc-testdev -device isa-debug-exit,iobase=0xf4,iosize=0x4 -vnc none -serial stdio -device pci-testdev -machine accel=kvm -kernel /tmp/tmp.kHcsacTcCc -smp 2 -cpu qemu64,+x2apic,+tsc-deadline # -initrd /tmp/tmp.Mc6ec4A6zG
06:48:28 DEBUG| [stderr] qemu-system-x86_64: warning: host doesn't support requested feature: CPUID.80000001H:ECX.svm [bit 2]
06:48:28 DEBUG| [stderr] qemu-system-x86_64: warning: host doesn't support requested feature: CPUID.80000001H:ECX.svm [bit 2]
06:48:29 DEBUG| [stdout] enabling apic
06:48:29 DEBUG| [stdout] enabling apic
06:48:29 DEBUG| [stdout] paging enabled
06:48:29 DEBUG| [stdout] cr0 = 80010011
06:48:29 DEBUG| [stdout] cr3 = 45a000
06:48:29 DEBUG| [stdout] cr4 = 20
06:48:29 DEBUG| [stdout] apic version: 50014
06:48:29 DEBUG| [stdout] PASS: apic existence
06:48:29 DEBUG| [stdout] PASS: xapic id matches cpuid
06:48:29 DEBUG| [stdout] PASS: writeable xapic id
06:48:29 DEBUG| [stdout] PASS: non-writeable x2apic id
06:48:29 DEBUG| [stdout] PASS: sane x2apic id
06:48:29 DEBUG| [stdout] PASS: x2apic id matches cpuid
06:48:29 DEBUG| [stdout] PASS: correct xapic id after reset
06:48:29 DEBUG| [stdout] PASS: apic_disable: Local apic disabled
06:48:29 DEBUG| [stdout] PASS: apic_disable: CPUID.1H:EDX.APIC[bit 9] is clear
06:48:29 DEBUG| [stdout] PASS: apic_disable: *0xfee00030: ffffffff
06:48:29 DEBUG| [stdout] PASS: apic_disable: CR8: 0
06:48:29 DEBUG| [stdout] PASS: apic_disable: CR8: f
06:48:29 DEBUG| [stdout] PASS: apic_disable: *0xfee00080: ffffffff
06:48:29 DEBUG| [stdout] PASS: apic_disable: Local apic enabled in xAPIC mode
06:48:29 DEBUG| [stdout] PASS: apic_disable: CPUID.1H:EDX.APIC[bit 9] is set
06:48:29 DEBUG| [stdout] PASS: apic_disable: *0xfee00030: 50014
06:48:29 DEBUG| [stdout] PASS: apic_disable: *0xfee00080: 0
06:48:29 DEBUG| [stdout] PASS: apic_disable: *0xfee00080: f0
06:48:29 DEBUG| [stdout] PASS: apic_disable: Local apic enabled in x2APIC mode
06:48:29 DEBUG| [stdout] PASS: apic_disable: CPUID.1H:EDX.APIC[bit 9] is set
06:48:29 DEBUG| [stdout] PASS: apic_disable: *0xfee00030: ffffffff
06:48:29 DEBUG| [stdout] PASS: apic_disable: CR8: 0
06:48:29 DEBUG| [stdout] PASS: apic_disable: CR8: f
06:48:29 DEBUG| [stdout] PASS: apic_disable: *0xfee00080: ffffffff
06:48:29 DEBUG| [stdout] x2apic enabled
0...

[Po-Hsu Lin (cypressyew)]

Based on comment #16, bump the timeout threshold to 240 second and resubmit to the upstream.
https://marc.info/?l=kvm&m=160258047509783&w=2

[Po-Hsu Lin (cypressyew)]

Still visible in Xenial 4.4.0-1118.132 AWS c5.metal