Re: Getting ACRN to work


Yin, Fengwei <fengwei.yin@...>
 

On 2/12/2020 8:04 AM, Chen, Zide wrote:
Hi Dubravko,
"Spurious vector" could because of external interrupts not registered in hypervisor. This may not be an issue and can be ignored for now.
For the repeating "Starting VCPU 3" issue, it seems some thing related to SIPI delivery. But nothing is obvious to me and need to debug it.
I highly suspect this endless "Starting VCPU" thing is not from SOS
kernel. It's more like from BIOS.

It could be related with some BIOS setting. I suggest checking the BIOS
setting and disable mwait for AP offline and see any difference.

Regards
Yin, Fengwei

I built a Clear Linux kernel with additional logs showing how it's bringing up APs. Could you please try the attached bzImage?
Also please enable early printk by adding "ignore_loglevel earlyprintk=serial,ttyS0,115200n8,keep" to the options in acrn.conf; And use the attached acrn.efi (I enabled some additional logs and print out Linux logs even before ACRN console is operational). If acrn.efi doesn't boot, which is highly possibly since it's not built against your custom board, you may need to apply the attached patch to ACRN hypervisor.
Hopefully the full logs can give us some clues.
Best Regards,
Zide
zide.chen@...
On 2/11/20 9:46 AM, Dubravko Moravski | Exor Embedded S.r.l. wrote:
Hi Zide,

The full log is below, with some additional /* comments */. I've noticed now that ACRN console prompt does appear, but it is unusable due to all the debug messages.

ACRN Hypervisor
calibrate_tsc, tsc_khz=1593600
[7621776us][cpu=0][(null)][sev=2][seq=1]:HV version 1.6-unstable-2020-02-11 17:29:55-4b983876-dirty DBG (daily tag:acrn-2020w04.1-140000p) build by clear, start time 7596708us
[7639207us][cpu=0][(null)][sev=2][seq=2]:API version 1.0
[7644984us][cpu=0][(null)][sev=2][seq=3]:Detect processor: Intel(R) Atom(TM) Processor E3940 @ 1.60GHz
[7655270us][cpu=0][(null)][sev=1][seq=4]:SECURITY WARNING!!!!!!
[7661731us][cpu=0][(null)][sev=1][seq=5]:Please apply the latest CPU uCode patch!
[7670865us][cpu=0][(null)][sev=5][seq=6]:hide pci uart dev: (0:18:0)
[7720135us][cpu=0][(null)][sev=5][seq=9]:profiling_setup: entering
[7720133us][cpu=1][(null)][sev=5][seq=7]:profiling_setup: entering
[7720136us][cpu=3][(null)][sev=5][seq=10]:profiling_setup: entering
[7720134us][cpu=2][(null)][sev=5][seq=8]:profiling_setup: entering
[7726787us][cpu=0][(null)][sev=5][seq=11]:profiling_setup: calling request_irq
[7733543us][cpu=1][(null)][sev=5][seq=12]:profiling_setup: exiting
[7740402us][cpu=3][(null)][sev=5][seq=13]:profiling_setup: exiting
[7747161us][cpu=2][(null)][sev=5][seq=14]:profiling_setup: exiting
[7755094us][cpu=0][(null)][sev=5][seq=15]:profiling_setup: exiting
[7783951us][cpu=0][(null)][sev=5][seq=16]:System S3/S5 is supported.
[7791335us][cpu=0][(null)][sev=5][seq=17]:Creating VCPU working on PCPU0
[7798597us][cpu=0][(null)][sev=5][seq=18]:Create VM0-VCPU0, Role: PRIMARY
[7806135us][cpu=0][(null)][sev=5][seq=19]:Creating VCPU working on PCPU1
[7813389us][cpu=0][(null)][sev=5][seq=20]:Create VM0-VCPU1, Role: SECONDARY
[7821031us][cpu=0][(null)][sev=5][seq=21]:Creating VCPU working on PCPU2
[7828376us][cpu=0][(null)][sev=5][seq=22]:Create VM0-VCPU2, Role: SECONDARY
[7836012us][cpu=0][(null)][sev=5][seq=23]:Creating VCPU working on PCPU3
[7843359us][cpu=0][(null)][sev=5][seq=24]:Create VM0-VCPU3, Role: SECONDARY
[7850998us][cpu=0][(null)][sev=4][seq=25]:Spurious vector: 0x50.
ACRN:\>[7858255us][cpu=0][(null)][sev=2][seq=26]:Start VM id: 0 name: ACRN SOS VM
[7865814us][cpu=0][vm0:vcpu0][sev=5][seq=27]:VM 0 Starting VCPU 0
[7872492us][cpu=0][vm0:vcpu0][sev=5][seq=28]:VM 0 VCPU 0 successfully launched
[7882501us][cpu=0][vm0:vcpu0][sev=4][seq=29]:Spurious vector: 0x50.
[7899292us][cpu=0][vm0:vcpu0][sev=4][seq=30]:Spurious vector: 0x50.
[7916327us][cpu=0][vm0:vcpu0][sev=4][seq=31]:Spurious vector: 0x50.
/* seq 32..99 are all identical entries like the surrounding ones */
[9075356us][cpu=0][vm0:vcpu0][sev=4][seq=100]:Spurious vector: 0x50.
[9092270us][cpu=0][vm0:vcpu0][sev=4][seq=101]:Spurious vector: 0x50.
[9109179us][cpu=0][vm0:vcpu0][sev=4][seq=102]:Spurious vector: 0x50.
[9126089us][cpu=0][vm0:vcpu0][sev=4][seq=103]:Spurious vector: 0x50.
[9163364us][cpu=0][vm0:vcpu0][sev=2][seq=104]:write_cfg 0:18.0 not found! off: 0x3c, val: 0x4
/* approximately here I've choosed an entry from the boot menu */

