Skip to content

Commit 23e332a

Browse files
authored
Track per-phase duration on each instance (#223)
* Track per-phase duration for each instance Add a small phasetracking package that records cumulative time spent in each lifecycle phase (running, standby, paused, etc.) using transition bookkeeping. Tracker state is persisted with the instance's stored metadata, so it survives process restarts without a DB migration. Instrument transitions directly in create/start/stop/standby/restore/fork rather than subscribing to the lifecycle event stream — the subscription is lossy, and these numbers will feed billing. Expose current_phase, current_phase_since, and phase_durations_ms on the Instance API so callers (notably the kernel-api billing pipeline) can compute true running time instead of wall-clock since CreatedAt. * gofmt phasetracking * Assert phase tracking in existing standby/fork integration tests Piggyback on the firecracker/QEMU standby-restore cycles and the cloud-hypervisor fork-from-running test to assert end-to-end that transition-site instrumentation is wired up: - after standby: Current == standby, Cumulative[running] > 0 - after restore: Current == running, Cumulative[standby] > 0 - after fork-from-running: fork's Cumulative[running] is zero while source's is non-zero — locks down the Phases.Reset() semantics No new tests, no added sleeps. The assertions read state at the same points where the tests already check State. * Use UTC for now in standby/stop transition timestamps The phase tracker's Since field is persisted and exposed in the API as current_phase_since. standby/stop were initializing `now` as local time while create/start/restore use UTC, leaving downstream consumers with mixed timezone offsets in the serialized value depending on which transition last occurred. Align all transition sites on UTC. StoppedAt moves to UTC as a byproduct, which is the correct normalization anyway. * Deep-copy phase tracker on metadata clone and use UTC in fork cloneStoredMetadata previously shallow-copied the Phases tracker, which aliased the Cumulative map between source and forked metadata — a subsequent Record on either side would mutate both. Add Tracker.Clone and use it from cloneStoredMetadata. Also normalise the fork transition timestamp to UTC for consistency with the other transition sites. * Mirror public State in phase tracking via lazy boot-marker hydration The recording sites previously jumped straight to PhaseRunning the moment the VMM was up, but the public State machine stays in Initializing until both ProgramStartedAt and GuestAgentReadyAt are hydrated from the guest serial log. That meant Phases.Current reported "running" while the API reported "Initializing". Make phase tracking honest: - create/start record PhaseInitializing on VM boot - restore inspects the preserved markers and records whichever phase the guest is actually in (Running in the common case) - hydrateBootMarkersFromLogs / persistBootMarkers detect the Initializing → Running boundary and Record(PhaseRunning) using the later marker timestamp, so the accrued Initializing duration matches real guest boot time rather than the wall clock when hydration ran Transient internal substates (Paused/Shutdown inside Standby/Stop) remain unrecorded — they're sub-ms blips inside non-yielding orchestration that no external observer can see. * phasetracking: drop unused PhasePaused/PhaseShutdown constants They were never recorded — internal Paused/Shutdown substates happen inside non-yielding orchestration calls and are intentionally not tracked (already documented in the package doc). * phasetracking: clamp marker-derived transition time to Phases.Since After a restore from early-standby (instance standbyed before boot markers ever hydrated), Phases.Since is set at restore time. The markers parsed afterwards can carry timestamps from the pre-standby boot session, predating Since by the entire standby interval. Without the clamp, Record would silently skip the negative-elapsed accrual but still move Since backwards — and every subsequent transition would then over-count Running. Since this field feeds billing, clamp forward so Since is monotonic. Adds a regression test covering the early-standby restore path. --------- Co-authored-by: sjmiller609 <7516283+sjmiller609@users.noreply.github.com>
1 parent 0c9574c commit 23e332a

18 files changed

Lines changed: 1035 additions & 274 deletions

cmd/api/api/instances.go

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1121,6 +1121,22 @@ func instanceToOAPI(inst instances.Instance) oapi.Instance {
11211121
oapiInst.Gpu = gpu
11221122
}
11231123

1124+
// Expose phase accounting (cumulative time in each lifecycle phase). The
1125+
// snapshot rolls in time accrued in the current phase since the last
1126+
// transition, so consumers don't need a separate "live since" calculation.
1127+
if inst.Phases.Current != "" {
1128+
current := string(inst.Phases.Current)
1129+
oapiInst.CurrentPhase = &current
1130+
since := inst.Phases.Since
1131+
oapiInst.CurrentPhaseSince = &since
1132+
snapshot := inst.Phases.Snapshot(time.Now())
1133+
out := make(map[string]int64, len(snapshot))
1134+
for k, v := range snapshot {
1135+
out[string(k)] = v
1136+
}
1137+
oapiInst.PhaseDurationsMs = &out
1138+
}
1139+
11241140
return oapiInst
11251141
}
11261142

