qemu exporter: virtiofs energy_uj counter grows 5× too slow due to missing step duration multiplication

[jaimeib]

Bug description

The qemu exporter writes ~5× less energy to the virtiofs energy_uj file than it should, causing scaph_host_power_microwatts inside the VM to report ~5× lower than the real power consumption of the VM.

The root cause is in src/exporters/qemu.rs. The main loop runs every 5 seconds and computes the energy to add to the virtiofs counter as:

let uj_to_add = ratio.value.parse::<f64>().unwrap()
    * topo_energy.value.parse::<f64>().unwrap()
    / 100.0;

topo_energy is the return value of topology.get_records_diff_power_microwatts(), which is correctly documented and implemented — it returns instantaneous power in µW (µJ/s), not accumulated energy:

/// Returns a Record instance containing the power consumed between
/// last and previous measurement, in microwatts.
pub fn get_records_diff_power_microwatts(&self) -> Option<Record> {
    ...
    let microwatts = microjoules as f64 / time_diff;
    return Some(Record::new(..., (microwatts as u64).to_string(), units::Unit::MicroWatt));
}

The bug is in the caller — the qemu exporter uses this µW value as if it were µJ and adds it directly to energy_uj without converting. To convert power to energy over one loop iteration, the result must be multiplied by the step duration in seconds:

energy (µJ) = power (µW) × time (s)

Without this factor, each 5-second cycle adds only ~1 second worth of energy to the counter instead of 5 seconds. The virtiofs counter grows 5× slower than it should, and Scaphandre inside the VM reads that counter and reports ~5× lower than the real power consumption.

The proposed fix is a single-line change in iterate():

// current (incorrect):
let uj_to_add = ratio.value.parse::<f64>().unwrap()
    * topo_energy.value.parse::<f64>().unwrap()
    / 100.0;

// corrected:
let uj_to_add = ratio.value.parse::<f64>().unwrap()
    * topo_energy.value.parse::<f64>().unwrap()
    / 100.0
    * step_secs;  // step_secs = 5.0 with the current default, passed from run()

To Reproduce

1. Run scaphandre qemu on a hypervisor with at least one running VM and virtiofs configured.
2. Run scaphandre --vm prometheus inside the VM.
3. Record scaph_host_power_microwatts inside the VM.
4. On the hypervisor, record scaph_process_power_consumption_microwatts for the qemu process of the same VM.
5. Compare: the value inside the VM will be ~5× lower than the value on the hypervisor.

To verify the root cause directly, measure the virtiofs counter delta over the same time window:

T1_RAPL=$(cat /sys/class/powercap/intel-rapl:0/energy_uj)
T1_VFS=$(cat /var/lib/libvirt/scaphandre/<vm-name>/intel-rapl:0/energy_uj)
sleep 30
T2_RAPL=$(cat /sys/class/powercap/intel-rapl:0/energy_uj)
T2_VFS=$(cat /var/lib/libvirt/scaphandre/<vm-name>/intel-rapl:0/energy_uj)
echo "RAPL delta: $((T2_RAPL - T1_RAPL)) µJ"
echo "VFS delta:  $((T2_VFS - T1_VFS)) µJ"
echo "VFS × 5:   $(( (T2_VFS-T1_VFS)*5 )) µJ"

VFS × 5 will closely match the energy proportional to the VM's CPU share, while the raw VFS delta will be ~5× too low.

Additionally, writing a known value manually to the virtiofs counter (bypassing the qemu exporter) confirms the VM-side agent reads and computes correctly. Incrementing the counter by 100,000 µW × 5s = 500,000 µJ every 5 seconds produces ~99,360 µW inside the VM (0.64% error, consistent with bash sleep jitter), confirming the bug is entirely in the write side.

Expected behavior

scaph_host_power_microwatts inside the VM should match scaph_process_power_consumption_microwatts of the corresponding qemu process on the hypervisor (within measurement noise). The energy written to the virtiofs counter per loop cycle should equal ratio% × topo_power_µW / 100 × step_seconds.

Screenshots

Single-script measurement run (30 seconds, all values captured simultaneously):

Delta RAPL total (S0+S1+DRAM): 1,793,372,378 µJ in 30s → 59,779,079 µW
scaph_host_power_microwatts (hypervisor):            59,992,820 µW   ← correct (0.3% error vs RAPL)

scaph_process_cpu_usage_percentage (qemu):            0.21535%
scaph_process_power_consumption_microwatts (qemu):  129,196 µW       ← correct (59,992,820 × 0.21535 / 100 = 129,200 µW)

Delta virtiofs:                    754,170 µJ
Expected in virtiofs (30s):      3,875,880 µJ  (129,196 µW × 30s)
Actual virtiofs × 5:             3,770,850 µJ  ← matches expected within 2.7% ✓
Factor:                               5.14×

scaph_host_power_microwatts (inside VM):   ~22,000 µW   ← reported (~5× too low)
Expected (from hypervisor):              ~129,000 µW   ← real

The 2.7% residual error after applying ×5 is consistent with scheduler jitter in the 5-second sleep and the non-perfect alignment between our measurement window and the exporter's internal cycle.

Environment