[9173239us][cpu=0][vm0:vcpu0][sev=3][seq=105]:vlapic: Start Secondary VCPU1 for VM[0]...
[9182086us][cpu=1][vm0:vcpu1][sev=5][seq=106]:VM 0 Starting VCPU 1
[9182310us][cpu=0][vm0:vcpu0][sev=3][seq=107]:vlapic: Start Secondary VCPU2 for VM[0]...
[9197761us][cpu=2][vm0:vcpu2][sev=5][seq=108]:VM 0 Starting VCPU 2
[9197985us][cpu=0][vm0:vcpu0][sev=3][seq=109]:vlapic: Start Secondary VCPU3 for VM[0]...
[9213427us][cpu=3][vm0:vcpu3][sev=5][seq=110]:VM 0 Starting VCPU 3
[9220288us][cpu=0][vm0:vcpu0][sev=3][seq=111]:vlapic: Start Secondary VCPU3 for VM[0]...
[9229124us][cpu=3][vm0:vcpu3][sev=5][seq=112]:VM 0 Starting VCPU 3
[9235992us][cpu=0][vm0:vcpu0][sev=3][seq=113]:vlapic: Start Secondary VCPU3 for VM[0]...
[9244836us][cpu=3][vm0:vcpu3][sev=5][seq=114]:VM 0 Starting VCPU 3
[9251701us][cpu=0][vm0:vcpu0][sev=3][seq=115]:vlapic: Start Secondary VCPU3 for VM[0]...
[9260536us][cpu=3][vm0:vcpu3][sev=5][seq=116]:VM 0 Starting VCPU 3
[9267402us][cpu=0][vm0:vcpu0][sev=3][seq=117]:vlapic: Start Secondary VCPU3 for VM[0]...
[9276237us][cpu=3][vm0:vcpu3][sev=5][seq=118]:VM 0 Starting VCPU 3
[9283102us][cpu=0][vm0:vcpu0][sev=3][seq=119]:vlapic: Start Secondary VCPU3 for VM[0]...
[9291941us][cpu=3][vm0:vcpu3][sev=5][seq=120]:VM 0 Starting VCPU 3
[9298810us][cpu=0][vm0:vcpu0][sev=3][seq=121]:vlapic: Start Secondary VCPU3 for VM[0]...
[9307648us][cpu=3][vm0:vcpu3][sev=5][seq=122]:VM 0 Starting VCPU 3
[9314511us][cpu=0][vm0:vcpu0][sev=3][seq=123]:vlapic: Start Secondary VCPU3 for VM[0]...
[9323355us][cpu=3][vm0:vcpu3][sev=5][seq=124]:VM 0 Starting VCPU 3
[9330216us][cpu=0][vm0:vcpu0][sev=3][seq=125]:vlapic: Start Secondary VCPU3 for VM[0]...
[9339041us][cpu=3][vm0:vcpu3][sev=5][seq=126]:VM 0 Starting VCPU 3
/* this continues indefinitely... */



