bhyve(8) tracing with ktr(4)

When tracing spurious guest errors in bhyve(8) such as double and triple faults, it can be extremely useful to actually check what’s going on.

Since revision 276098 bhyve(8) includes some ktr(4) tracing functionality.

To use this, build the kernel with:

options KTR
options KTR_ENTRIES=(4*1024*1024)
options KTR_MASK=(KTR_GEN)

To enable bhyve tracing through ktr(4), set the following tunable in /boot/loader.conf:

debug.ktr.verbose = 1
hw.vmm.trace_guest_exceptions = 1

debug.ktr.verbose is not necessary, but quite useful to follow ktr(4) entries on the console.

The ktr(4) buffer refills quite quickly, so it’s best to dump it directly after running bhyve(8):

bhyve <args>; ktrdump -cto /tmp/ktrdump.out

And finally, here’s a trace of a guest triple-faulting due to not having a page fault handler:

index  cpu timestamp        trace
------ --- ---------------- -----
   673   0     350887364560 vm testing[0]: vcpu state changed from frozen to idle
   672   0     350887363766 vm testing[0]: retu 0/14
   671   0     350887362932 vm testing[0]: All vcpus suspended
   670   0     350887357212 vm testing[0]: vcpu state changed from running to frozen
   669   0     350887350444 vm testing[0]: returning from vmx_run: exitcode 14
   668   0     350887348806 vm testing: virtual machine successfully suspended 4
   667   0     350887347712 vm testing[0]: triple fault: info1(0x80000b08), info2(0x80000b0e)
   666   0     350887347590 vm testing[0]: Exception 14 delivered: 0x80000b0e
   665   0     350887346312 vm testing[0]: handled exception vmexit at 0x102a56
   664   0     350887346178 vm testing[0]: Exception 14 pending
   663   0     350887346060 vm testing[0]: Setting intr_shadow to 0 succeeded
   662   0     350887341876 vm testing[0]: Reflecting exception 14/0 into the guest
   661   0     350887339570 vm testing[0]: vm_exit_intinfo: info1(0x80000b08)
   660   0     350887315326 vm testing[0]: Resume execution at 0x102a56
   659   0     350887311168 vm testing[0]: vm_entry_intinfo: info1(0x80000b0e), info2(0x80000b0e), retinfo(0x80000b08)
   658   0     350887310988 vm testing[0]: Exception 14 delivered: 0x80000b0e
   657   0     350887309700 vm testing[0]: handled exception vmexit at 0x102a56
   656   0     350887309570 vm testing[0]: Exception 14 pending
   655   0     350887309442 vm testing[0]: Setting intr_shadow to 0 succeeded
   654   0     350887305126 vm testing[0]: Reflecting exception 14/0 into the guest
   653   0     350887302436 vm testing[0]: vm_exit_intinfo: info1(0x80000b0e)
   652   0     350887248280 vm testing[0]: Resume execution at 0x102a56
   651   0     350887184160 vm testing[0]: vm_entry_intinfo: info1(0), info2(0x80000b0e), retinfo(0x80000b0e)
   650   0     350887184040 vm testing[0]: Exception 14 delivered: 0x80000b0e
   649   0     350887182668 vm testing[0]: handled exception vmexit at 0x102a56
   648   0     350887182374 vm testing[0]: Exception 14 pending
   647   0     350887182240 vm testing[0]: Setting intr_shadow to 0 succeeded
   646   0     350887176682 vm testing[0]: Reflecting exception 14/0 into the guest
   645   0     350887149146 vm testing[0]: Resume execution at 0x102f9b
   644   0     350887145218 vm testing[0]: handled cpuid vmexit at 0x102f99
   643   0     350887143374 vm testing[0]: cpuid 0x40000000,0x100fd8
   642   0     350887121556 vm testing[0]: Resume execution at 0x102f9b
   641   0     350887117424 vm testing[0]: handled cpuid vmexit at 0x102f99
   640   0     350887102692 vm testing[0]: cpuid 0x1,0x100fd8
   639   0     350887079146 vm testing[0]: Resume execution at 0x102f9b
   638   0     350887074874 vm testing[0]: handled cpuid vmexit at 0x102f99
   637   0     350887061536 vm testing[0]: cpuid 0,0x100fd8
   636   0     350886961656 vm testing[0]: Resume execution at 0x104000
   635   0     350886900428 vm testing[0]: vcpu state changed from frozen to running
   634   0     350886895942 vm testing[0]: vcpu state changed from idle to frozen
   633   0     350886886630 vm testing[0]: vcpu state changed from frozen to idle
   632   0     350886885990 vm testing[0]: Setting nextrip to 0x104000
   631   0     350886802596 vm testing[0]: vcpu state changed from idle to frozen
   630   3     350886414966 vm testing[0]: vcpu state changed from frozen to idle
   629   3     350886414184 vm testing[0]: activated
   628   3     350886412730 vm testing[0]: vcpu state changed from idle to frozen
   627   3     350886137831 vm testing[0]: vcpu state changed from frozen to idle
   626   3     350885989045 vm testing[0]: vcpu state changed from idle to frozen
Use whatever you may find here at your own risk. This is my personal collection of things I feel may be useful to others but there are no guarantees, no warranties nor any form of support. See the FAQ for details.