• Linux distribution: hypervisor Ubuntu 22.04 LTS, VM Ubuntu 24.04 LTS
• Kernel version: (standard kernel for each distro)
• Scaphandre version: v1.0.2 on both hypervisor and VM
• Hypervisor CPU: 2 physical sockets, 20 cores/socket, 2 threads/core = 80 logical CPUs
• VM: 8 vCPUs, 16 GB RAM

Additional context

This bug affects all deployments using scaphandre qemu regardless of the number of sockets, since the missing factor is the loop step (5s by default), not a socket count. The step value is hardcoded — if a --step CLI flag is added to the qemu subcommand in the future, passing step.as_secs_f64() into iterate() would make the fix work correctly for any step value without further changes.

The same underreporting affects scaph_process_power_consumption_microwatts for all processes and containers running inside the VM, since container-level power is derived proportionally from scaph_host_power_microwatts.

[jaimeib]

Additional validation: graphical confirmation of the ×5 factor and residual timing offset

We plotted scaph_host_power_microwatts (inside the VM) against scaph_process_power_consumption_microwatts{vmname="instance-001096a9"} (hypervisor, qemu process) over the same 30-minute window, sampled every 30 seconds. In both screenshots, the blue line is the VM's power as reported from the hypervisor (scaph_process_power_consumption_microwatts), and the green line is the power reported by the agent running inside the VM itself (scaph_host_power_microwatts).

Figure 1 — without correction, the VM-side series (green) sits consistently ~5× below the hypervisor-side series (blue) across the entire window, matching the earlier findings.

Figure 2 — with the ×5 correction applied to the VM series (label_replace(scaph_host_power_microwatts, "source", "vm", "", "") * 5), the two series align closely in magnitude, but a residual timing offset remains visible — peaks and valleys in one series don't always land on the same sample as in the other, and some transitions appear shifted by one tick.

This is expected and does not indicate an additional bug. There are three independent, unsynchronized clocks in the measurement chain:

1. The scaphandre prometheus agent on the hypervisor, which computes scaph_process_power_consumption_microwatts on its own refresh cycle (tied to HTTP scrape requests, minimum ~2s between refreshes).
2. The scaphandre qemu agent on the hypervisor, which writes to the virtiofs counter on its own 5-second loop, with no coordination with (1).
3. The scaphandre prometheus agent inside the VM, which reads the virtiofs counter and computes scaph_host_power_microwatts on its own refresh cycle, unaware of when (2) actually wrote the last update.

None of the three share a clock or coordinate with each other — each measures its own time window, and those windows overlap imperfectly. The ×5 factor corrects the systematic magnitude error (the missing-step multiplication), but it does not correct the timing misalignment between independent sampling cycles. It's worth noting that the absolute variability introduced by this timing offset is on the order of a few tens of thousands of microwatts (tens of mW) at most, on values in the hundred-thousand-microwatt range — a relatively minor source of noise compared to the ~5× systematic error this issue is about, and not significant in practice for the purpose of tracking VM-level power trends.

It's worth noting that at the process level, only instantaneous power (µW) is available. There is no per-process energy counter to fall back on, since energy accounting in this exporter is inherently derived at the power level for individual processes (the virtiofs energy_uj counter itself is the one artifact that accumulates energy, and that's precisely the object of this bug report). So the timing offset described above is a property of the measurement setup, not something that can be worked around by switching to a rate-based per-process metric.

[jaimeib]

Opened a fix for this: #429

[jaimeib]

Fix applied and validated end-to-end

We applied a fix and validated it against the real hardware described in this issue. The graph below shows the transition clearly: before ~09:35 (green line, VM-reported power) sitting ~5× below the blue line (hypervisor-reported power for the same VM process), and after ~09:35, once the patched package was installed and the service restarted, both lines converge and track each other closely for the remainder of the window — no × 5 correction needed anymore.

The final fix

The originally proposed fix in this issue multiplied the power reading by the loop's step duration (* step_secs) to convert µW into µJ before accumulating. That works, but it ties the correctness of the exporter to an assumed/hardcoded step value, and it doesn't account for scheduler jitter in the thread::sleep between iterations.

A cleaner fix, applied instead: in src/exporters/qemu.rs, replace the call to self.topology.get_records_diff_power_microwatts() with self.topology.get_records_diff() (already defined in src/sensors/mod.rs).

• get_records_diff_power_microwatts() returns power (µJ / actual elapsed time) — exactly the value that caused the bug when it was used as if it were energy.
• get_records_diff() returns the raw energy delta in µJ between the two most recent records directly, with no division/re-multiplication round-trip.

In other words: instead of computing power and then multiplying by an assumed time interval to get back to energy, the fix sums the energy delta directly — the natural unit for an accumulating energy_uj counter.

Advantages over the * step_secs approach:

• Not dependent on any assumed/hardcoded step value — if a --step flag is ever added to the qemu subcommand, this keeps working without any further change.
• Immune to scheduler jitter — it uses the real elapsed time between the two record timestamps, not the nominal 5s interval that the loop's thread::sleep only approximately guarantees.

One minor, unrelated note found while implementing this: get_records_diff() requires record_buffer.len() > 2, while the sibling function get_records_diff_power_microwatts() only requires len() > 1 — both access the same two elements (last() and get(len - 2)), so len() > 1 is sufficient and safe. Relaxing this removes one extra ~5s startup cycle before the qemu exporter begins writing energy.