Cache hypervisor state and bound /vm.info calls in list path (#225)

Tracing on the previous list-path span PR showed single `instances.derive_state`
spans of 10-37s on the dev fleet, with no children — all the time was inside
`hv.GetVMInfo`. The cloud-hypervisor API socket serializes per VM, so a
snapshot in flight from auto-standby parks every concurrent `/vm.info` call
behind it, blocking the entire serial list loop.

Two changes:

1. Cache the last observed hypervisor VM state per instance with a 5s TTL.
   List calls within the TTL skip the HTTP round-trip entirely. Lifecycle
   event notifications (start/stop/standby/restore/delete/...) write through
   the cache so it stays current with state changes hypeman itself drives.

2. Wrap the underlying `GetVMInfo` call in a 500ms timeout. On timeout the
   instance is reported as Unknown (matching today's behavior when the
   hypervisor is unreachable) and the next list call retries.

Together these eliminate the 14-37s tails while leaving the
hypervisor-of-last-resort check intact for crash detection via the TTL
sweep.

Co-authored-by: sjmiller609 <7516283+sjmiller609@users.noreply.github.com>
Co-authored-by: Claude Opus 4.7 <noreply@anthropic.com>

Author: sjmiller609

lib/instances/manager.go

@@ -116,6 +116,7 @@ type manager struct {
 	resourceValidator         ResourceValidator // Optional validator for aggregate resource limits
 	instanceLocks             sync.Map          // map[string]*sync.RWMutex - per-instance locks
 	bootMarkerScans           sync.Map          // map[string]time.Time next allowed boot-marker rescan
+	hypervisorStateCache      sync.Map          // map[string]hypervisorStateCacheEntry - last observed hypervisor state per instance
 	hostTopology              *HostTopology     // Cached host CPU topology
 	metrics                   *Metrics
 	meter                     metric.Meter
@@ -243,6 +244,7 @@ func (m *manager) notifyLifecycleEvent(ctx context.Context, action LifecycleEven
 	if inst == nil {
 		return
 	}
+	m.updateCachedHypervisorStateFromInstance(inst)
 	m.lifecycleEvents.Notify(ctx, LifecycleEvent{
 		Action:     action,
 		InstanceID: inst.Id,
@@ -251,6 +253,7 @@ func (m *manager) notifyLifecycleEvent(ctx context.Context, action LifecycleEven
 }
 
 func (m *manager) notifyLifecycleDelete(ctx context.Context, instanceID string) {
+	m.invalidateCachedHypervisorState(instanceID)
 	m.lifecycleEvents.Notify(ctx, LifecycleEvent{
 		Action:     LifecycleEventDelete,
 		InstanceID: instanceID,

lib/instances/query.go

@@ -25,8 +25,24 @@ const (
 	programStartSentinelPrefix = "HYPEMAN-PROGRAM-START "
 	agentReadySentinelPrefix   = "HYPEMAN-AGENT-READY "
 	bootMarkerRescanInterval   = 1 * time.Second
+	// hypervisorStateCacheTTL bounds how long a cached hypervisor state may be
+	// reused before a fresh GetVMInfo call is required. Short enough to detect
+	// guest-driven shutdowns promptly, long enough that bursty list calls
+	// collapse onto one underlying socket query.
+	hypervisorStateCacheTTL = 5 * time.Second
+	// getVMInfoTimeout bounds a single hypervisor /vm.info query. The cloud
+	// hypervisor API socket serializes requests, so a snapshot in flight can
+	// otherwise park derive_state for tens of seconds.
+	getVMInfoTimeout = 500 * time.Millisecond
 )
 
+// hypervisorStateCacheEntry stores the last observed hypervisor VM state for
+// an instance, used to skip /vm.info queries on hot list paths.
+type hypervisorStateCacheEntry struct {
+	state       hypervisor.VMState
+	refreshedAt time.Time
+}
+
 // stateResult holds the result of state derivation
 type stateResult struct {
 	State               State
@@ -56,39 +72,55 @@ func (m *manager) deriveStateWithOptions(ctx context.Context, stored *StoredMeta
 	// 1. Check if socket exists
 	if _, err := os.Stat(stored.SocketPath); err != nil {
 		// No socket - check for snapshot to distinguish Stopped vs Standby
+		m.invalidateCachedHypervisorState(stored.Id)
 		if m.hasSnapshot(stored.DataDir) {
 			return stateResult{State: StateStandby}
 		}
 		return stateResult{State: StateStopped}
 	}
 
-	// 2. Socket exists - query hypervisor for actual state
-	hv, err := m.getHypervisor(stored.SocketPath, stored.HypervisorType)
-	if err != nil {
-		// Failed to create client - this is unexpected if socket exists
-		errMsg := fmt.Sprintf("failed to create hypervisor client: %v", err)
-		log.WarnContext(ctx, "failed to determine instance state",
-			"instance_id", stored.Id,
-			"socket", stored.SocketPath,
-			"error", err,
-		)
-		return stateResult{State: StateUnknown, Error: &errMsg}
-	}
+	// 2. Socket exists - resolve hypervisor state, preferring the in-memory
+	// cache (populated by lifecycle events and prior queries) and falling
+	// back to a time-bounded /vm.info call.
+	var hvState hypervisor.VMState
+	if cached, ok := m.loadCachedHypervisorState(stored.Id); ok {
+		span.SetAttributes(attribute.Bool("hypervisor_state.cache_hit", true))
+		hvState = cached
+	} else {
+		span.SetAttributes(attribute.Bool("hypervisor_state.cache_hit", false))
+		hv, err := m.getHypervisor(stored.SocketPath, stored.HypervisorType)
+		if err != nil {
+			// Failed to create client - this is unexpected if socket exists
+			errMsg := fmt.Sprintf("failed to create hypervisor client: %v", err)
+			log.WarnContext(ctx, "failed to determine instance state",
+				"instance_id", stored.Id,
+				"socket", stored.SocketPath,
+				"error", err,
+			)
+			return stateResult{State: StateUnknown, Error: &errMsg}
+		}
 
-	info, err := hv.GetVMInfo(ctx)
-	if err != nil {
-		// Socket exists but hypervisor is unreachable - this is unexpected
-		errMsg := fmt.Sprintf("failed to query hypervisor: %v", err)
-		log.WarnContext(ctx, "failed to query hypervisor state",
-			"instance_id", stored.Id,
-			"socket", stored.SocketPath,
-			"error", err,
-		)
-		return stateResult{State: StateUnknown, Error: &errMsg}
+		queryCtx, cancel := context.WithTimeout(ctx, getVMInfoTimeout)
+		info, err := hv.GetVMInfo(queryCtx)
+		cancel()
+		if err != nil {
+			// Socket exists but hypervisor query failed or timed out. The API
+			// socket serializes requests, so a snapshot in flight will trip
+			// the timeout — return Unknown and let the next list call retry.
+			errMsg := fmt.Sprintf("failed to query hypervisor: %v", err)
+			log.WarnContext(ctx, "failed to query hypervisor state",
+				"instance_id", stored.Id,
+				"socket", stored.SocketPath,
+				"error", err,
+			)
+			return stateResult{State: StateUnknown, Error: &errMsg}
+		}
+		hvState = info.State
+		m.storeCachedHypervisorState(stored.Id, hvState)
 	}
 
 	// 3. Map hypervisor state to our state
-	switch info.State {
+	switch hvState {
 	case hypervisor.StateCreated:
 		return stateResult{State: StateCreated}
 	case hypervisor.StateRunning:
@@ -106,15 +138,74 @@ func (m *manager) deriveStateWithOptions(ctx context.Context, stored *StoredMeta
 		return stateResult{State: StateShutdown}
 	default:
 		// Unknown state - log and return Unknown
-		errMsg := fmt.Sprintf("unexpected hypervisor state: %s", info.State)
+		errMsg := fmt.Sprintf("unexpected hypervisor state: %s", hvState)
 		log.WarnContext(ctx, "hypervisor returned unexpected state",
 			"instance_id", stored.Id,
-			"hypervisor_state", info.State,
+			"hypervisor_state", hvState,
 		)
 		return stateResult{State: StateUnknown, Error: &errMsg}
 	}
 }
 
+// loadCachedHypervisorState returns the cached hypervisor state for an instance
+// when present and within the TTL window. Stale entries are treated as a miss.
+func (m *manager) loadCachedHypervisorState(id string) (hypervisor.VMState, bool) {
+	v, ok := m.hypervisorStateCache.Load(id)
+	if !ok {
+		return "", false
+	}
+	entry, ok := v.(hypervisorStateCacheEntry)
+	if !ok {
+		return "", false
+	}
+	if m.nowUTC().Sub(entry.refreshedAt) > hypervisorStateCacheTTL {
+		return "", false
+	}
+	return entry.state, true
+}
+
+// storeCachedHypervisorState records the latest known hypervisor state for an
+// instance so subsequent derive_state calls within the TTL window avoid the
+// socket round-trip.
+func (m *manager) storeCachedHypervisorState(id string, state hypervisor.VMState) {
+	m.hypervisorStateCache.Store(id, hypervisorStateCacheEntry{
+		state:       state,
+		refreshedAt: m.nowUTC(),
+	})
+}
+
+// invalidateCachedHypervisorState drops the cached hypervisor state for an
+// instance. Called when the instance no longer has a live hypervisor socket
+// (Stopped, Standby, Deleted) or transitions through a state where the cached
+// value would be stale.
+func (m *manager) invalidateCachedHypervisorState(id string) {
+	m.hypervisorStateCache.Delete(id)
+}
+
+// updateCachedHypervisorStateFromInstance reconciles the hypervisor state
+// cache with the post-transition instance state observed by a lifecycle
+// event. Lifecycle events are the source of truth for state changes hypeman
+// itself drives; mirroring them into the cache avoids re-querying /vm.info
+// on the next list call.
+func (m *manager) updateCachedHypervisorStateFromInstance(inst *Instance) {
+	if inst == nil {
+		return
+	}
+	switch inst.State {
+	case StateRunning, StateInitializing:
+		m.storeCachedHypervisorState(inst.Id, hypervisor.StateRunning)
+	case StateCreated:
+		m.storeCachedHypervisorState(inst.Id, hypervisor.StateCreated)
+	case StatePaused:
+		m.storeCachedHypervisorState(inst.Id, hypervisor.StatePaused)
+	case StateShutdown:
+		m.storeCachedHypervisorState(inst.Id, hypervisor.StateShutdown)
+	default:
+		// Stopped, Standby, Unknown — no live socket worth caching.
+		m.invalidateCachedHypervisorState(inst.Id)
+	}
+}
+
 func deriveRunningState(stored *StoredMetadata) State {
 	if stored.ProgramStartedAt == nil {
 		return StateInitializing

lib/instances/query_test.go

@@ -6,6 +6,7 @@ import (
 	"testing"
 	"time"
 
+	"github.com/kernel/hypeman/lib/hypervisor"
 	"github.com/kernel/hypeman/lib/paths"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
@@ -313,3 +314,95 @@ func TestAppLogPathsForMarkerScan_IgnoresArchivedLogs(t *testing.T) {
 	paths := m.appLogPathsForMarkerScan(id)
 	require.Equal(t, []string{logPath + ".2", logPath + ".1", logPath}, paths)
 }
+
+func TestHypervisorStateCache_TTL(t *testing.T) {
+	t.Parallel()
+
+	now := time.Date(2026, 5, 1, 12, 0, 0, 0, time.UTC)
+	m := &manager{}
+	m.now = func() time.Time { return now }
+
+	_, ok := m.loadCachedHypervisorState("missing")
+	require.False(t, ok)
+
+	m.storeCachedHypervisorState("vm-1", hypervisor.StateRunning)
+	got, ok := m.loadCachedHypervisorState("vm-1")
+	require.True(t, ok)
+	require.Equal(t, hypervisor.StateRunning, got)
+
+	// Advance just under TTL — still a hit.
+	now = now.Add(hypervisorStateCacheTTL - time.Millisecond)
+	got, ok = m.loadCachedHypervisorState("vm-1")
+	require.True(t, ok)
+	require.Equal(t, hypervisor.StateRunning, got)
+
+	// Past TTL — treated as miss so derive_state will re-query.
+	now = now.Add(2 * time.Millisecond)
+	_, ok = m.loadCachedHypervisorState("vm-1")
+	require.False(t, ok)
+}
+
+func TestHypervisorStateCache_InvalidationAndUpdate(t *testing.T) {
+	t.Parallel()
+
+	now := time.Date(2026, 5, 1, 12, 0, 0, 0, time.UTC)
+	m := &manager{}
+	m.now = func() time.Time { return now }
+
+	m.storeCachedHypervisorState("vm-1", hypervisor.StateRunning)
+	m.invalidateCachedHypervisorState("vm-1")
+	_, ok := m.loadCachedHypervisorState("vm-1")
+	require.False(t, ok)
+
+	// Lifecycle event with a live-socket state populates the cache.
+	m.updateCachedHypervisorStateFromInstance(&Instance{
+		StoredMetadata: StoredMetadata{Id: "vm-1"},
+		State:          StateInitializing,
+	})
+	got, ok := m.loadCachedHypervisorState("vm-1")
+	require.True(t, ok)
+	require.Equal(t, hypervisor.StateRunning, got)
+
+	m.updateCachedHypervisorStateFromInstance(&Instance{
+		StoredMetadata: StoredMetadata{Id: "vm-1"},
+		State:          StatePaused,
+	})
+	got, ok = m.loadCachedHypervisorState("vm-1")
+	require.True(t, ok)
+	require.Equal(t, hypervisor.StatePaused, got)
+
+	// Standby has no live socket, so the cache must be cleared so the next
+	// derive_state correctly short-circuits to Standby/Stopped via the
+	// socket check rather than reusing a stale Running entry.
+	m.updateCachedHypervisorStateFromInstance(&Instance{
+		StoredMetadata: StoredMetadata{Id: "vm-1"},
+		State:          StateStandby,
+	})
+	_, ok = m.loadCachedHypervisorState("vm-1")
+	require.False(t, ok)
+}
+
+func TestNotifyLifecycleEvent_UpdatesAndDropsHypervisorStateCache(t *testing.T) {
+	t.Parallel()
+
+	now := time.Date(2026, 5, 1, 12, 0, 0, 0, time.UTC)
+	m := &manager{
+		lifecycleEvents: newLifecycleSubscribers(),
+	}
+	m.now = func() time.Time { return now }
+
+	inst := &Instance{
+		StoredMetadata: StoredMetadata{Id: "vm-2"},
+		State:          StateRunning,
+	}
+	m.notifyLifecycleEvent(t.Context(), LifecycleEventStart, inst)
+	got, ok := m.loadCachedHypervisorState("vm-2")
+	require.True(t, ok)
+	require.Equal(t, hypervisor.StateRunning, got)
+
+	// Delete must drop the cache so a future re-create with the same id does
+	// not race with a stale entry from before deletion.
+	m.notifyLifecycleDelete(t.Context(), "vm-2")
+	_, ok = m.loadCachedHypervisorState("vm-2")
+	require.False(t, ok)
+}