mesh-provisioner: compose a node once and read its own states from the copy (issue 1954)

provisioner_compose took 2.6-13.6 s per node with nothing changed, CPU
bound. The node is now composed at its wanted and its newest builds over
one read (frombus.PlansHeldTwice, whose composer resolves each machine
once), its own plans, provisions and refusals and the providers' entries
are read from the watched copy, its own writes taken in at once, and a
provider's manifest once by digest: no read by key per composition is
left. The result says where the time went, phase by phase, and a slow
composition that changed nothing says it in the log.

BenchmarkComposeNode times it over a mesh captured with the read tools
(MESH_COMPOSE_CAPTURE): novox 11.7 s to 0.49 s, ace 0.49 s, g14 and
shanks 0.39 s; plans and provisions identical to before over nine
compositions of the four nodes.

Needs mesh-sdk feat/compose-once (5d26c65); go.mod still pins the old
mesh-sdk until the group pins its head.

Claude-Session: https://claude.ai/code/session_01NcbgfJ9Gum47zkFKWRaovL

modules/mesh-provisioner/cmd/mesh-provisioner/compose_bench_test.go

@@ -0,0 +1,225 @@
+package main
+
+// BenchmarkComposeNode times ComposeNode of an unchanged node over a mesh captured from the bus (issue 1954): the
+// placement, wants, haves, the indexer's modules and manifests, the builder's builds, mesh-config's resolved values and
+// the templates archives, read with the read tools (mesh-placement.placement, mesh-delivery-view.assigner_wants,
+// node_haves, indexer_modules, builder_build, mesh-config.config) and the manifests and archives by digest. The capture
+// is not kept in this repository (a few megabytes, and the mesh's own addresses and keys): the benchmark reads the
+// directory MESH_COMPOSE_CAPTURE names and is skipped without it. MESH_COMPOSE_NODE names the node (novox when unset).
+//
+// The capture's layout: placement.json, wants.json, haves.json, modules.json and config.json as those tools answer,
+// builds/<module>.<hex>.json as builder_build answers, manifests/<digest> and archives/<hex> as their bytes.
+
+import (
+	"context"
+	"encoding/json"
+	"os"
+	"path/filepath"
+	"strings"
+	"sync/atomic"
+	"testing"
+	"time"
+
+	stdio "git.novox.be/novox/mesh-sdk/go"
+	"git.novox.be/novox/mesh-sdk/go/compose/frombus"
+	"git.novox.be/novox/mesh-sdk/go/compose/fromruntime"
+	"git.novox.be/novox/mesh-sdk/go/delivery"
+)
+
+// countingStore counts the holder's reads of its own states (and the providers' entries), each a bus request live.
+type countingStore struct {
+	Store
+	gets, keys atomic.Int64
+}
+
+func (c *countingStore) Get(state, key string) (*Entry, error) {
+	c.gets.Add(1)
+	return c.Store.Get(state, key)
+}
+
+func (c *countingStore) Keys(state string) ([]string, error) {
+	c.keys.Add(1)
+	return c.Store.Keys(state)
+}
+
+// captured is the captured mesh as the states the holder reads, and the archives by digest.
+func captured(b *testing.B, dir string) (map[string]map[string][]byte, map[string][]byte) {
+	b.Helper()
+	read := func(name string, into any) {
+		raw, err := os.ReadFile(filepath.Join(dir, name))
+		if err != nil {
+			b.Fatal(err)
+		}
+		if err := json.Unmarshal(raw, into); err != nil {
+			b.Fatalf("%s: %v", name, err)
+		}
+	}
+	states := map[string]map[string][]byte{}
+	put := func(state, key string, raw []byte) {
+		if states[state] == nil {
+			states[state] = map[string][]byte{}
+		}
+		states[state][key] = raw
+	}
+	var placement struct {
+		Keys map[string]struct {
+			Placement json.RawMessage `json:"placement"`
+		} `json:"keys"`
+	}
+	read("placement.json", &placement)
+	for node, k := range placement.Keys {
+		var p delivery.Placement
+		if err := json.Unmarshal(k.Placement, &p); err != nil {
+			b.Fatal(err)
+		}
+		p.Node = node
+		raw, err := delivery.EncodePlacement(p)
+		if err != nil {
+			b.Fatal(err)
+		}
+		put(PlacementRead, "placement."+node, raw)
+	}
+	var wants struct {
+		Wants map[string]json.RawMessage `json:"wants"`
+	}
+	read("wants.json", &wants)
+	for k, v := range wants.Wants {
+		put(WantsRead, k, v)
+	}
+	var haves struct {
+		Keys map[string]json.RawMessage `json:"keys"`
+	}
+	read("haves.json", &haves)
+	for k, v := range haves.Keys {
+		put(HaveRead, k, v)
+	}
+	var modules struct {
+		Modules map[string]json.RawMessage `json:"modules"`
+	}
+	read("modules.json", &modules)
+	for m, v := range modules.Modules {
+		key, err := delivery.ModulesKey(m)
+		if err != nil {
+			b.Fatal(err)
+		}
+		put(ModulesRead, key, v)
+	}
+	var config struct {
+		Resolved []struct {
+			Key, Module, Node, Source string
+			Value                     any
+		} `json:"resolved"`
+	}
+	read("config.json", &config)
+	for _, r := range config.Resolved {
+		raw, _ := json.Marshal(map[string]any{"value": r.Value, "source": r.Source})
+		put(ResolvedRead, r.Node+"."+r.Module+"."+r.Key, raw)
+	}
+	manifests, _ := filepath.Glob(filepath.Join(dir, "manifests", "*"))
+	for _, f := range manifests {
+		raw, err := os.ReadFile(f)
+		if err != nil {
+			b.Fatal(err)
+		}
+		digest := filepath.Base(f)
+		v, err := delivery.EncodeManifest(delivery.Manifest{Module: "captured", JSON: string(raw)})
+		if err != nil {
+			b.Fatal(err)
+		}
+		key, err := delivery.ManifestsKey(digest)
+		if err != nil {
+			b.Fatal(err)
+		}
+		put(ManifestsRead, key, v)
+	}
+	builds, _ := filepath.Glob(filepath.Join(dir, "builds", "*.json"))
+	for _, f := range builds {
+		var bb struct {
+			Module      string          `json:"module"`
+			Fingerprint string          `json:"fingerprint"`
+			Build       json.RawMessage `json:"build"`
+		}
+		read(strings.TrimPrefix(f, dir+"/"), &bb)
+		key, err := delivery.BuilderBuildKey(bb.Module, bb.Fingerprint)
+		if err != nil {
+			b.Fatal(err)
+		}
+		put(BuildsRead, key, bb.Build)
+	}
+	archives := map[string][]byte{}
+	files, _ := filepath.Glob(filepath.Join(dir, "archives", "*"))
+	for _, f := range files {
+		raw, err := os.ReadFile(f)
+		if err != nil {
+			b.Fatal(err)
+		}
+		archives[filepath.Base(f)] = raw
+	}
+	return states, archives
+}
+
+func BenchmarkComposeNode(b *testing.B) {
+	dir := os.Getenv("MESH_COMPOSE_CAPTURE")
+	if dir == "" {
+		b.Skip("MESH_COMPOSE_CAPTURE names no captured mesh")
+	}
+	node := os.Getenv("MESH_COMPOSE_NODE")
+	if node == "" {
+		node = "novox"
+	}
+	states, archives := captured(b, dir)
+	ws := stdio.WatchedStatesOver(func(state string, handle func(stdio.StateChange) error) error {
+		for k, v := range states[state] {
+			if err := handle(stdio.StateChange{State: state, Key: k, Op: stdio.OpPut, Value: v, Current: true}); err != nil {
+				return err
+			}
+		}
+		return nil
+	}, func(state, key string) ([]byte, bool, error) {
+		v, ok := states[state][key]
+		return v, ok, nil
+	})
+	fetch := fromruntime.KeptFetch(func(_ context.Context, url string) ([]byte, error) {
+		_, hex, _ := strings.Cut(url, "sha256:")
+		raw, ok := archives[hex]
+		if !ok {
+			return nil, os.ErrNotExist
+		}
+		return raw, nil
+	})
+	own := &countingStore{Store: newStore()}
+	h := &Holder{Store: Watching(own, ws), Compose: composerOver(frombus.StatesReader(fromruntime.Watched{WatchedStates: ws}, fetch)),
+		Now: time.Now, Logf: func(string, ...any) {}}
+	// Composed twice before it is timed: a provision's state follows the states of those it depends on, which the first
+	// composition writes, so the second may still change a key; from then on nothing changes.
+	first, err := h.ComposeNode(context.Background(), node)
+	if err != nil {
+		b.Fatal(err)
+	}
+	if second, err := h.ComposeNode(context.Background(), node); err != nil {
+		b.Fatal(err)
+	} else if len(second.Changed) > 0 {
+		b.Logf("the second composition of %s changed %v", node, second.Changed)
+	}
+	b.Logf("first composition of %s: %d plans written, %d held, %d problems, %d keys changed", node, len(first.Plans),
+		len(first.Held), len(first.Problems), len(first.Changed))
+	for _, p := range first.Problems {
+		b.Logf("problem: %s", p)
+	}
+	own.gets.Store(0)
+	own.keys.Store(0)
+	b.ResetTimer()
+	var c Composed
+	for b.Loop() {
+		c, err = h.ComposeNode(context.Background(), node)
+		if err != nil {
+			b.Fatal(err)
+		}
+		if len(c.Plans)+len(c.Gone)+len(c.Changed) > 0 {
+			b.Fatalf("an unchanged node composed changes: %+v", c)
+		}
+	}
+	b.Logf("the last composition of %s: %s", node, TookSaid(c.Took))
+	b.ReportMetric(float64(own.gets.Load())/float64(b.N), "own-gets/op")
+	b.ReportMetric(float64(own.keys.Load())/float64(b.N), "own-keys/op")
+}