*Dubravko Moravski*
/SW engineering/
*Exor Embedded S.r.l.*
p:     +38 512455659 <tel:+38 512455659>  m:+38 5915402413 <tel:+38 5915402413>
a:     Slavonska avenija, 50, Zagreb, Croatia, 10000
w:     exorint.com <https://exorint.com/>




  Prima di stampare pensa ai costi ambientali. Please consider the environment before printing this email.

Privacy <https://www.exorint.com/it/privacy>
--------------------------------------------------------------------------------------------------------------------------

*From:* acrn-users@... <acrn-users@...> on behalf of Chen, Zide via Lists.Projectacrn.Org <zide.chen=intel.com@...>
*Sent:* Tuesday, February 11, 2020 5:31 PM
*To:* acrn-users@... <acrn-users@...>
*Subject:* Re: [acrn-users] Getting ACRN to work
Hi Dubravko,

Is it possible to post the full log here?

Thanks,
Zide


On 2/11/20 6:19 AM, Dubravko Moravski | Exor Embedded S.r.l. wrote:
Hi Zide,

Your instructions were clear, unfortunately I'm still having issues.

I have followed the instructions from https://projectacrn.github.io/latest/tutorials/kbl-nuc-sdc.html, and first upgraded
Clear Linux to the same version as used there, just in case. Also I've rebuilt ACRN with CONFIG_CONSOLE_LOGLEVEL_DEFAULT
now set to 5 (previously was 6).

I've verified that I have all the required files on the EFI partition. I've added a new boot entry with:

     sudo efibootmgr -c -l "\EFI\acrn\acrn.efi" -d /dev/mmcblk0 -p 1 -L "ACRN hypervisor" -u
     "bootloader=\EFI\org.clearlinux\bootloaderx64.efi uart=bdf@0:18.0"

Then I've set clr-boot-manager options according to instructions. This all went smoothly.

After the reboot, ACRN loads. While it's waiting in the boot menu it continuously prints out a lot of these:

     [21481383us][cpu=0][vm0:vcpu0][sev=4][seq=827]:Spurious vector: 0x50.
     [21498377us][cpu=0][vm0:vcpu0][sev=4][seq=828]:Spurious vector: 0x50.
     [21515373us][cpu=0][vm0:vcpu0][sev=4][seq=829]:Spurious vector: 0x50.
     [21532360us][cpu=0][vm0:vcpu0][sev=4][seq=830]:Spurious vector: 0x50.
     [21549353us][cpu=0][vm0:vcpu0][sev=4][seq=831]:Spurious vector: 0x50.


When I choose the first option that I believe should start the Service OS, it then continuously prints out these:

     [34072934us][cpu=3][vm0:vcpu3][sev=5][seq=1645]:VM 0 Starting CPU 3
     [34079998us][cpu=0][vm0:vcpu0][sev=3][seq=1646]:vlapic: Start Secondary VCPU3 for VM[0]...
     [34089037us][cpu=3][vm0:vcpu3][sev=5][seq=1647]:VM 0 Starting VCPU 3
     [34096100us][cpu=0][vm0:vcpu0][sev=3][seq=1648]:vlapic: Start Secondary VCPU3 for VM[0]...
     [34105131us][cpu=3][vm0:vcpu3][sev=5][seq=1649]:VM 0 Starting VCPU 3
     [34112188us][cpu=0][vm0:vcpu0][sev=3][seq=1650]:vlapic: Start Secondary VCPU3 for VM[0]...

... and it never gets to SOS or ACRN console.

As far as I know, there is nothing wrong with any of the CPU cores; all are enabled in BIOS; "top" in regular Clear Linux
shows that all 4 cores are alive and occasionally doing something.

Best regards,



*Dubravko Moravski*
/SW engineering/
*Exor Embedded S.r.l.*
p:     +38 512455659 <tel:+38 512455659>  m:+38 5915402413 <tel:+38 5915402413>
a:     Slavonska avenija, 50, Zagreb, Croatia, 10000
w:     exorint.com <https://exorint.com/>



   Prima di stampare pensa ai costi ambientali. Please consider the environment before printing this email.

Privacy <https://www.exorint.com/it/privacy>
--------------------------------------------------------------------------------------------------------------------------

*From:* acrn-users@... <acrn-users@...> on behalf of Chen, Zide via
Lists.Projectacrn.Org <zide.chen=intel.com@...>
*Sent:* Monday, February 10, 2020 8:00 PM
*To:* acrn-users@... <acrn-users@...>
*Subject:* Re: [acrn-users] Getting ACRN to work
Hi Dubravko,

