diff --git a/modules/mesh-provisioner/cmd/mesh-provisioner/compose_bench_test.go b/modules/mesh-provisioner/cmd/mesh-provisioner/compose_bench_test.go new file mode 100644 index 00000000..0b901b32 --- /dev/null +++ b/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/..json as builder_build answers, manifests/ and archives/ 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") +} diff --git a/modules/mesh-provisioner/cmd/mesh-provisioner/holder.go b/modules/mesh-provisioner/cmd/mesh-provisioner/holder.go index 2a7ee6bd..a15e1abc 100644 --- a/modules/mesh-provisioner/cmd/mesh-provisioner/holder.go +++ b/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 `..`, a have's // `.` or `.node`. A change of either recomposes that node (ADR 0580 clause 2). func NodesOfNodeKey(key string) []string { diff --git a/modules/mesh-provisioner/cmd/mesh-provisioner/holder_integration_test.go b/modules/mesh-provisioner/cmd/mesh-provisioner/holder_integration_test.go index 708f4571..e5a56156 100644 --- a/modules/mesh-provisioner/cmd/mesh-provisioner/holder_integration_test.go +++ b/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 { diff --git a/modules/mesh-provisioner/cmd/mesh-provisioner/holder_test.go b/modules/mesh-provisioner/cmd/mesh-provisioner/holder_test.go index 96c53213..31638dc1 100644 --- a/modules/mesh-provisioner/cmd/mesh-provisioner/holder_test.go +++ b/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]) } diff --git a/modules/mesh-provisioner/cmd/mesh-provisioner/main.go b/modules/mesh-provisioner/cmd/mesh-provisioner/main.go index dcc74524..33d50c83 100644 --- a/modules/mesh-provisioner/cmd/mesh-provisioner/main.go +++ b/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 != "" {