cmd/api/api/instances_test.go

Lines changed: 59 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@ import (
1111
"github.com/kernel/hypeman/lib/autostandby"
1212
"github.com/kernel/hypeman/lib/hypervisor"
1313
"github.com/kernel/hypeman/lib/instances"
14+
"github.com/kernel/hypeman/lib/instances/phasetracking"
1415
mw "github.com/kernel/hypeman/lib/middleware"
1516
"github.com/kernel/hypeman/lib/oapi"
1617
"github.com/kernel/hypeman/lib/paths"
@@ -531,6 +532,64 @@ func TestCreateInstance_InvalidStandbyCompressionDelayInSnapshotPolicy(t *testin
531532
assert.Contains(t, badReq.Message, "standby_compression_delay")
532533
}
533534

535+
func TestInstanceToOAPI_EmitsPhaseAccounting(t *testing.T) {
536+
t.Parallel()
537+
538+
t0 := time.Now().Add(-10 * time.Minute)
539+
tr := phasetracking.Tracker{}
540+
tr.Record(phasetracking.PhaseRunning, t0)
541+
tr.Record(phasetracking.PhaseStandby, t0.Add(60*time.Second))
542+
tr.Record(phasetracking.PhaseRunning, t0.Add(60*time.Second+5*time.Minute))
543+
544+
inst := instances.Instance{
545+
StoredMetadata: instances.StoredMetadata{
546+
Id: "inst-phases",
547+
Name: "inst-phases",
548+
Image: "docker.io/library/alpine:latest",
549+
CreatedAt: t0,
550+
HypervisorType: hypervisor.TypeCloudHypervisor,
551+
Phases: tr,
552+
},
553+
State: instances.StateRunning,
554+
}
555+
556+
oapiInst := instanceToOAPI(inst)
557+
558+
require.NotNil(t, oapiInst.CurrentPhase)
559+
assert.Equal(t, "running", *oapiInst.CurrentPhase)
560+
require.NotNil(t, oapiInst.CurrentPhaseSince)
561+
require.NotNil(t, oapiInst.PhaseDurationsMs)
562+
563+
durations := *oapiInst.PhaseDurationsMs
564+
// Standby stint was a completed 300s window — no live accrual since.
565+
assert.Equal(t, int64(300_000), durations["standby"])
566+
// Running = 60s completed + live time since latest Record. The
567+
// recorded-at instant is in the past, so this must be >= 60s.
568+
assert.GreaterOrEqual(t, durations["running"], int64(60_000),
569+
"running should include the completed 60s stint")
570+
}
571+
572+
func TestInstanceToOAPI_OmitsPhaseFieldsWhenUnset(t *testing.T) {
573+
t.Parallel()
574+
575+
inst := instances.Instance{
576+
StoredMetadata: instances.StoredMetadata{
577+
Id: "inst-no-phases",
578+
Name: "inst-no-phases",
579+
Image: "docker.io/library/alpine:latest",
580+
CreatedAt: time.Now(),
581+
HypervisorType: hypervisor.TypeCloudHypervisor,
582+
},
583+
State: instances.StateStopped,
584+
}
585+
586+
oapiInst := instanceToOAPI(inst)
587+
588+
assert.Nil(t, oapiInst.CurrentPhase)
589+
assert.Nil(t, oapiInst.CurrentPhaseSince)
590+
assert.Nil(t, oapiInst.PhaseDurationsMs)
591+
}
592+
534593
func TestInstanceToOAPI_EmitsStandbyCompressionDelayInSnapshotPolicy(t *testing.T) {
535594
t.Parallel()
536595

lib/instances/create.go

Lines changed: 7 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@ import (
1313
"github.com/kernel/hypeman/lib/guestmemory"
1414
"github.com/kernel/hypeman/lib/hypervisor"
1515
"github.com/kernel/hypeman/lib/images"
16+
"github.com/kernel/hypeman/lib/instances/phasetracking"
1617
"github.com/kernel/hypeman/lib/logger"
1718
"github.com/kernel/hypeman/lib/network"
1819
"github.com/kernel/hypeman/lib/system"
@@ -496,6 +497,7 @@ func (m *manager) createInstance(
496497
}
497498
bootStart := time.Now().UTC()
498499
stored.StartedAt = &bootStart
500+
stored.Phases.Record(phasetracking.PhaseCreated, bootStart)
499501

500502
// 18. Save metadata
501503
log.DebugContext(ctx, "saving instance metadata", "instance_id", id)
@@ -528,7 +530,11 @@ func (m *manager) createInstance(
528530
reservedResources = false
529531
}
530532

531-
// 20. Persist runtime metadata updates after VM boot.
533+
// 20. Persist runtime metadata updates after VM boot. The VMM is up but
534+
// guest boot markers have not yet been written, so we are in Initializing;
535+
// persistBootMarkers will advance us to Running once the markers appear
536+
// in the serial log.
537+
stored.Phases.Record(phasetracking.PhaseInitializing, time.Now().UTC())
532538
meta = &metadata{StoredMetadata: *stored}
533539
if err := m.saveMetadata(meta); err != nil {
534540
// VM is running but metadata failed - log but don't fail

lib/instances/firecracker_test.go

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@ import (
1717
"github.com/kernel/hypeman/lib/devices"
1818
"github.com/kernel/hypeman/lib/hypervisor"
1919
"github.com/kernel/hypeman/lib/images"
20+
"github.com/kernel/hypeman/lib/instances/phasetracking"
2021
"github.com/kernel/hypeman/lib/network"
2122
"github.com/kernel/hypeman/lib/paths"
2223
"github.com/kernel/hypeman/lib/resources"
@@ -163,6 +164,7 @@ func TestFirecrackerStandbyAndRestore(t *testing.T) {
163164
inst, err = waitForInstanceState(ctx, mgr, inst.Id, StateRunning, integrationTestTimeout(20*time.Second))
164165
require.NoError(t, err)
165166
require.NoError(t, waitForExecAgent(ctx, mgr, inst.Id, 30*time.Second))
167+
assert.Equal(t, phasetracking.PhaseRunning, inst.Phases.Current, "fresh instance should be in running phase")
166168

167169
firstFilePath := "/tmp/firecracker-standby-first.txt"
168170
secondFilePath := "/tmp/firecracker-standby-second.txt"
@@ -222,10 +224,14 @@ func TestFirecrackerStandbyAndRestore(t *testing.T) {
222224
t.Logf("first standby (full snapshot expected) took %v", firstStandbyDuration)
223225
assert.Equal(t, StateStandby, inst.State)
224226
assert.True(t, inst.HasSnapshot)
227+
assert.Equal(t, phasetracking.PhaseStandby, inst.Phases.Current, "standby transition should set current phase")
228+
assert.Greater(t, inst.Phases.Cumulative[phasetracking.PhaseRunning], int64(0), "first running stint should be accrued after standby")
225229

226230
firstRestoreRunningDuration, _ := restoreAndMeasure("first")
227231
assert.False(t, inst.HasSnapshot, "running instances should not expose retained snapshot bases as standby snapshots")
228232
assertRetainedBaseState()
233+
assert.Equal(t, phasetracking.PhaseRunning, inst.Phases.Current, "restored instance should be in running phase")
234+
assert.Greater(t, inst.Phases.Cumulative[phasetracking.PhaseStandby], int64(0), "first standby stint should be accrued after restore")
229235
t.Logf("first full-cycle timings: standby=%v restore-to-running=%v", firstStandbyDuration, firstRestoreRunningDuration)
230236

231237
assertGuestFileContents(firstFilePath, firstFileContents)
@@ -245,6 +251,7 @@ func TestFirecrackerStandbyAndRestore(t *testing.T) {
245251
secondRestoreRunningDuration, _ := restoreAndMeasure("second")
246252
assert.False(t, inst.HasSnapshot, "running instances should not expose retained snapshot bases as standby snapshots")
247253
assertRetainedBaseState()
254+
assert.Equal(t, phasetracking.PhaseRunning, inst.Phases.Current, "second restore should land back in running")
248255
t.Logf("second diff-cycle timings: standby=%v restore-to-running=%v", secondStandbyDuration, secondRestoreRunningDuration)
249256

250257
assertGuestFileContents(secondFilePath, secondFileContents)

lib/instances/fork.go

Lines changed: 14 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@ import (
1313
"github.com/kernel/hypeman/lib/forkvm"
1414
"github.com/kernel/hypeman/lib/guest"
1515
"github.com/kernel/hypeman/lib/hypervisor"
16+
"github.com/kernel/hypeman/lib/instances/phasetracking"
1617
"github.com/kernel/hypeman/lib/logger"
1718
"github.com/kernel/hypeman/lib/network"
1819
"github.com/nrednav/cuid2"
@@ -267,7 +268,7 @@ func (m *manager) forkInstanceFromStoppedOrStandby(ctx context.Context, id strin
267268
return nil, fmt.Errorf("get vm starter: %w", err)
268269
}
269270

270-
now := time.Now()
271+
now := time.Now().UTC()
271272
forkMeta := cloneStoredMetadataWithoutPendingStandbyCompression(meta.StoredMetadata)
272273
forkMeta.Id = forkID
273274
forkMeta.Name = req.Name
@@ -280,6 +281,17 @@ func (m *manager) forkInstanceFromStoppedOrStandby(ctx context.Context, id strin
280281
forkMeta.VsockSocket = m.paths.InstanceSocket(forkID, hypervisor.VsockSocketNameForType(forkMeta.HypervisorType))
281282
forkMeta.ExitCode = nil
282283
forkMeta.ExitMessage = ""
284+
// Forks are new instances; phase accounting must not inherit the source's
285+
// cumulative durations. The first transition into the fork's runtime
286+
// phase (Standby for snapshot forks, Stopped for stopped forks) will be
287+
// recorded by the appropriate operation when the fork is acted on.
288+
forkMeta.Phases.Reset()
289+
switch source.State {
290+
case StateStandby:
291+
forkMeta.Phases.Record(phasetracking.PhaseStandby, now)
292+
case StateStopped:
293+
forkMeta.Phases.Record(phasetracking.PhaseStopped, now)
294+
}
283295

284296
// Keep the original CID for snapshot-based forks.
285297
// Rewriting CID in restored memory snapshots is not reliable across
@@ -514,6 +526,7 @@ func cloneStoredMetadata(src StoredMetadata) StoredMetadata {
514526
exitCode := *src.ExitCode
515527
dst.ExitCode = &exitCode
516528
}
529+
dst.Phases = src.Phases.Clone()
517530

518531
return dst
519532
}

lib/instances/fork_test.go

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@ import (
1818
"github.com/kernel/hypeman/lib/guest"
1919
"github.com/kernel/hypeman/lib/hypervisor"
2020
"github.com/kernel/hypeman/lib/images"
21+
"github.com/kernel/hypeman/lib/instances/phasetracking"
2122
"github.com/kernel/hypeman/lib/paths"
2223
snapshotstore "github.com/kernel/hypeman/lib/snapshot"
2324
"github.com/stretchr/testify/assert"
@@ -548,6 +549,14 @@ func TestForkCloudHypervisorFromRunningNetwork(t *testing.T) {
548549
assert.NotEqual(t, sourceAfterFork.MAC, forked.MAC)
549550
assertGuestHasOnlyExpectedIPv4(t, forked, forked.IP, 30*time.Second)
550551
assertHostCanReachNginx(t, forked.IP, 80, 60*time.Second)
552+
553+
// Fork must start with a fresh phase ledger and not inherit the source's
554+
// accumulated running time. The source has completed at least one running
555+
// stint by now (running -> internal-standby -> running); the fork is still
556+
// in its first running stint and so has no completed running ms logged.
557+
assert.Equal(t, phasetracking.PhaseRunning, forked.Phases.Current)
558+
assert.Zero(t, forked.Phases.Cumulative[phasetracking.PhaseRunning], "fork should not inherit source's running ledger")
559+
assert.Greater(t, sourceAfterFork.Phases.Cumulative[phasetracking.PhaseRunning], int64(0), "source's pre-fork running stint should be cumulated")
551560
}
552561

553562
func assertHostCanReachNginx(t *testing.T, ip string, port int, timeout time.Duration) {
Lines changed: 114 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,114 @@
1+
// Package phasetracking accumulates cumulative time-in-phase for instance
2+
// lifecycle phases. The tracker is embedded in instance metadata and updated
3+
// at every externally-observable state transition so consumers can use the
4+
// resulting durations for billing, observability, and analytics.
5+
//
6+
// Phases mirror the externally-observable values of instances.State (lowercased
7+
// so they remain stable in the API surface even if the internal enum is
8+
// renamed). The Initializing→Running transition is detected lazily when guest
9+
// boot markers are persisted, so the tracker reflects the same view of guest
10+
// readiness that the public State machine reports — not the bare moment the
11+
// VMM process came up.
12+
//
13+
// Transient internal substates that no external observer can see — for example
14+
// the Paused/Shutdown steps inside a single Standby or Stop orchestration — are
15+
// intentionally not recorded; they would be sub-millisecond blips inside a
16+
// non-yielding function call that adds noise without truth.
17+
//
18+
// Only the transition orchestration sites in lib/instances should call Record.
19+
// The tracker intentionally does not subscribe to the lifecycle event bus —
20+
// that bus is best-effort and lossy, which is unsuitable for billing.
21+
package phasetracking
22+
23+
import "time"
24+
25+
// Phase is the canonical lifecycle phase name. Values mirror instances.State
26+
// lowercased so they remain stable in the API surface even if the internal
27+
// State enum is renamed.
28+
type Phase string
29+
30+
const (
31+
PhaseStopped Phase = "stopped"
32+
PhaseCreated Phase = "created"
33+
PhaseInitializing Phase = "initializing"
34+
PhaseRunning Phase = "running"
35+
PhaseStandby Phase = "standby"
36+
)
37+
38+
// Tracker accumulates cumulative wall-clock time spent in each phase.
39+
//
40+
// Invariants:
41+
// - Cumulative[phase] is the total ms spent in `phase` across all prior
42+
// completed visits to that phase.
43+
// - Time spent in the *current* phase (since `Since`) is NOT yet rolled into
44+
// Cumulative — callers that want "live" totals should use Snapshot.
45+
// - Current and Since must be updated atomically with Cumulative; that's
46+
// the contract of Record. Direct mutation is not supported.
47+
//
48+
// The zero value is valid: it represents an instance that has not entered
49+
// any phase yet. The first Record call sets Current and Since without
50+
// accruing time (there is no prior phase to accrue from).
51+
type Tracker struct {
52+
Current Phase `json:"current,omitempty"`
53+
Since time.Time `json:"since,omitempty"`
54+
Cumulative map[Phase]int64 `json:"cumulative,omitempty"`
55+
}
56+
57+
// Record transitions into newPhase as of `now`, first accruing time-in-current
58+
// into Cumulative. Safe to call on a zero-value Tracker (first transition has
59+
// no prior phase, so no accrual happens).
60+
//
61+
// `now` is a parameter rather than time.Now() so tests can pin time and so
62+
// callers can use the same `now` value they're persisting elsewhere on the
63+
// metadata (e.g. StartedAt) without drift.
64+
func (t *Tracker) Record(newPhase Phase, now time.Time) {
65+
if t.Cumulative == nil {
66+
t.Cumulative = make(map[Phase]int64)
67+
}
68+
if t.Current != "" && !t.Since.IsZero() {
69+
elapsed := now.Sub(t.Since).Milliseconds()
70+
if elapsed > 0 {
71+
t.Cumulative[t.Current] += elapsed
72+
}
73+
}
74+
t.Current = newPhase
75+
t.Since = now
76+
}
77+
78+
// Snapshot returns a copy of Cumulative with the in-flight time-in-current
79+
// rolled in, without mutating the tracker. Use this when reporting "running
80+
// time so far" — typically in the API response path.
81+
func (t Tracker) Snapshot(now time.Time) map[Phase]int64 {
82+
out := make(map[Phase]int64, len(t.Cumulative)+1)
83+
for k, v := range t.Cumulative {
84+
out[k] = v
85+
}
86+
if t.Current != "" && !t.Since.IsZero() {
87+
elapsed := now.Sub(t.Since).Milliseconds()
88+
if elapsed > 0 {
89+
out[t.Current] += elapsed
90+
}
91+
}
92+
return out
93+
}
94+
95+
// Reset clears all accumulated state. Used when forking — the fork is a new
96+
// instance and must not inherit the source's phase history.
97+
func (t *Tracker) Reset() {
98+
t.Current = ""
99+
t.Since = time.Time{}
100+
t.Cumulative = nil
101+
}
102+
103+
// Clone returns a deep copy of the tracker. The returned tracker shares no
104+
// state with the receiver, so independent Record/Reset calls do not interfere.
105+
func (t Tracker) Clone() Tracker {
106+
dst := t
107+
if t.Cumulative != nil {
108+
dst.Cumulative = make(map[Phase]int64, len(t.Cumulative))
109+
for k, v := range t.Cumulative {
110+
dst.Cumulative[k] = v
111+
}
112+
}
113+
return dst
114+
}

0 commit comments

Comments
 (0)