If you see endless vmexit messages, it's possibly that you have successfully loaded the guest kernel.

You may remove the vmexit logs by configuring CONFIG_CONSOLE_LOGLEVEL_DEFAULT to any number < 6.

Build it with "RELEASE=1" disables the hypervisor serial console so you won't be able to see anything. So it's discouraged
to do that during bring-up.

I'm expecting you can see the console prompt: "ACRN:\>", and you can try some basic commands like "help", "vm_list",
"vcpu_list", etc. If you find any guest VM is running from "vm_list" command, you can switch to the guest console by
"vm_console 0", and switch back to HV console by pressing "Ctrl + Space".

https://projectacrn.github.io/latest/tutorials/debug.html?highlight=console

If you don't see any VM running, you may following this tutorial (of cause you can try other scenario):
https://projectacrn.github.io/latest/tutorials/kbl-nuc-sdc.html

The key point is at the end you need to install a clear Linux bzImage and acrn.efi (sample:
misc/efi-stub/clearlinux/acrn.conf) in the EFI partition, and the "Linux" line in acrn.efi points to the bzImage you
installed.


Best Regards,
Zide


On 2/10/20 10:39 AM, Dubravko Moravski | Exor Embedded S.r.l. wrote:
Hi Zide,

You were right again, I don't know how it happened but my MAX_PCPU_NUM was set to 3, while there are 4 CPUs.

MADT and DMAR tables seem to be correct.
I'm using acrn.efi, RELOC is enabled.

Now the hypervisor seems to be almost working... The initialization seems to complete fine, then I'm getting a huge number
of printouts like these:

     [836682306us][cpu=0][vm0:vcpu0][sev=6][seq=31854]:Exit Reason: 0x0000000000000001
     [836722306us][cpu=0][vm0:vcpu0][sev=6][seq=31855]:Exit Reason: 0x0000000000000001
     [836762306us][cpu=0][vm0:vcpu0][sev=6][seq=31856]:Exit Reason: 0x0000000000000001
     [836802306us][cpu=0][vm0:vcpu0][sev=6][seq=31857]:Exit Reason: 0x0000000000000001

They continue indefinitely. As far as I can tell, there are no errors (unless these indicate some errors), but also
nothing else happens, just these printouts.

RELEASE=1 build doesn't display the above printouts, but also nothing seems to happen.

I think I might not have configured loading of the next stage (Linux loader) correctly, so it's possible that ACRN just
doesn't have anything to do. The tutorials aren't quite clear regarding doing that, for new custom boards. Though if
that's the problem, I would expect at least some warning message to be displayed. I'll check that first anyway.

Thank you and best regards,
Dubravko



*Dubravko Moravski*
/SW engineering/
*Exor Embedded S.r.l.*
p:     +38 512455659 <tel:+38 512455659>  m:+38 5915402413 <tel:+38 5915402413>
a:     Slavonska avenija, 50, Zagreb, Croatia, 10000
w:     exorint.com <https://exorint.com/>



   Prima di stampare pensa ai costi ambientali. Please consider the environment before printing this email.

Privacy <https://www.exorint.com/it/privacy>
--------------------------------------------------------------------------------------------------------------------------

*From:* acrn-users@... <acrn-users@...> on behalf of Chen, Zide via
Lists.Projectacrn.Org <zide.chen=intel.com@...>
*Sent:* Monday, February 10, 2020 5:50 PM
*To:* acrn-users@... <acrn-users@...>
*Subject:* Re: [acrn-users] Getting ACRN to work
Hi Dubravko,

Did you boot ACRN from acrn.efi (UEFI) or acrn.bin (SBL), or acrn.32.out (Grub)? RELOC is enabled for acrn.efi, but not
others.

For the init_percpu_lapic_init() issue, it's highly possibly that the user defined MAX_PCPU_NUM is less than the physical
CPU number from ACPI table.

Other than that, probably you need to debug the parse_madt() and see if it can't find MADT table or corrupted MADT so that
it finds 0 pcpus.

BTW, you can pull this PR to your code which may help your bring-up since it enables early panic() and other pr_err()
messages.
https://github.com/projectacrn/acrn-hypervisor/pull/4381

Best Regards,
Zide






Join acrn-users@lists.projectacrn.org to automatically receive all group messages.