amadan
Wake latency pass 2a: per-step timing for the launch, prepare, pinned health, lease and instance-control (census-ruling-wake-latency-2)
Squashed from wake-latency-2 into main.
8 files changed,
+75
−6
docs/superpowers/notes/census-proposal-wake-latency-2.md+16 −0internal/activator/backend_exec.go+11 −2internal/activator/prepare.go+15 −2internal/activator/swaphold.go+6 −0internal/instancectl/gen.go+6 −2internal/lease/lease.go+7 −0internal/provision/testdata/plan14-root-reads-chain.tsv+1 −0internal/provision/testdata/plan14-root-reads-wake-latency-2.tsv+13 −0
CI cancelled — superseded by a newer push — run details
CI log
=== gate ===
.amadan/test-gate.sh
=== launchctx (0 s)
ok amadan.net/carlos/platform.git/launchctx 0.012s
? amadan.net/carlos/platform.git/launchctx/controlname [no test files]
? amadan.net/carlos/platform.git/launchctx/wireid [no test files]
=== vet (18 s)
=== gofmt (0 s)
gofmt -l .: clean
=== rest (169 s)
? github.com/carlosframework/platform/cmd/changelog [no test files]
ok github.com/carlosframework/platform/cmd/console 3.695s
ok github.com/carlosframework/platform/cmd/moveprobe 11.927s
ok github.com/carlosframework/platform/cmd/zddprobe 0.713s
ok github.com/carlosframework/platform/internal/activator 60.388s
ok github.com/carlosframework/platform/internal/agentsock 0.025s
ok github.com/carlosframework/platform/internal/alerting 0.008s
ok github.com/carlosframework/platform/internal/analytics 0.043s
ok github.com/carlosframework/platform/internal/appconfig 2.968s
ok github.com/carlosframework/platform/internal/apperr 0.129s
ok github.com/carlosframework/platform/internal/applog 0.184s
ok github.com/carlosframework/platform/internal/awsinv 0.007s
ok github.com/carlosframework/platform/internal/boxchoice 0.006s
ok github.com/carlosframework/platform/internal/boxid 0.925s
? github.com/carlosframework/platform/internal/boxid/boxidtest [no test files]
? github.com/carlosframework/platform/internal/boxid/internal/signtest [no test files]
ok github.com/carlosframework/platform/internal/boxvolumes 0.014s
ok github.com/carlosframework/platform/internal/caps 0.023s
ok github.com/carlosframework/platform/internal/certwarm 0.007s
ok github.com/carlosframework/platform/internal/cgroup 0.804s
ok github.com/carlosframework/platform/internal/changelog 0.630s
ok github.com/carlosframework/platform/internal/claimactivation 1.258s
ok github.com/carlosframework/platform/internal/clamd 0.058s
? github.com/carlosframework/platform/internal/cliflag [no test files]
? github.com/carlosframework/platform/internal/controlname [no test files]
? github.com/carlosframework/platform/internal/controlsock [no test files]
ok github.com/carlosframework/platform/internal/dbdoor 8.404s
ok github.com/carlosframework/platform/internal/dbdoor/dbdoortest 0.013s
ok github.com/carlosframework/platform/internal/dbquery 0.010s
ok github.com/carlosframework/platform/internal/dbreads 2.279s
? github.com/carlosframework/platform/internal/dbreads/dbreadstest [no test files]
ok github.com/carlosframework/platform/internal/dbverify 0.005s
ok github.com/carlosframework/platform/internal/dnsrec 0.005s
ok github.com/carlosframework/platform/internal/docsite 0.012s
ok github.com/carlosframework/platform/internal/domains 2.911s
ok github.com/carlosframework/platform/internal/doorkey 0.014s
ok github.com/carlosframework/platform/internal/economics 0.005s
ok github.com/carlosframework/platform/internal/edge 45.757s
? github.com/carlosframework/platform/internal/edgeproof [no test files]
ok github.com/carlosframework/platform/internal/edgesfile 0.008s
ok github.com/carlosframework/platform/internal/fleetapi 0.131s
ok github.com/carlosframework/platform/internal/gate 1.654s
ok github.com/carlosframework/platform/internal/genselect 0.015s
ok github.com/carlosframework/platform/internal/geo 0.013s
ok github.com/carlosframework/platform/internal/geoip 0.029s
ok github.com/carlosframework/platform/internal/historyreadback 0.156s
ok github.com/carlosframework/platform/internal/host 141.507s
ok github.com/carlosframework/platform/internal/hostactors 6.523s
ok github.com/carlosframework/platform/internal/hostactors/awsmembership 0.005s
ok github.com/carlosframework/platform/internal/hostbox 3.229s
ok github.com/carlosframework/platform/internal/hostclaim 0.782s
ok github.com/carlosframework/platform/internal/hostenv 0.004s
ok github.com/carlosframework/platform/internal/hostevidence 0.006s
ok github.com/carlosframework/platform/internal/hostexec 5.249s
ok github.com/carlosframework/platform/internal/hostfence 0.063s
ok github.com/carlosframework/platform/internal/hostfiles 10.311s
ok github.com/carlosframework/platform/internal/hostfloor 0.015s
ok github.com/carlosframework/platform/internal/hostguard 1.028s
ok github.com/carlosframework/platform/internal/hostops 1.941s
? github.com/carlosframework/platform/internal/hostops/fencerelease [no test files]
ok github.com/carlosframework/platform/internal/hostops/internal/fencerelease 0.003s
ok github.com/carlosframework/platform/internal/hostquarantine 0.004s
ok github.com/carlosframework/platform/internal/hostrelocate 0.612s
ok github.com/carlosframework/platform/internal/hostresolve 0.167s
ok github.com/carlosframework/platform/internal/hostwrite 0.002s
ok github.com/carlosframework/platform/internal/infraview 0.002s
ok github.com/carlosframework/platform/internal/instancectl 5.224s
ok github.com/carlosframework/platform/internal/instanceexec 2.783s
ok github.com/carlosframework/platform/internal/instancefs 0.010s
ok github.com/carlosframework/platform/internal/instancekey 0.004s
ok github.com/carlosframework/platform/internal/instanceupdates 0.012s
ok github.com/carlosframework/platform/internal/layout 1.736s
ok github.com/carlosframework/platform/internal/lbhealth 0.002s
ok github.com/carlosframework/platform/internal/lease 10.245s
ok github.com/carlosframework/platform/internal/lease/leasetest 0.556s
ok github.com/carlosframework/platform/internal/ledger 0.033s
ok github.com/carlosframework/platform/internal/mail 0.282s
ok github.com/carlosframework/platform/internal/maintenance 0.097s
ok github.com/carlosframework/platform/internal/maintenanceexec 5.530s
ok github.com/carlosframework/platform/internal/maintenanceguard 0.112s
ok github.com/carlosframework/platform/internal/metrics 0.016s
ok github.com/carlosframework/platform/internal/moves 22.330s
ok github.com/carlosframework/platform/internal/moves/archive 0.971s
ok github.com/carlosframework/platform/internal/objstore 0.264s
ok github.com/carlosframework/platform/internal/ops 0.242s
ok github.com/carlosframework/platform/internal/park 0.295s
ok github.com/carlosframework/platform/internal/plans 0.005s
ok github.com/carlosframework/platform/internal/privatefile 0.008s
ok github.com/carlosframework/platform/internal/provision 23.260s
ok github.com/carlosframework/platform/internal/publicrelease 0.010s
? github.com/carlosframework/platform/internal/regionname [no test files]
ok github.com/carlosframework/platform/internal/registry 5.511s
ok github.com/carlosframework/platform/internal/relay 7.238s
ok github.com/carlosframework/platform/internal/release 25.999s
ok github.com/carlosframework/platform/internal/rollout 3.814s
ok github.com/carlosframework/platform/internal/rolloutwords 0.007s
ok github.com/carlosframework/platform/internal/rootaws 0.013s
ok github.com/carlosframework/platform/internal/rootparticipation 0.060s
ok github.com/carlosframework/platform/internal/rootstate 0.028s
ok github.com/carlosframework/platform/internal/runs 0.556s
ok github.com/carlosframework/platform/internal/s3compat 0.005s
ok github.com/carlosframework/platform/internal/safefile 0.005s
ok github.com/carlosframework/platform/internal/schedule 2.634s
ok github.com/carlosframework/platform/internal/seeds 0.021s
ok github.com/carlosframework/platform/internal/sim/engines 2.536s
ok github.com/carlosframework/platform/internal/sim/hostlife 10.299s
ok github.com/carlosframework/platform/internal/sim/litestreamfacts 4.314s
ok github.com/carlosframework/platform/internal/status 0.073s
ok github.com/carlosframework/platform/internal/steering 0.006s
ok github.com/carlosframework/platform/internal/stopevidence 0.314s
ok github.com/carlosframework/platform/internal/svcrole 0.002s
ok github.com/carlosframework/platform/internal/telemetry 0.006s
ok github.com/carlosframework/platform/internal/termfence 0.004s
ok github.com/carlosframework/platform/internal/tunnelclient 0.003s
ok github.com/carlosframework/platform/internal/unixdial 0.003s
ok github.com/carlosframework/platform/internal/updatewords 0.005s
ok github.com/carlosframework/platform/internal/usage 0.006s
ok github.com/carlosframework/platform/internal/version 0.002s
ok github.com/carlosframework/platform/internal/vet 1.673s
=== internal_console@0 (86 s)
ok github.com/carlosframework/platform/internal/console 84.782s
=== internal_console@1 (43 s)
ok github.com/carlosframework/platform/internal/console 41.593s
=== internal_console@2 (41 s)
ok github.com/carlosframework/platform/internal/console 39.282s
=== internal_console@3 (42 s)
ok github.com/carlosframework/platform/internal/console 40.030s
=== internal_console@4 (43 s)
ok github.com/carlosframework/platform/internal/console 41.284s
=== internal_console@5 (41 s)
ok github.com/carlosframework/platform/internal/console 39.551s
=== internal_console@6 (37 s)
ok github.com/carlosframework/platform/internal/console 35.630s
=== internal_console@7 (46 s)
ok github.com/carlosframework/platform/internal/console 44.299s
=== root@0 (109 s)
ok github.com/carlosframework/platform 107.256s
=== root@1 (84 s)
ok github.com/carlosframework/platform 82.651s
=== root@2 (92 s)
ok github.com/carlosframework/platform 90.300s
=== cross ===
--- shard 0 of 5 ---
cross-compiling darwin/arm64
--- shard 1 of 5 ---
cross-compiling darwin/amd64
--- shard 2 of 5 ---
cross-compiling linux/arm64
linux/arm64 carlos binary: 50659490 bytes (ceiling 52000000)
--- shard 3 of 5 ---
cross-compiling windows/amd64
--- shard 4 of 5 ---
cross-compiling windows/arm64
=== minio-contract ===
minio contract: arm64, minio RELEASE.2025-09-07T16-13-09Z, mc RELEASE.2025-08-13T08-35-41Z
minio: downloading https://github.com/minio/minio/releases/download/RELEASE.2025-09-07T16-13-09Z/minio.linux-arm64.RELEASE.2025-09-07T16-13-09Z
minio: downloaded, digest verified
mc: downloading https://github.com/minio/mc/releases/download/RELEASE.2025-08-13T08-35-41Z/mc.linux-arm64.RELEASE.2025-08-13T08-35-41Z
mc: downloaded, digest verified
minio healthy on 127.0.0.1:20999
Added `local` successfully.
Bucket created successfully `local/contract-bucket`.
Bucket created successfully `local/denied-bucket`.
Created policy `contract-only` successfully.
Added user `scopeduser` successfully.
Attached Policies: [contract-only]
To User: scopeduser
buckets and scoped user ready
=== RUN TestDeliveredContractMinio
=== RUN TestDeliveredContractMinio/put
=== RUN TestDeliveredContractMinio/get_round-trips_the_body
=== RUN TestDeliveredContractMinio/list_shows_the_key
=== RUN TestDeliveredContractMinio/head_and_list_agree_on_the_version
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_its_own_object
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_its_own_object/not_by_PutObjectTagging
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_its_own_object/and_not_by_x-amz-tagging_on_upload
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/not_by_CreateMultipartUpload
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/not_by_CopyObject_with_a_REPLACE_tagging_directive
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/but_multipart_itself_is_allowed
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/and_copy_itself_is_allowed
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/a_POST-policy_forged_tag_with_a_matching_version_is_still_not_a_verdict
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/and_an_ordinary_tagged-with-something-else_upload_is_allowed
=== RUN TestDeliveredContractMinio/delete_removes_it
=== RUN TestDeliveredContractMinio/cross-bucket_denial
--- PASS: TestDeliveredContractMinio (0.02s)
--- PASS: TestDeliveredContractMinio/put (0.00s)
--- PASS: TestDeliveredContractMinio/get_round-trips_the_body (0.00s)
--- PASS: TestDeliveredContractMinio/list_shows_the_key (0.00s)
--- PASS: TestDeliveredContractMinio/head_and_list_agree_on_the_version (0.00s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_its_own_object (0.00s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_its_own_object/not_by_PutObjectTagging (0.00s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_its_own_object/and_not_by_x-amz-tagging_on_upload (0.00s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route (0.01s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/not_by_CreateMultipartUpload (0.00s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/not_by_CopyObject_with_a_REPLACE_tagging_directive (0.00s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/but_multipart_itself_is_allowed (0.00s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/and_copy_itself_is_allowed (0.00s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/a_POST-policy_forged_tag_with_a_matching_version_is_still_not_a_verdict (0.00s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/and_an_ordinary_tagged-with-something-else_upload_is_allowed (0.00s)
--- PASS: TestDeliveredContractMinio/delete_removes_it (0.00s)
--- PASS: TestDeliveredContractMinio/cross-bucket_denial (0.00s)
PASS
ok github.com/carlosframework/platform/internal/objstore 0.021s
=== RUN TestT4StorageProbeMinio
2026/10/24 21:22:26 moves: T4: STORE: list: operation error S3: ListObjectsV2, https response error StatusCode: 403, RequestID: 18E194156C627FF0, HostID: 7c420053e0fbcd7f41653fdd92ffa2802c903d05303b1aa15adc2e8bb65d183f, api error SignatureDoesNotMatch: The request signature we calculated does not match the signature you provided. Check your key and signing method.
--- PASS: TestT4StorageProbeMinio (0.01s)
PASS
ok github.com/carlosframework/platform/internal/host 0.021s
=== RUN TestS3StoreMinioContract
=== RUN TestS3StoreMinioContract/conditional_get_and_etag_listing
=== RUN TestS3StoreMinioContract/bump_through_every_mutation_path
--- PASS: TestS3StoreMinioContract (0.02s)
--- PASS: TestS3StoreMinioContract/conditional_get_and_etag_listing (0.01s)
--- PASS: TestS3StoreMinioContract/bump_through_every_mutation_path (0.01s)
PASS
ok github.com/carlosframework/platform/internal/release 0.027s
Bucket created successfully `local/dbf-deploy`.
Bucket created successfully `local/dbf-data-ie`.
Bucket created successfully `local/dbf-data-uk`.
local/dbf-deploy versioning is enabled
Created policy `dbf-console` successfully.
Created policy `dbf-ukbox` successfully.
Added user `dbfconsole` successfully.
Added user `dbfukbox` successfully.
Attached Policies: [dbf-console]
To User: dbfconsole
Attached Policies: [dbf-ukbox]
To User: dbfukbox
amadan: job cancelled — a newer push superseded it
diff --git a/docs/superpowers/notes/census-proposal-wake-latency-2.md b/docs/superpowers/notes/census-proposal-wake-latency-2.md| new file mode 100644 |
| index 000000000..32d8ccb2c |
| --- /dev/null |
| +++ b/docs/superpowers/notes/census-proposal-wake-latency-2.md |
| @@ -0,0 +1,16 @@ |
| +# Census approval: wake-latency-2 |
| + |
| +Ruling `census-ruling-wake-latency-2`. Every change below keeps the disposition it already has, so it needs an approval, not a decision. |
| + |
| +| unit | change | read sites | what changed | |
| +|---|---|---|---| |
| +| `internal/activator/backend_exec.go` `ExecBackend.spawnUnitFrom` | body | unchanged (26) | times the launch's steps with time.Now() (build, prepare, launch file, gate, root start) and adds them to its existing "started" journal line; no read added or moved | |
| +| `internal/activator/prepare.go` `ExecBackend.prepareAt` | body | unchanged (1) | passes nil for prepareKeyedAt's new timing parameter; nothing else changed | |
| +| `internal/activator/prepare.go` `ExecBackend.prepareKeyedAt` | body | unchanged (13) | takes an optional timer and marks its steps with time.Now() (dirs, admin token, instance key, env, control socket, key gate, logs); no read added or moved | |
| +| `internal/activator/swaphold.go` `Service.startPinnedAt` | sites | +registry:Host | times record, staged start and health with time.Now() and logs them with rt.Host after a healthy start (the new registry:Host site is that log line); no read added or moved | |
| + |
| +Envelopes re-pinned: `internal/activator`, `internal/instancectl`, `internal/lease`. |
| + |
| +Seal: `0ca3baafa26f59c0b7d8c6d6a39237d074afb71f885b7fbd50debebab5bf89f2` → `27b020590845320cd37b94fdeddf61b7c6f90e12ba7841850f2e7bbd6836ecd8`. |
| + |
| +Overlay: `internal/provision/testdata/plan14-root-reads-wake-latency-2.tsv`, appended to `internal/provision/testdata/plan14-root-reads-chain.tsv`. |
diff --git a/internal/activator/backend_exec.go b/internal/activator/backend_exec.go| index 6656e8ee9..d6c81c739 100644 |
| --- a/internal/activator/backend_exec.go |
| +++ b/internal/activator/backend_exec.go |
| @@ -2394,6 +2394,9 @@ func (b *ExecBackend) normalizeSocketMode(rt registry.Route, sock string, proc P |
| // generation-keyed files (unitGen); otherwise it is ignored. A failure |
| // whose kill could not prove the unit empty wraps errGenUnproven. |
| func (b *ExecBackend) spawnUnitFrom(ctx context.Context, rt registry.Route, sock string, n uint64, exe *instancectl.StagedExe, tier cgroup.Limit) (Proc, string, error) { |
| + // The launch's own split, for the journal (wake latency, pass 2). |
| + var steps wakeSteps |
| + steps.begin(time.Now()) |
| if err := b.nestedGate(rt); err != nil { |
| return nil, "", err |
| } |
| @@ -2421,7 +2424,9 @@ func (b *ExecBackend) spawnUnitFrom(ctx context.Context, rt registry.Route, sock |
| return nil, "", err |
| } |
| } |
| - p, ctl, logs, fileEnv, keyLayer, err := b.prepareKeyedAt(rt, instancectl.RoleRun, sock, gen) |
| + steps.mark(time.Now(), "build") |
| + var prep wakeSteps |
| + p, ctl, logs, fileEnv, keyLayer, err := b.prepareKeyedAt(rt, instancectl.RoleRun, sock, gen, &prep) |
| if err != nil { |
| return nil, "", err |
| } |
| @@ -2434,9 +2439,11 @@ func (b *ExecBackend) spawnUnitFrom(ctx context.Context, rt registry.Route, sock |
| } |
| childVars := b.agentOwnedVars(rt, sock+".control", fileEnv, ctl != nil) |
| argv := []string{b.liveLink(rt.Host), "--socket", sock, "--db", p.dbPath} |
| + steps.mark(time.Now(), "prepare ("+prep.String()+")") |
| if err := b.writeLaunchFor(p, instancectl.RoleRun, gen, rt.Host, argv, childEnv(childVars)); err != nil { |
| return fail(err) |
| } |
| + steps.mark(time.Now(), "launch file") |
| // Read the symlink immediately before the start, same fail-safe |
| // direction as startChild: a concurrent repoint at worst records the |
| // older version (one extra convergence cycle), never the newer. A |
| @@ -2461,7 +2468,9 @@ func (b *ExecBackend) spawnUnitFrom(ctx context.Context, rt registry.Route, sock |
| } |
| return fail(err) |
| } |
| + steps.mark(time.Now(), "gate") |
| inv, err := b.startRole(ctx, rt, instancectl.RoleRun, gen, exe, tier) |
| + steps.mark(time.Now(), "root start") |
| // Past this call root may have started the unit: every failure below |
| // but ErrStagedExe (root's refusal before it laid out or started |
| // anything) and errNoStagedExeControl (root was never asked: the |
| @@ -2518,7 +2527,7 @@ func (b *ExecBackend) spawnUnitFrom(ctx context.Context, rt registry.Route, sock |
| if started == (cgroup.Limit{}) { |
| started = b.tier(rt) |
| } |
| - log.Printf("activator: %s: started %s memory.max=%d", rt.Host, unitName(instancectl.RoleRun, rt.Host, gen), started.MemoryMax) |
| + log.Printf("activator: %s: started %s memory.max=%d (%s)", rt.Host, unitName(instancectl.RoleRun, rt.Host, gen), started.MemoryMax, steps.String()) |
| up := b.newUnitProcFor(rt, instancectl.RoleRun, gen, p, inv, ctl, logs) |
| // The file environment this generation launched with, kept on its |
| // handle: a run against it composes its environment from this, never |
diff --git a/internal/activator/prepare.go b/internal/activator/prepare.go| index 39eadb475..288d79507 100644 |
| --- a/internal/activator/prepare.go |
| +++ b/internal/activator/prepare.go |
| @@ -47,7 +47,7 @@ func (b *ExecBackend) prepare(rt registry.Route, role instancectl.Role) (instanc |
| // it keys the log socket and the exit records cleared (zero-downtime spec |
| // §7.6). |
| func (b *ExecBackend) prepareAt(rt registry.Route, role instancectl.Role, sock string, gen uint64) (instancePaths, *edge.ControlListener, *logListener, map[string]string, error) { |
| - p, ctl, logs, env, _, err := b.prepareKeyedAt(rt, role, sock, gen) |
| + p, ctl, logs, env, _, err := b.prepareKeyedAt(rt, role, sock, gen, nil) |
| return p, ctl, logs, env, err |
| } |
| @@ -55,7 +55,13 @@ func (b *ExecBackend) prepareAt(rt registry.Route, role instancectl.Role, sock s |
| // CARLOS_INSTANCE_KEY came from, decided by the same read (instance-key |
| // ruling 29). The nested run spawn keeps both on the generation's handle, |
| // for a run's command against that generation (StartCmd). |
| -func (b *ExecBackend) prepareKeyedAt(rt registry.Route, role instancectl.Role, sock string, gen uint64) (instancePaths, *edge.ControlListener, *logListener, map[string]string, instancekey.Layer, error) { |
| +// steps, when not nil, times prepare's parts for the caller's journal line. |
| +func (b *ExecBackend) prepareKeyedAt(rt registry.Route, role instancectl.Role, sock string, gen uint64, steps *wakeSteps) (instancePaths, *edge.ControlListener, *logListener, map[string]string, instancekey.Layer, error) { |
| + if steps == nil { |
| + steps = &wakeSteps{} |
| + } else { |
| + steps.begin(time.Now()) |
| + } |
| p := b.pathsFor(rt) |
| if err := os.MkdirAll(p.dataDir, 0o700); err != nil { |
| return p, nil, nil, nil, instancekey.LayerNone, err |
| @@ -66,6 +72,7 @@ func (b *ExecBackend) prepareKeyedAt(rt registry.Route, role instancectl.Role, s |
| if err := os.MkdirAll(filepath.Dir(b.logSocketFor(rt.Host, role, gen)), 0o700); err != nil { |
| return p, nil, nil, nil, instancekey.LayerNone, err |
| } |
| + steps.mark(time.Now(), "dirs") |
| var env map[string]string |
| var keyLayer instancekey.Layer // the layer env's key came from, read with it (ruling 29) |
| switch role { |
| @@ -76,14 +83,17 @@ func (b *ExecBackend) prepareKeyedAt(rt registry.Route, role instancectl.Role, s |
| if err := EnsureAdminTokenBeneath(p.dataDir, rt.Host+".env"); err != nil { |
| return p, nil, nil, nil, instancekey.LayerNone, fmt.Errorf("admin token for %s: %w", rt.Host, err) |
| } |
| + steps.mark(time.Now(), "admin token") |
| if _, err := b.ensureInstanceKeyFor(context.Background(), rt, p); err != nil { // prepareAt has no ctx to bound the mint's bucket read; configReadTimeout does |
| return p, nil, nil, nil, instancekey.LayerNone, fmt.Errorf("instance key for %s: %w", rt.Host, err) |
| } |
| + steps.mark(time.Now(), "instance key") |
| var err error |
| env, keyLayer, err = b.instanceEnvLayer(rt) |
| if err != nil { |
| return p, nil, nil, nil, instancekey.LayerNone, err |
| } |
| + steps.mark(time.Now(), "env") |
| case instancectl.RoleCmd: |
| // A run's environment is the one its generation launched with |
| // (merge ruling M3), which StartCmd has. The delivered files are |
| @@ -137,6 +147,7 @@ func (b *ExecBackend) prepareKeyedAt(rt registry.Route, role instancectl.Role, s |
| } |
| _ = os.Remove(sock) |
| ctl = b.listenControl(rt, sock+".control", p.envFile, gen) |
| + steps.mark(time.Now(), "control socket") |
| } |
| // A replica's roles are gated like a flat launch (ruling 26): the seed |
| // and the sidecar have no control socket, the run role has the one just |
| @@ -152,6 +163,7 @@ func (b *ExecBackend) prepareKeyedAt(rt registry.Route, role instancectl.Role, s |
| return p, nil, nil, nil, instancekey.LayerNone, err |
| } |
| } |
| + steps.mark(time.Now(), "key gate") |
| // The cmd role's output goes only to its own chunks, never to the |
| // journal or the app log, so it has no app-log listener. |
| var logs *logListener |
| @@ -165,6 +177,7 @@ func (b *ExecBackend) prepareKeyedAt(rt registry.Route, role instancectl.Role, s |
| return p, nil, nil, nil, instancekey.LayerNone, fmt.Errorf("log listener for %s %s: %w", rt.Host, role, err) |
| } |
| } |
| + steps.mark(time.Now(), "logs") |
| return p, ctl, logs, env, keyLayer, nil |
| } |
diff --git a/internal/activator/swaphold.go b/internal/activator/swaphold.go| index c55654d96..279606566 100644 |
| --- a/internal/activator/swaphold.go |
| +++ b/internal/activator/swaphold.go |
| @@ -458,13 +458,17 @@ func (a *Service) startPinnedAt(ctx context.Context, rt registry.Route, pin Gen, |
| // records again). A refusal returns no process: nothing ran. If the |
| // backend's own exec gate then refuses, the state names a build about to |
| // run that did not, which the spec allows ("or one about to"). |
| + // Timed for the journal (wake latency, pass 2). |
| + began := time.Now() |
| if err := a.recordBuild(ctx, rt.Host, pin.Build); err != nil { |
| return nil, "", pin, err |
| } |
| + recorded := time.Now() |
| g, proc, err := gb.StartStaged(withExecGate(ctx, gate), rt, pin) |
| if err != nil { |
| return proc, "", pin, err |
| } |
| + started := time.Now() |
| if g.N != pin.N || g.Build != pin.Build || g.StagedPath != pin.StagedPath { |
| return proc, "", pin, fmt.Errorf("%w: generation %d of %s from %q; the hold chose %s from %q", errPinMismatch, g.N, g.Build, g.StagedPath, pin.Build, pin.StagedPath) |
| } |
| @@ -477,6 +481,8 @@ func (a *Service) startPinnedAt(ctx context.Context, rt registry.Route, pin Gen, |
| if err := a.genHealthy(hctx, g); err != nil { |
| return proc, "", g, err |
| } |
| + log.Printf("activator: %s: generation %d of %s: record %s, start %s, healthy %s later", rt.Host, g.N, g.Build, |
| + recorded.Sub(began).Round(time.Millisecond), started.Sub(recorded).Round(time.Millisecond), time.Since(started).Round(time.Millisecond)) |
| gb.GenReady(rt, g, proc) |
| return proc, g.Build, g, nil |
| } |
diff --git a/internal/instancectl/gen.go b/internal/instancectl/gen.go| index c23172173..54b308362 100644 |
| --- a/internal/instancectl/gen.go |
| +++ b/internal/instancectl/gen.go |
| @@ -155,6 +155,7 @@ func (s *Server) startGen(w http.ResponseWriter, r *http.Request, req request) { |
| if s.refuseStagedExe(w, req, unit) { |
| return |
| } |
| + checked := time.Now() |
| if s.refuseStart(w, req.host, unit, func() error { |
| err := s.ensureGenExeAt(req.host, req.gen, req.exe) |
| if err != nil { |
| @@ -168,10 +169,12 @@ func (s *Server) startGen(w http.ResponseWriter, r *http.Request, req request) { |
| s.removeGenFiles(unit) |
| http.Error(w, msg, status) |
| } |
| + laidOut := time.Now() |
| if err := s.writeGenDropIn(req.host, req.gen, req.tier); err != nil { |
| fail(http.StatusBadGateway, "drop-in: "+err.Error()) |
| return |
| } |
| + written := time.Now() |
| // The reload is only for a unit systemd already holds loaded from older |
| // files. A generation's unit is new and an inactive one is unloaded |
| // straight away, so the next reference reads the drop-in fresh: the |
| @@ -210,8 +213,9 @@ func (s *Server) startGen(w http.ResponseWriter, r *http.Request, req request) { |
| s.abandonGen(ctx, w, req.host, unit, "show: "+err.Error()) |
| return |
| } |
| - s.logf("instance-control: %s: started %s memory.max=%d (prepared in %s, reload %s, start %s)", req.host, unit, req.tier.MemoryMax, |
| - startAt.Sub(began).Round(time.Millisecond), reload, time.Since(startAt).Round(time.Millisecond)) |
| + ms := func(d time.Duration) time.Duration { return d.Round(time.Millisecond) } |
| + s.logf("instance-control: %s: started %s memory.max=%d (prepared in %s: staged exe %s, layout %s, drop-in %s, check and tier %s; reload %s, start %s)", req.host, unit, req.tier.MemoryMax, |
| + ms(startAt.Sub(began)), ms(checked.Sub(began)), ms(laidOut.Sub(checked)), ms(written.Sub(laidOut)), ms(startAt.Sub(written)), reload, ms(time.Since(startAt))) |
| writeJSON(w, http.StatusOK, StartResponse{InvocationID: strings.TrimSpace(inv)}) |
| } |
diff --git a/internal/lease/lease.go b/internal/lease/lease.go| index 3da80af54..11c14c5de 100644 |
| --- a/internal/lease/lease.go |
| +++ b/internal/lease/lease.go |
| @@ -15,6 +15,7 @@ import ( |
| "context" |
| "errors" |
| "fmt" |
| + "log" |
| "os" |
| "path/filepath" |
| "sync" |
| @@ -175,10 +176,12 @@ func AcquireTTL(ctx context.Context, bucket, prefix, region string, ttl time.Dur |
| // and the data it guards must resolve to the same store. The region is |
| // resolved ONCE, here, and carried on the Held: Replicate's replica client |
| // has to sign for whatever this client signed for. |
| + began := time.Now() |
| client, region, err := newLeaserClient(ctx, region) |
| if err != nil { |
| return nil, err |
| } |
| + built := time.Now() |
| leaser := lss3.NewLeaser() |
| leaser.SetClient(client) |
| @@ -205,6 +208,10 @@ func AcquireTTL(ctx context.Context, bucket, prefix, region string, ttl time.Dur |
| _ = leaser.ReleaseLease(relCtx, cur) |
| return nil, err |
| } |
| + // Journal only: the wake's lease step, split into the client and the |
| + // lock's own read and conditional write. |
| + log.Printf("lease: %s: acquired in %s (client %s, lock read and write %s)", prefix, |
| + time.Since(began).Round(time.Millisecond), built.Sub(began).Round(time.Millisecond), time.Since(started).Round(time.Millisecond)) |
| return &Held{leaser: leaser, region: region, rn: rn}, nil |
| } |
diff --git a/internal/provision/testdata/plan14-root-reads-chain.tsv b/internal/provision/testdata/plan14-root-reads-chain.tsv| index b55f07f47..283a2117c 100644 |
| --- a/internal/provision/testdata/plan14-root-reads-chain.tsv |
| +++ b/internal/provision/testdata/plan14-root-reads-chain.tsv |
| @@ -4,3 +4,4 @@ |
| plan14-root-reads-sec-host-imdsv2-module.tsv 945934f5978ace14dc5a9bae0ed69dfabf29b994504fc843c03d4a633ecd6c6a |
| plan14-root-reads-sec-deps-dos-bumps.tsv 945934f5978ace14dc5a9bae0ed69dfabf29b994504fc843c03d4a633ecd6c6a |
| plan14-root-reads-sec-sidecar-create-gate.tsv 0ca3baafa26f59c0b7d8c6d6a39237d074afb71f885b7fbd50debebab5bf89f2 |
| +plan14-root-reads-wake-latency-2.tsv 27b020590845320cd37b94fdeddf61b7c6f90e12ba7841850f2e7bbd6836ecd8 |
diff --git a/internal/provision/testdata/plan14-root-reads-wake-latency-2.tsv b/internal/provision/testdata/plan14-root-reads-wake-latency-2.tsv| new file mode 100644 |
| index 000000000..86337c8d9 |
| --- /dev/null |
| +++ b/internal/provision/testdata/plan14-root-reads-wake-latency-2.tsv |
| @@ -0,0 +1,13 @@ |
| +# Census overlay wake-latency-2, written by census-propose (#369). census-ruling-wake-latency-2, approved by the census owner before the merge; the approval card is docs/superpowers/notes/census-proposal-wake-latency-2.md. |
| +# 3 body, 1 sites, 3 envelope: each changed unit re-frozen at its existing disposition with its claim appended. |
| +@legacy b2c5ff1260bffcd7f2cc4b537ebc79989befbc6aeaf04f4330d775cb30cb49fe internal/activator/backend_exec.go ExecBackend.spawnUnitFrom legacy accepted-legacy accepted-legacy;rev3=census-ruling-carlos-run;basis=Re-digested at the pre-land merge: the body includes main's own change under census ruling 292, with no further change from this branch. the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos): main's body; it calls prepareKeyedAt and keeps the launch environment and its key layer on the generation's handle; read sites unchanged, offsets moved;rev3=census-ruling-wake-latency-2;basis=times the launch's steps with time.Now() (build, prepare, launch file, gate, root start) and adds them to its existing "started" journal line; no read added or moved registry:Host@1185,registry:Host@1662,registry:Host@1820,registry:Host@2277,registry:Host@2757,registry:Host@3753,registry:Host@4339,registry:Host@4609,registry:Host@4829,registry:Host@5014,registry:Host@5409,registry:Host@5690,registry:Host@5752,registry:Host@5910,registry:Host@5949,registry:Host@6797,registry:Host@6891,whole:Route@1349,whole:Route@1591,whole:Route@2993,whole:Route@308,whole:Route@4662,whole:Route@5843,whole:Route@6023,whole:Route@872,whole:Route@970 24ca0bdb76b85948fb34916a49eab74e5eaf4ebea02d57adc309cbe9d0adafd8 |
| +@legacy 41bab0818501b13d67f0b5201601faa043c0097016faabe1d932155d1080e170 internal/activator/prepare.go ExecBackend.prepareAt legacy accepted-legacy accepted-legacy;rev3=census-ruling-carlos-run;basis=the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos): now a wrapper: its ReadDir and its Host and route reads moved, unchanged, into prepareKeyedAt;rev3=census-ruling-wake-latency-2;basis=passes nil for prepareKeyedAt's new timing parameter; nothing else changed whole:Route@227 6aa2cdbd41f356d0a7497025efacb62b05a5e4f293cb20b3423bddc4c92ae72a |
| +@legacy 43fecababb55813cdd4ead403f99f119705bce26992eef5bcf85e0b25ffefeb8 internal/activator/prepare.go ExecBackend.prepareKeyedAt legacy accepted-legacy accepted-legacy;rev3=census-ruling-carlos-run;basis=Re-digested at the pre-land merge: the body includes main's own change under census ruling zddr4, with no further change from this branch beyond carrying main's new early return into the six-value signature. the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos): body of the frozen prepareAt, which is now its wrapper; it also returns the instance key's layer and reads no env for the cmd role; same reads, same nested launch paths;rev3=census-ruling-wake-latency-2;basis=takes an optional timer and marks its steps with time.Now() (dirs, admin token, instance key, env, control socket, key gate, logs); no read added or moved file:ReadDir@2531,registry:Host@1162,registry:Host@1280,registry:Host@1588,registry:Host@5195,registry:Host@5384,registry:Host@612,whole:Route@1398,whole:Route@1705,whole:Route@320,whole:Route@4244,whole:Route@4772,whole:Route@5229 8f172cc2cdb6cea7fad368c8c0a153f1e196616b39307a9bee0c6c1672f797b2 |
| +@legacy dc96074aa3bb2b5cea94c19a05330846701676abe78a3fa42a3587dc54c8556e internal/activator/swaphold.go Service.startPinnedAt legacy accepted-legacy accepted-legacy;rev3=J1;basis=root-route;rev3=census-ruling-wake-latency-2;basis=times record, staged start and health with time.Now() and logs them with rt.Host after a healthy start (the new registry:Host site is that log line); no read added or moved registry:Host@1183,registry:Host@1964,whole:Route@1328,whole:Route@2139,whole:Route@435 20c4e4acf9186100d5f9d3e188665597bd36f790443691a9d8c84555b67ade8a |
| +internal/activator/backend_exec.go ExecBackend.spawnUnitFrom legacy accepted-legacy accepted-legacy;rev3=census-ruling-carlos-run;basis=Re-digested at the pre-land merge: the body includes main's own change under census ruling 292, with no further change from this branch. the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos): main's body; it calls prepareKeyedAt and keeps the launch environment and its key layer on the generation's handle; read sites unchanged, offsets moved;rev3=census-ruling-wake-latency-2;basis=times the launch's steps with time.Now() (build, prepare, launch file, gate, root start) and adds them to its existing "started" journal line; no read added or moved registry:Host@1185,registry:Host@1662,registry:Host@1820,registry:Host@2277,registry:Host@2757,registry:Host@3753,registry:Host@4339,registry:Host@4609,registry:Host@4829,registry:Host@5014,registry:Host@5409,registry:Host@5690,registry:Host@5752,registry:Host@5910,registry:Host@5949,registry:Host@6797,registry:Host@6891,whole:Route@1349,whole:Route@1591,whole:Route@2993,whole:Route@308,whole:Route@4662,whole:Route@5843,whole:Route@6023,whole:Route@872,whole:Route@970 24ca0bdb76b85948fb34916a49eab74e5eaf4ebea02d57adc309cbe9d0adafd8 |
| +internal/activator/prepare.go ExecBackend.prepareAt legacy accepted-legacy accepted-legacy;rev3=census-ruling-carlos-run;basis=the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos): now a wrapper: its ReadDir and its Host and route reads moved, unchanged, into prepareKeyedAt;rev3=census-ruling-wake-latency-2;basis=passes nil for prepareKeyedAt's new timing parameter; nothing else changed whole:Route@227 6aa2cdbd41f356d0a7497025efacb62b05a5e4f293cb20b3423bddc4c92ae72a |
| +internal/activator/prepare.go ExecBackend.prepareKeyedAt legacy accepted-legacy accepted-legacy;rev3=census-ruling-carlos-run;basis=Re-digested at the pre-land merge: the body includes main's own change under census ruling zddr4, with no further change from this branch beyond carrying main's new early return into the six-value signature. the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos): body of the frozen prepareAt, which is now its wrapper; it also returns the instance key's layer and reads no env for the cmd role; same reads, same nested launch paths;rev3=census-ruling-wake-latency-2;basis=takes an optional timer and marks its steps with time.Now() (dirs, admin token, instance key, env, control socket, key gate, logs); no read added or moved file:ReadDir@2531,registry:Host@1162,registry:Host@1280,registry:Host@1588,registry:Host@5195,registry:Host@5384,registry:Host@612,whole:Route@1398,whole:Route@1705,whole:Route@320,whole:Route@4244,whole:Route@4772,whole:Route@5229 8f172cc2cdb6cea7fad368c8c0a153f1e196616b39307a9bee0c6c1672f797b2 |
| +internal/activator/swaphold.go Service.startPinnedAt legacy accepted-legacy accepted-legacy;rev3=J1;basis=root-route;rev3=census-ruling-wake-latency-2;basis=times record, staged start and health with time.Now() and logs them with rt.Host after a healthy start (the new registry:Host site is that log line); no read added or moved registry:Host@1183,registry:Host@1964,whole:Route@1328,whole:Route@2139,whole:Route@435 20c4e4acf9186100d5f9d3e188665597bd36f790443691a9d8c84555b67ade8a |
| +@coverage internal/activator 01ef3773518c962eaf5e0bc12dce99847f6fa42326f39a5f5e201941d10eaf5c |
| +@coverage internal/instancectl 8b91f954d7b96ca3ff0251152d7049aa94c935680c12e7f5eb2cfc47105f1add |
| +@coverage internal/lease 65b4e9e54300b00e8d09af4580c7184b78977bfecff40adfdff2ab9eb571fbb2 |