modules/mesh-provisioner/cmd/mesh-provisioner/holder.go

@@ -75,12 +75,18 @@ var BoundReads = []string{"gitea", "keycloak", "postgres", "route-adapter", "rou
 // boundRead is a provider's entries as this module reads them.
 func boundRead(module string) string { return module + ".bound" }
 
-// Composer is each module's provisioning plan on a node, composed from the bus: at the builds keptAt names
-// (module → fingerprint), the newest build of every other placed module. A module whose build or plan refuses is held
-// (frombus.PlansHeld; issue 774, one bad module must not drop its node): in held with why, none of its plan in plans.
-// err is a refusal that is no single module's.
-type Composer func(ctx context.Context, node string, keptAt map[string]string) (plans map[string]catalogue.Plan,
-	held map[string]string, err error)
+// Composer is a node's provisioning plans, composed from the bus over one read: at the builds keptAt names (module →
+// fingerprint, the newest build of every other placed module), and at the newest build of each placed module (issue
+// 1954: once, not twice). A module whose build or plan refuses is held (frombus.PlansHeld; issue 774, one bad module
+// must not drop its node): in held with why, none of its plan in plans; a scope's Err is a refusal that is no single
+// module's.
+type Composer func(ctx context.Context, node string, keptAt map[string]string) Composition
+
+// Composition is a node's plans at its wanted builds and at its newest, and where the time went.
+type Composition struct {
+	AtWants, Newest frombus.HeldPlans
+	Took            []frombus.Phase
+}
 
 // Asker is the operator's channel as this module asks on it: publish an ask under its own name, and read the router's
 // record of it.
@@ -111,13 +117,40 @@ type Composed struct {
 	// stay as they were, and every other module is composed (issue 774).
 	Held     map[string]string `json:"modules-held,omitempty"`
 	Problems []string          `json:"problems,omitempty"`
+	// Took is where the composition's time went, phase by phase in milliseconds, its whole last (issue 1954).
+	Took []Took `json:"took"`
+}
+
+// Took is one phase of a composition and its milliseconds.
+type Took struct {
+	Phase string `json:"phase"`
+	MS    int64  `json:"ms"`
+}
+
+// TookSaid says a composition's phases in one line.
+func TookSaid(took []Took) string {
+	var said []string
+	for _, t := range took {
+		said = append(said, fmt.Sprintf("%s %d ms", t.Phase, t.MS))
+	}
+	return strings.Join(said, ", ")
 }
 
 // ComposeNode composes one node: its plans and its provisions.
-func (h *Holder) ComposeNode(ctx context.Context, node string) (Composed, error) {
+func (h *Holder) ComposeNode(ctx context.Context, node string) (out Composed, err error) {
 	h.mu.Lock()
 	defer h.mu.Unlock()
-	out := Composed{Node: node}
+	out = Composed{Node: node}
+	began, start := time.Now(), time.Now()
+	mark := func(phase string, took time.Duration) {
+		out.Took = append(out.Took, Took{Phase: phase, MS: took.Milliseconds()})
+	}
+	lap := func(phase string) {
+		now := time.Now()
+		mark(phase, now.Sub(start))
+		start = now
+	}
+	defer func() { mark("whole", time.Since(began)) }()
 	wanted, err := h.wantedOn(node)
 	if err != nil {
 		return out, err
@@ -129,14 +162,19 @@ func (h *Holder) ComposeNode(ctx context.Context, node string) (Composed, error)
 			wanted[module] = fp
 		}
 	}
-	atWants, heldAtWants, err := h.Compose(ctx, node, wanted)
-	if err != nil {
-		return out, fmt.Errorf("the plans of %s cannot be composed: %w", node, err)
+	lap("wants")
+	c := h.Compose(ctx, node, wanted)
+	for _, p := range c.Took {
+		mark(p.Name, p.Took)
 	}
-	newest, heldNewest, err := h.Compose(ctx, node, nil)
-	if err != nil {
-		return out, fmt.Errorf("the plans of %s at the newest builds cannot be composed: %w", node, err)
+	start = time.Now()
+	if c.AtWants.Err != nil {
+		return out, fmt.Errorf("the plans of %s cannot be composed: %w", node, c.AtWants.Err)
 	}
+	if c.Newest.Err != nil {
+		return out, fmt.Errorf("the plans of %s at the newest builds cannot be composed: %w", node, c.Newest.Err)
+	}
+	atWants, heldAtWants, newest, heldNewest := c.AtWants.Plans, c.AtWants.Held, c.Newest.Plans, c.Newest.Held
 	// A module held at its wanted build has no plan composed: its last plan and its provisions are kept, said in
 	// `refused`. One held at its newest build alone keeps its plan at its want; what its newest build needs ahead waits.
 	if len(heldAtWants) > 0 {
@@ -153,6 +191,7 @@ func (h *Holder) ComposeNode(ctx context.Context, node string) (Composed, error)
 	if err := h.writePlans(node, atWants, heldAtWants, &out); err != nil {
 		out.Problems = append(out.Problems, err.Error())
 	}
+	lap("plans written")
 	needed := map[string]provisions.Provision{}
 	elsewhere := map[string]provisions.Provision{}
 	vaultNode := h.vaultNode()
@@ -199,6 +238,7 @@ func (h *Holder) ComposeNode(ctx context.Context, node string) (Composed, error)
 	}
 	h.judgeElsewhere(elsewhere, &out)
 	h.judgeNode(node, needed, heldAtWants, &out)
+	lap("provisions judged")
 	return out, nil
 }
 
@@ -1046,21 +1086,40 @@ func orSaid(words ...string) string {
 }
 
 // FromWatched is the holder's composer over one watched copy of its reads (novox/hq ADR 0580 clause 2): frombus's plans
-// of a node, at the builds keptAt names, read from the copy (placement, haves, modules, resolved values), a build by key
-// and a manifest once per digest; no state is read key by key per composition. A plan names no value, so no own secret
-// and no credential is read (compose.Planning).
+// of a node, at the builds keptAt names and at the newest over one read of the copy (placement, haves, modules,
+// resolved values), a build by key and a manifest once per digest; no state is read key by key per composition. A plan
+// names no value, so no own secret and no credential is read (compose.Planning).
 func FromWatched(ws *stdio.WatchedStates) Composer {
-	r := fromruntime.WatchedReader(ws)
-	return func(ctx context.Context, node string, keptAt map[string]string) (map[string]catalogue.Plan, map[string]string, error) {
-		return frombus.PlansHeld(ctx, r, frombus.Mesh{}, frombus.Scope{Node: node, KeptAt: keptAt})
+	return composerOver(fromruntime.WatchedReader(ws))
+}
+
+// composerOver is the holder's composer over a reader: both scopes over one read (frombus.PlansHeldTwice).
+func composerOver(r frombus.Reader) Composer {
+	return func(ctx context.Context, node string, keptAt map[string]string) Composition {
+		at, newest, took := frombus.PlansHeldTwice(ctx, r, frombus.Mesh{}, frombus.Scope{Node: node, KeptAt: keptAt})
+		return Composition{AtWants: at, Newest: newest, Took: took}
 	}
 }
 
 // WatchedReads are the states the holder reads whole, each from the watched copy: what the composer reads and the
-// wants (ADR 0580 clause 2). Its own states and the providers' entries stay read from the bus, after its own writes.
-var WatchedReads = []string{PlacementRead, WantsRead, ModulesRead, HaveRead, ResolvedRead}
+// wants (ADR 0580 clause 2), and the providers' entries, whose watch is also what rejudges a key.
+var WatchedReads = append([]string{PlacementRead, WantsRead, ModulesRead, HaveRead, ResolvedRead}, boundReads()...)
 
-// Watching is a Store whose WatchedReads come from the copy; every other state, and every write, from s.
+// OwnStates are the states the holder alone writes (ADR 0570 clause 1), read from the watched copy too (issue 1954: some
+// 250 to 400 reads by key per composition): each of its own writes is taken into the copy at once (WatchedStates.Wrote),
+// so it reads back what it wrote before the watch hands it back.
+var OwnStates = []string{PlansState, ProvisionsState, RefusedState}
+
+func boundReads() []string {
+	out := make([]string, 0, len(BoundReads))
+	for _, p := range BoundReads {
+		out = append(out, boundRead(p))
+	}
+	return out
+}
+
+// Watching is a Store whose WatchedReads and OwnStates come from the copy, its writes of OwnStates taken into the copy as
+// they land, and a manifest read once by its digest; every other state, and every write, from s.
 func Watching(s Store, ws *stdio.WatchedStates) Store { return watchingStore{Store: s, ws: ws} }
 
 type watchingStore struct {
@@ -1068,11 +1127,24 @@ type watchingStore struct {
 	ws *stdio.WatchedStates
 }
 
+// RevisionPutter is a Store that says the revision a put landed at (the bus does), so the copy keeps it exactly.
+type RevisionPutter interface {
+	PutRevision(state, key string, value any) (uint64, error)
+}
+
+func (w watchingStore) copied(state string) bool {
+	return slices.Contains(WatchedReads, state) || slices.Contains(OwnStates, state)
+}
+
 func (w watchingStore) Get(state, key string) (*Entry, error) {
-	if !slices.Contains(WatchedReads, state) {
+	get := w.ws.Get
+	switch {
+	case state == ManifestsRead:
+		get = w.ws.Once // a manifest by its digest never changes: read once, kept (ADR 0580 clause 1)
+	case !w.copied(state):
 		return w.Store.Get(state, key)
 	}
-	v, found, err := w.ws.Get(state, key)
+	v, found, err := get(state, key)
 	if err != nil || !found {
 		return nil, err
 	}
@@ -1080,12 +1152,39 @@ func (w watchingStore) Get(state, key string) (*Entry, error) {
 }
 
 func (w watchingStore) Keys(state string) ([]string, error) {
-	if !slices.Contains(WatchedReads, state) {
+	if !w.copied(state) {
 		return w.Store.Keys(state)
 	}
 	return w.ws.Keys(state)
 }
 
+func (w watchingStore) Put(state, key string, value any) error {
+	if !slices.Contains(OwnStates, state) {
+		return w.Store.Put(state, key, value)
+	}
+	raw, err := json.Marshal(value)
+	if err != nil {
+		return err
+	}
+	var revision uint64
+	if rp, ok := w.Store.(RevisionPutter); ok {
+		revision, err = rp.PutRevision(state, key, json.RawMessage(raw))
+	} else {
+		err = w.Store.Put(state, key, json.RawMessage(raw))
+	}
+	if err != nil {
+		return err
+	}
+	return w.ws.Wrote(state, key, raw, revision)
+}
+
+func (w watchingStore) Delete(state, key string) error {
+	if err := w.Store.Delete(state, key); err != nil || !slices.Contains(OwnStates, state) {
+		return err
+	}
+	return w.ws.Removed(state, key)
+}
+
 // NodesOfNodeKey is the node a key that starts with it names: a resolved value's `<node>.<module>.<key>`, a have's
 // `<node>.<module>` or `<node>.node`. A change of either recomposes that node (ADR 0580 clause 2).
 func NodesOfNodeKey(key string) []string {

modules/mesh-provisioner/cmd/mesh-provisioner/holder_integration_test.go

@@ -22,7 +22,6 @@ import (
 
 	stdio "git.novox.be/novox/mesh-sdk/go"
 	"git.novox.be/novox/mesh-sdk/go/asks"
-	"git.novox.be/novox/mesh-sdk/go/catalogue"
 	"git.novox.be/novox/mesh-sdk/go/compose/frombus"
 	"git.novox.be/novox/mesh-sdk/go/compose/frombus/frombustest"
 	"git.novox.be/novox/mesh-sdk/go/compose/fromruntime"
@@ -262,9 +261,7 @@ func TestTheHolderComposesProvidesAndAsksOnTheBus(t *testing.T) {
 	reader := frombus.StatesReader(fromruntime.Watched{WatchedStates: ws}, fetch)
 	a := &asked{}
 	h := &Holder{Store: Watching(s, ws), Asks: a, Now: time.Now, Logf: t.Logf,
-		Compose: func(ctx context.Context, node string, keptAt map[string]string) (map[string]catalogue.Plan, map[string]string, error) {
-			return frombus.PlansHeld(ctx, reader, frombus.Mesh{}, frombus.Scope{Node: node, KeptAt: keptAt})
-		}}
+		Compose: composerOver(reader)}
 	state := func(key string) provisions.Provision {
 		e, _ := s.Get(ProvisionsState, key)
 		if e == nil {

modules/mesh-provisioner/cmd/mesh-provisioner/holder_test.go

@@ -15,6 +15,7 @@ import (
 	stdio "git.novox.be/novox/mesh-sdk/go"
 	"git.novox.be/novox/mesh-sdk/go/asks"
 	"git.novox.be/novox/mesh-sdk/go/catalogue"
+	"git.novox.be/novox/mesh-sdk/go/compose/frombus"
 	"git.novox.be/novox/mesh-sdk/go/delivery"
 	"git.novox.be/novox/mesh-sdk/go/provisions"
 )
@@ -68,12 +69,10 @@ func newMesh() *mesh {
 	now := time.Date(2026, 10, 29, 22, 0, 0, 0, time.UTC)
 	m.h = &Holder{Store: m.s, Asks: m.r, Logf: func(string, ...any) {},
 		Now: func() time.Time { now = now.Add(time.Second); return now },
-		Compose: func(_ context.Context, node string, keptAt map[string]string) (map[string]catalogue.Plan, map[string]string, error) {
+		Compose: func(_ context.Context, node string, keptAt map[string]string) Composition {
 			m.composed = append(m.composed, node)
-			if keptAt != nil {
-				return m.atWant[node], m.heldAt[node], nil
-			}
-			return m.atNewest[node], nil, nil
+			return Composition{AtWants: frombus.HeldPlans{Plans: m.atWant[node], Held: m.heldAt[node]},
+				Newest: frombus.HeldPlans{Plans: m.atNewest[node]}}
 		}}
 	// What each provider's manifest declares: postgres, keycloak and the vault keep entries, the others report by their
 	// have.
@@ -385,12 +384,9 @@ func TestAModuleHeldWithoutAWantIsComposedAtTheBuildItRuns(t *testing.T) {
 	m.s.write(t, HaveRead, "novox.nats", `{"v":1,"fp":"`+fp+`","phase":"running","health":"ok"}`)
 	m.s.write(t, HaveRead, "g14.dunst", `{"v":1,"fp":"src2:`+strings.Repeat("ee", 32)+`","phase":"running","health":"ok"}`)
 	var keptAt map[string]string
-	m.h.Compose = func(_ context.Context, node string, at map[string]string) (map[string]catalogue.Plan, map[string]string, error) {
-		if at != nil {
-			keptAt = at
-			return map[string]catalogue.Plan{"nats": {}}, nil, nil
-		}
-		return nil, nil, nil
+	m.h.Compose = func(_ context.Context, node string, at map[string]string) Composition {
+		keptAt = at
+		return Composition{AtWants: frombus.HeldPlans{Plans: map[string]catalogue.Plan{"nats": {}}}}
 	}
 	// ADR 0580 clause 2: the reads come from one watched copy, each state watched once and none read key by key from the
 	// bus, and a change the copy takes wakes the node it touches (a resolved value its node).
@@ -419,8 +415,16 @@ func TestAModuleHeldWithoutAWantIsComposedAtTheBuildItRuns(t *testing.T) {
 		if i == 0 && !slices.Contains(c.Plans, "novox.nats") {
 			t.Fatalf("no plan written for a module held without a want: %+v", c)
 		}
+		// Issue 1954: its own states come from the copy too, its own writes read back at once (nothing is written
+		// again), and the result says where the time went, its whole last.
+		if i == 1 && len(c.Plans)+len(c.Changed) > 0 {
+			t.Fatalf("composed again unchanged, it wrote %+v: its own writes were not read back", c)
+		}
+		if n := len(c.Took); n == 0 || c.Took[n-1].Phase != "whole" || c.Took[0].Phase != "wants" {
+			t.Fatalf("the composition says its phases as %v", c.Took)
+		}
 	}
-	for _, r := range WatchedReads {
+	for _, r := range append(slices.Clone(WatchedReads), OwnStates...) {
 		if bus.read[r] != 0 || watches[r] > 1 {
 			t.Errorf("%s was read %d times from the bus and watched %d times", r, bus.read[r], watches[r])
 		}

modules/mesh-provisioner/cmd/mesh-provisioner/main.go

@@ -43,6 +43,11 @@ func (runtimeStore) Put(state, key string, value any) error {
 	return err
 }
 
+// PutRevision is Put, saying the revision it landed at.
+func (runtimeStore) PutRevision(state, key string, value any) (uint64, error) {
+	return stdio.State(state).Put(key, value)
+}
+
 func (runtimeStore) Delete(state, key string) error { return stdio.State(state).Delete(key) }
 
 func (runtimeStore) Keys(state string) ([]string, error) { return stdio.State(state).Keys() }
@@ -95,14 +100,28 @@ func (w *work) run(h *Holder) {
 			c, err := h.ComposeNode(context.Background(), n)
 			switch {
 			case err != nil:
-				logf("[%s] %s is not composed: %v", Module, n, err)
+				logf("[%s] %s is not composed (%s): %v", Module, n, TookSaid(c.Took), err)
 			case len(c.Plans)+len(c.Gone)+len(c.Changed)+len(c.Asked)+len(c.Problems) > 0:
 				logf("[%s] composed %s: %+v", Module, n, c)
+			case slowest(c.Took) >= slowAt:
+				// Nothing changed and it took long: where the time went is said, so a slow composition is seen (issue 1954).
+				logf("[%s] composed %s, nothing changed: %s", Module, n, TookSaid(c.Took))
 			}
 		}
 	}
 }
 
+// slowAt is how long a composition that changed nothing may take before its phases are said.
+const slowAt = time.Second
+
+// slowest is a composition's whole time: its last phase, "whole".
+func slowest(took []Took) time.Duration {
+	if len(took) == 0 {
+		return 0
+	}
+	return time.Duration(took[len(took)-1].MS) * time.Millisecond
+}
+
 func main() {
 	s := runtimeStore{}
 	ws := stdio.NewWatchedStates() // one copy of what it reads, each state by its watch (ADR 0580 clause 2)
@@ -122,7 +141,8 @@ func main() {
 		return nil
 	})
 	for _, provider := range BoundReads {
-		go stdio.State(boundRead(provider)).Follow("", func(c stdio.StateChange) error {
+		// Into the copy the holder reads them from, its handler run after the copy took the change.
+		go ws.Follow(boundRead(provider), func(c stdio.StateChange) error {
 			if said, err := h.Rejudge(c.Key); err != nil {
 				logf("[%s] %s is not judged again: %v", Module, c.Key, err)
 			} else if said != "" {