Re: [PATCH v3 5/5] KVM: arm64: Log source when panicking from nVHE hyp

From: Marc Zyngier <maz@kernel.org>
To: Will Deacon <will@kernel.org>
Cc: catalin.marinas@arm.com, kernel-team@android.com,
	kvmarm@lists.cs.columbia.edu
Subject: Re: [PATCH v3 5/5] KVM: arm64: Log source when panicking from nVHE hyp
Date: Fri, 19 Mar 2021 09:51:29 +0000	[thread overview]
Message-ID: <87v99nh3oe.wl-maz@kernel.org> (raw)
In-Reply-To: <20210318165946.GA7656@willie-the-truck>

On Thu, 18 Mar 2021 16:59:47 +0000,
Will Deacon <will@kernel.org> wrote:
> 
> On Thu, Mar 18, 2021 at 02:33:11PM +0000, Andrew Scull wrote:
> > To aid with debugging, add details of the source of a panic from nVHE
> > hyp. This is done by having nVHE hyp exit to nvhe_hyp_panic_handler()
> > rather than directly to panic(). The handler will then add the extra
> > details for debugging before panicking the kernel.
> > 
> > If the panic was due to a BUG(), look up the metadata to log the file
> > and line, if available, otherwise log an address that can be looked up
> > in vmlinux. The hyp offset is also logged to allow other hyp VAs to be
> > converted, similar to how the kernel offset is logged during a panic.
> > 
> > __hyp_panic_string is now inlined since it no longer needs to be
> > referenced as a symbol and the message is free to diverge between VHE
> > and nVHE.
> > 
> > The following is an example of the logs generated by a BUG in nVHE hyp.
> > 
> > [   46.754840] kvm [307]: nVHE hyp BUG at: arch/arm64/kvm/hyp/nvhe/switch.c:242!
> > [   46.755357] kvm [307]: Hyp Offset: 0xfffea6c58e1e0000
> > [   46.755824] Kernel panic - not syncing: HYP panic:
> > [   46.755824] PS:400003c9 PC:0000d93a82c705ac ESR:f2000800
> > [   46.755824] FAR:0000000080080000 HPFAR:0000000000800800 PAR:0000000000000000
> > [   46.755824] VCPU:0000d93a880d0000
> > [   46.756960] CPU: 3 PID: 307 Comm: kvm-vcpu-0 Not tainted 5.12.0-rc3-00005-gc572b99cf65b-dirty #133
> > [   46.757459] Hardware name: QEMU QEMU Virtual Machine, BIOS 0.0.0 02/06/2015
> > [   46.758366] Call trace:
> > [   46.758601]  dump_backtrace+0x0/0x1b0
> > [   46.758856]  show_stack+0x18/0x70
> > [   46.759057]  dump_stack+0xd0/0x12c
> > [   46.759236]  panic+0x16c/0x334
> > [   46.759426]  arm64_kernel_unmapped_at_el0+0x0/0x30
> > [   46.759661]  kvm_arch_vcpu_ioctl_run+0x134/0x750
> > [   46.759936]  kvm_vcpu_ioctl+0x2f0/0x970
> > [   46.760156]  __arm64_sys_ioctl+0xa8/0xec
> > [   46.760379]  el0_svc_common.constprop.0+0x60/0x120
> > [   46.760627]  do_el0_svc+0x24/0x90
> > [   46.760766]  el0_svc+0x2c/0x54
> > [   46.760915]  el0_sync_handler+0x1a4/0x1b0
> > [   46.761146]  el0_sync+0x170/0x180
> > [   46.761889] SMP: stopping secondary CPUs
> > [   46.762786] Kernel Offset: 0x3e1cd2820000 from 0xffff800010000000
> > [   46.763142] PHYS_OFFSET: 0xffffa9f680000000
> > [   46.763359] CPU features: 0x00240022,61806008
> > [   46.763651] Memory Limit: none
> 
> Nice!
> 
> > [   46.813867] ---[ end Kernel panic - not syncing: HYP panic:
> > [   46.813867] PS:400003c9 PC:0000d93a82c705ac ESR:f2000800
> > [   46.813867] FAR:0000000080080000 HPFAR:0000000000800800 PAR:0000000000000000
> > [   46.813867] VCPU:0000d93a880d0000 ]---
> 
> Why did these last three lines get printed twice?

That's the panic string that gets repeated, a standard "feature" of
the panic code:

root@tiger-roach:~# echo -n 'c' > /proc/sysrq-trigger 
[250622.941867] sysrq: Trigger a crash
[250622.941903] Kernel panic - not syncing: sysrq triggered crash
[250622.945515] CPU: 0 PID: 4890 Comm: bash Tainted: G            E     5.11.0 #3124
[250622.952930] Hardware name:  , BIOS 2021.01-rc2-00012-gde865f7ee1 11/16/2020
[250622.959917] Call trace:
[250622.962417]  dump_backtrace+0x0/0x1e4
[250622.966126]  show_stack+0x24/0x80
[250622.969490]  dump_stack+0xc8/0x120
[250622.972940]  panic+0x178/0x38c
[250622.976045]  sysrq_handle_crash+0x28/0x30
[250622.980098]  __handle_sysrq+0x98/0x1a4
[250622.983893]  write_sysrq_trigger+0x94/0x12c
[250622.988120]  proc_reg_write+0xb4/0xf0
[250622.991828]  vfs_write+0xfc/0x29c
[250622.995192]  ksys_write+0x74/0x100
[250622.998642]  __arm64_sys_write+0x28/0x3c
[250623.002610]  el0_svc_common.constprop.0+0x80/0x1c0
[250623.007440]  do_el0_svc+0x30/0xa0
[250623.010803]  el0_svc+0x28/0x70
[250623.013908]  el0_sync_handler+0x1a8/0x1ac
[250623.017962]  el0_sync+0x174/0x180
[250623.021331] SMP: stopping secondary CPUs
[250623.025301] Kernel Offset: 0x435917bf0000 from 0xffff800010000000
[250623.031417] PHYS_OFFSET: 0xffff9bc5c0000000
[250623.035643] CPU features: 0x08240022,2aa0a830
[250623.040042] Memory Limit: none
[250623.043153] ---[ end Kernel panic - not syncing: sysrq triggered crash ]---

KVM just happens to have a fairly large, multi line panic string.

	M.

-- 
Without deviation from the norm, progress is not possible.
_______________________________________________
kvmarm mailing list
kvmarm@lists.cs.columbia.edu
https://lists.cs.columbia.edu/mailman/listinfo/kvmarm