Hypervisor trace events

The following should help you interpret the data provided with Class 10 events from a hypervisor host.

ID 0 — guest entry

The guest is executing code at guest_ip address.

Arguments:

guest_ip: The execution address, as seen by the guest.

Note: The timestamp for the ID 0 event should not be used to calculate the time spent in the guest during an entry/exit cycle. For an explanation, see the note in the ID 7 event description.

ID 1 — guest exit

The guest has stopped executing code.

Arguments:

status: Architecture-specific. On x86 platforms, a non-zero ID 1 status field indicates that the guest entry was aborted before guest was able to run.
reason: Architecture-specific.
clockcycles_offset: Offset between guest view of timestamp and host view of timestamp. Measured in clock cycles (see ClockCycles() in the C Library Reference). A negative number means the guest is behind the host; a positive number means the guest is ahead of the host.; On x86 platforms, if the status field is non-zero, the guest didn't run, so the value of clockcycles_offset is stale (and therefore meaningless).
guest_ip: The execution address, as seen by the guest.
hw_payload: Architecture-specific.

Note:

For both ARM and x86 platforms, to know if the guest actually ran before it exited, check for the presence of ID 7 events between the ID 0 and ID 1 events (see “ID 7 — provide guest clock cycle values at guest entry and exit” below). If no ID 7 events are present, then the guest didn't run.

The timestamp for the ID 1 event should not be used to calculate the time spent in the guest during an entry/exit cycle. For an explanation, see the note in the ID 7 event description.

ID 2 — create a vCPU thread

A virtual CPU (vCPU) thread has been created to schedule the vCPU.

Occurs only once per vCPU in the lifetime of a qvm process instance. If you start your trace after the qvm process has started, you won't see these events.

Arguments:

vcpu_id: vCPU-specific ID internal to hypervisor. The ID number as seen in the trace logs will be marked as virtual cpu num, where num is the vCPU number, starting at 0 (zero).

ID 3 — assert an interrupt to a guest CPU

An interrupt has been asserted on a vCPU (seen by the guest as a CPU). The VM (qvm process instance) in which the guest is running must be configured to deliver the interrupt to the guest. This configuration is specified in the *.qvmconf file for the qvm process instance.

Arguments:

vcpu_id: ID of the vCPU where the interrupt is being asserted.
interrupt: The interrupt as seen by the guest (e.g., on x86-64 platforms, a vector number).

ID 4 — de-assert an interrupt to a guest CPU

An interrupt is being de-asserted on a vCPU (seen by the guest as a CPU).

Arguments:

vcpu_id: ID of the vCPU where the interrupt is being de-asserted.
interrupt: The interrupt as seen by the guest (e.g., on x86-64 platforms, a vector number).

ID 5 — create a virtual timer

A timer has been created for a vCPU.

Occurs only once per timer in the lifetime of a qvm process instance. If you start your trace after the qvm process has started, you may not see these events.

Arguments:

timer_id: The value returned by timer_create(), which has been called by the qvm process instance.
cpu_id: The ID of the vCPU where the timer was created.

ID 6 — trigger a virtual timer

A virtual timer has been triggered.

Argument:

timer_id: The ID of the vCPU where the timer was triggered.

ID 7 — provide guest clock cycle values at guest entry and exit

Guest clock cycle values at guest entry and exit.

Arguments:

at_entry: The guest clock cycles (ClockCycles()) value at guest entry.
at_exit: The guest clock cycles value at guest exit.

The Cycles trace event records the amount of time spent in the guest between Entry/Exit trace events.

Note:

You can't draw meaningful conclusions from the difference between the timestamps of the Entry (ID 0) and Exit (ID 1) events. These events are emitted at the user level, and thus the vCPU thread can be preempted, migrated, interrupted, etc. between the time of the guest exit and re-entry.

This is especially true on a system where the host OS is heavily loaded by threads that are unrelated to the hypervisor's vCPU threads. Also, work is often done in a hypervisor-privileged context when the hypervisor prepares to enter a guest and when it handles a guest exit.

The Cycles trace event should be used because it includes only the time spent in the guest and excludes both the time that the hypervisor may not have been running and the time taken to perform the guest exit/enter processing.

For an example of how you can interpret the trace events emitted by a hypervisor to measure its overhead, see “Measuring the hypervisor overhead” below.

Kernel call events

The kernel calls you will see in trace logs for a hypervisor host will also include events that are not specific to the hypervisor, such as MMap and MMunmap. See the System Analysis Toolkit User's Guide for more information about kernel call trace events.

Measuring the hypervisor overhead

If you want to measure the hypervisor overhead, you must have an accurate indication of the time spent in the guest versus the time spent in the host. Here, we list some of the trace events emitted by the hypervisor during a guest entry/exit cycle and show how to calculate the percentage of time spent in the guest.

In the pseudo-code example below, we provide an abstract and idealized vCPU loop:

begin
    HYP EL 0 - Guest Entry Trace Event
    HYP EL 0 - prepare to enter guest
    HYP EL 2 - enter guest 
    GST EL 0/1 - running in guest
    HYP EL 2 - guest exited because the CPU needs the hypervisor to intervene
    HYP EL 0 - Cycles + Guest Exit Trace Events
    HYP EL 0 - handle guest exit (may involve a vdev or emulation of PSCI calls, etc.)
end

While the vCPU thread is running hypervisor code at EL 0, the host QNX Neutrino OS sees it as an ordinary application and will handle interrupts and context switch between host threads. Some systems run other software on the host, at the same or higher thread priorities as the vCPUs, that's unrelated to what the hypervisor and guest are doing. If you take the difference between the guest exit and guest entry timestamps, you will include all time that is completely dependent on what the other software concurrently running on the host is doing. This other time is not hypervisor overhead.

The Cycles trace event provides the start and end times between which the guest ran during the entry/exit cycle. Subtracting the start time from the end time provides the actual time spent in the guest. If you want to know when those times were from the host's perspective, then examine the “offset” value in the Exit trace event; this lets you convert the start or end time from the Cycles event into a timestamp that is meaningful for the host.

We can measure the hypervisor overhead as the percentage of time spent in the guest, as follows:

% time in guest = (time spent in guest) / (total thread RUNNING time between guest exit and entry)

Note that:

Determining the amount of thread RUNNING time involves many other QNX Neutrino trace events.
Given the variation in overheads from one exit to another, you would usually do this calculation across a time interval spanning many entry/exit cycles.