solver: log dep cache-key starvation (edgeState vs result keys)

Diagnose the concurrency-triggered cross-build miss: build 2/13 never
queries because its shared base dependency is reused already-complete
(pinned in Solver.actives by a concurrent build) and hands over an
edgeState with zero cache keys, so probeCache/Query is never called and
noCacheMatchPossible latches the dep to complete-only.

Two probes, keyed by vertex digest:
- checkDepMatchPossible: WARN when noCacheMatchPossible flips, logging the
  dep's state/keys/keyMap and whether its result still carries a cache key
  (dep_result_keys>0 with dep_keymap==0 = the starvation).
- processDepReq: DEBUG on each cache-slow/complete dep delivery, logging
  edgeState keys vs result keys, so the fatal complete/0-key delivery in the
  concurrent run contrasts with the healthy cache-slow/keyed delivery in the
  serial run.

Keeps the earlier probeCache-skip WARN as a proven-negative.

Signed-off-by: Felix de Souza <fdesouza@palantir.com>

solver/debug.go

@@ -311,3 +311,49 @@ func debugSchedulerSkipInputRequestBasedOnDepState(e *edge, dep *dep, desiredSta
 			Debug("skip input request based on dep state")
 	}
 }
+
+// debugSchedulerNoCacheMatchPossible records the moment an edge latches
+// noCacheMatchPossible because a dependency exposed no probeable key
+// (len(dep.keyMap)==0) once past cache-slow. When the dep nonetheless carries a
+// non-empty result cache key (dep_result_keys>0 with dep_keymap==0), that is the
+// stale/complete shared-dependency starvation: the key lives on the result but
+// was never delivered via edgeState.keys, so probeCache/Query never ran.
+func debugSchedulerNoCacheMatchPossible(e *edge, dep *dep, depHasSlowCache bool) {
+	if e.debug {
+		depResultKeys := 0
+		if dep.result != nil {
+			depResultKeys = len(dep.result.CacheKeys())
+		}
+		bklog.G(context.TODO()).
+			WithField("vtx", e.edge.Vertex.Digest()).
+			WithField("dep", dep.index).
+			WithField("dep_state", dep.state).
+			WithField("dep_keys", len(dep.keys)).
+			WithField("dep_keymap", len(dep.keyMap)).
+			WithField("dep_has_slow_cache", depHasSlowCache).
+			WithField("dep_result", dep.result != nil).
+			WithField("dep_result_keys", depResultKeys).
+			Debug("noCacheMatchPossible set: dep yields no probeable cache key")
+	}
+}
+
+// debugSchedulerDepDelivery records what a dependency hands over once it is
+// key-bearing (cache-slow) or terminal (complete). The starvation shows up as a
+// dep that arrives with dep_edgestate_keys=0 while dep_result_keys>0 -- keys on
+// the result but none in edgeState.keys, so probeCache is fed an empty slice.
+func debugSchedulerDepDelivery(e *edge, dep *dep, state *edgeState) {
+	if e.debug {
+		depResultKeys := 0
+		if state.result != nil {
+			depResultKeys = len(state.result.CacheKeys())
+		}
+		bklog.G(context.TODO()).
+			WithField("vtx", e.edge.Vertex.Digest()).
+			WithField("dep", dep.index).
+			WithField("dep_state", state.state).
+			WithField("dep_edgestate_keys", len(state.keys)).
+			WithField("dep_result", state.result != nil).
+			WithField("dep_result_keys", depResultKeys).
+			Debug("dep delivery: edgeState keys vs result keys")
+	}
+}

solver/edge.go

@@ -220,6 +220,7 @@ func (e *edge) checkDepMatchPossible(dep *dep) {
 	depHasSlowCache := e.cacheMap.Deps[dep.index].ComputeDigestFunc != nil
 	if !e.noCacheMatchPossible && (((!dep.slowCacheFoundKey && dep.slowCacheComplete && depHasSlowCache) || (!depHasSlowCache && dep.state >= edgeStatusCacheSlow)) && len(dep.keyMap) == 0) {
 		e.noCacheMatchPossible = true
+		debugSchedulerNoCacheMatchPossible(e, dep, depHasSlowCache)
 	}
 }
 
@@ -654,6 +655,10 @@ func (e *edge) processDepReq(dep *dep) (depChanged bool) {
 		return false
 	}
 
+	if state.state >= edgeStatusCacheSlow {
+		debugSchedulerDepDelivery(e, dep, state)
+	}
+
 	if len(dep.keys) < len(state.keys) {
 		newKeys := state.keys[len(dep.keys):]
 		if e.cacheMap != nil {