Skip to content

Commit 18c24a3

Browse files
steveyeggeclaude
andauthored
perf(metrics): stop paying telemetry startup costs on every bd invocation (gastownhall#5646)
* perf(metrics): cache the telemetry machine ID; never probe when metrics are disabled (bd-rzweb) metrics.Init eagerly computed eventkit.MachineID on every bd invocation — a fork of the platform machine-id probe (ioreg on macOS), measured at 20.2±1.2ms — even with BD_DISABLE_METRICS=1 and even for bd --version, because the enabled gate only selected the emitter. Now the ID is resolved only on the enabled path, and cached at ~/.beads/machine-id (0600, atomic temp+rename write) so the probe forks at most once per machine instead of once per invocation. A probe failure (eventkit's literal "invalid") is never cached, and a corrupt cache reads as a miss and is recomputed. The probe call itself stays in metrics.go behind computeMachineID, keeping the depguard eventkit fence unchanged. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> * perf(metrics): spawn the send-metrics flusher only when events are queued, at most every 5 minutes (bd-p6o3y) CloseAndFlush unconditionally re-exec'd the full bd binary as a detached 'bd send-metrics' child (plus an HTTPS POST) on every invocation — 8.5 to 14.1ms in-band before the child even starts, ~10k spawns/day on a busy machine, with no check that anything was queued. MaybeSpawnFlusher now spawns only when the eventsData queue holds at least one .evtq batch AND the last spawn attempt is 5+ minutes old (marker file eventsData/.last-flush, mtime = last attempt; attempt-based so the rate stays bounded even when uploads keep failing). The marker carries no .evtq extension so the eventkit FileFlusher scan ignores it. Queued events still upload — batched, worst case one interval late plus one bd invocation. Env/config gates (BD_IS_FLUSHER, BD_DISABLE_METRICS, BD_DISABLE_EVENT_FLUSH, BEADS_TEST_MODE) are unchanged and still checked first. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> * perf(metrics): stat the throttle marker before scanning the event queue (bd-p6o3y) flusherDue scanned the queue dir with os.ReadDir before consulting the throttle marker — and os.ReadDir reads and sorts EVERY entry before returning. On a machine whose uploads keep failing, the queue backs up without bound (148k .evtq / 1.1GB observed), and that scan cost ~250ms on every bd invocation: the commit meant to remove a ~10ms tax added a 5x startup regression (65ms -> 330ms for bd --version) exactly where the queue is unhealthiest. Caught re-measuring bd-c9c57 against this branch. Now the marker stat runs first, so the throttled path — every invocation inside the 5-minute interval — is one stat and never touches the queue; the pending-events check (hasQueuedEvents) reads the directory in unsorted 64-entry chunks and returns at the first match. Decision semantics are unchanged for every marker-age/queue-state combination. Measured: 40ms warm against the 148k-entry queue. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> --------- Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
1 parent 96388ea commit 18c24a3

6 files changed

Lines changed: 611 additions & 3 deletions

File tree

CHANGELOG.md

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -446,6 +446,21 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
446446

447447
### Fixed
448448

449+
- **Telemetry no longer taxes every bd invocation.** Two startup costs paid on
450+
every command, measured during the post-wave startup audit, are gone. First,
451+
the machine-scoped distinct ID was recomputed on every invocation — a fork
452+
of the platform machine-id probe (`ioreg` on macOS, 20.2±1.2ms) — even with
453+
`BD_DISABLE_METRICS=1` and even for `bd --version`. The ID is now resolved
454+
only when metrics are enabled and cached at `~/.beads/machine-id` (0600), so
455+
the probe runs at most once per machine; a probe failure is retried next run
456+
rather than cached. Second, every invocation unconditionally spawned a
457+
detached `bd send-metrics` child — a full re-exec of the binary plus an
458+
HTTPS upload attempt, with no check that anything was queued. The spawn now
459+
requires at least one queued event batch and is throttled to one attempt per
460+
5 minutes (marker: `eventsData/.last-flush`); queued events still upload,
461+
just batched. Telemetry content, opt-out semantics, and the sanctioned
462+
endpoint pinning are all unchanged.
463+
449464
- **A long or multi-paragraph close reason renders as body text in `bd show`**
450465
([#5595](https://github.com/gastownhall/beads/pull/5595)). Every other
451466
free-text field — description, design, notes, acceptance criteria, comments —

internal/metrics/machineid.go

Lines changed: 117 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,117 @@
1+
package metrics
2+
3+
import (
4+
"os"
5+
"path/filepath"
6+
"strings"
7+
)
8+
9+
// machineIDCacheName is the file under ~/.beads that persists the telemetry
10+
// distinct ID. eventkit.MachineID shells out to the platform machine-id probe
11+
// (`ioreg` on macOS, DMI/registry reads elsewhere) via denisbrodbeck/machineid
12+
// on every call — measured at 20.2±1.2ms per bd invocation — so the computed
13+
// ID is cached here once and reused by every subsequent invocation, including
14+
// the detached send-metrics child. The ID is already an app-scoped HMAC of the
15+
// platform machine ID (machineid.ProtectedID), not the raw machine ID, so the
16+
// cache stores nothing more sensitive than what every telemetry event carries;
17+
// it is still written 0600 like the rest of our per-user state.
18+
const machineIDCacheName = "machine-id"
19+
20+
// maxMachineIDLen bounds what the cache read will accept. ProtectedID today is
21+
// a 64-char hex HMAC; the bound is loose so an upstream format change does not
22+
// silently invalidate every cache, while still refusing to feed a corrupt or
23+
// swapped-in file into every event's distinct_id.
24+
const maxMachineIDLen = 128
25+
26+
func machineIDCachePath() (string, error) {
27+
home, err := os.UserHomeDir()
28+
if err != nil {
29+
return "", err
30+
}
31+
return filepath.Join(home, dataDirName, machineIDCacheName), nil
32+
}
33+
34+
// validMachineID accepts a cached or freshly computed ID for (re)use: one
35+
// non-empty token of printable non-space ASCII, bounded length, and not the
36+
// literal "invalid" that eventkit.MachineID returns when the platform probe
37+
// fails — a failed probe must be retried next run, never cached.
38+
func validMachineID(id string) bool {
39+
if id == "" || id == "invalid" || len(id) > maxMachineIDLen {
40+
return false
41+
}
42+
for _, r := range id {
43+
if r <= ' ' || r > '~' {
44+
return false
45+
}
46+
}
47+
return true
48+
}
49+
50+
func readCachedMachineID(path string) string {
51+
// #nosec G304 -- path is derived from os.UserHomeDir + our fixed cache
52+
// name (machineIDCachePath), never from user or repository input.
53+
data, err := os.ReadFile(path)
54+
if err != nil {
55+
return ""
56+
}
57+
id := strings.TrimSpace(string(data))
58+
if !validMachineID(id) {
59+
return ""
60+
}
61+
return id
62+
}
63+
64+
// writeMachineIDCache persists id atomically (temp file + rename) so a
65+
// concurrent reader can never observe a truncated ID. Failures are ignored:
66+
// the cache is a pure optimization and the caller already holds a usable ID.
67+
func writeMachineIDCache(path, id string) {
68+
dir := filepath.Dir(path)
69+
if err := os.MkdirAll(dir, 0o700); err != nil {
70+
return
71+
}
72+
tmp, err := os.CreateTemp(dir, machineIDCacheName+".tmp-*")
73+
if err != nil {
74+
return
75+
}
76+
name := tmp.Name()
77+
if err := tmp.Chmod(0o600); err != nil {
78+
_ = tmp.Close()
79+
_ = os.Remove(name)
80+
return
81+
}
82+
if _, err := tmp.WriteString(id + "\n"); err != nil {
83+
_ = tmp.Close()
84+
_ = os.Remove(name)
85+
return
86+
}
87+
if err := tmp.Close(); err != nil {
88+
_ = os.Remove(name)
89+
return
90+
}
91+
if err := os.Rename(name, path); err != nil {
92+
_ = os.Remove(name)
93+
}
94+
}
95+
96+
// cachedMachineID returns the stable distinct ID for this machine, reading the
97+
// ~/.beads/machine-id cache first and falling back to the (slow) platform
98+
// probe, whose result it caches for every later invocation. Only called when
99+
// metrics are enabled — a disabled invocation never pays for an ID at all.
100+
//
101+
// The probe itself (computeMachineID, backed by eventkit.MachineID) lives in
102+
// metrics.go: eventkit imports are depguard-fenced to metrics.go/flusher.go
103+
// (.golangci.yml dolt-storage-boundary), and this file needs none of it.
104+
func cachedMachineID(appName string) string {
105+
path, err := machineIDCachePath()
106+
if err != nil {
107+
return computeMachineID(appName)
108+
}
109+
if id := readCachedMachineID(path); id != "" {
110+
return id
111+
}
112+
id := computeMachineID(appName)
113+
if validMachineID(id) {
114+
writeMachineIDCache(path, id)
115+
}
116+
return id
117+
}

internal/metrics/machineid_test.go

Lines changed: 170 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,170 @@
1+
package metrics
2+
3+
import (
4+
"os"
5+
"path/filepath"
6+
"runtime"
7+
"strings"
8+
"testing"
9+
)
10+
11+
// TestCachedMachineIDReusesCacheWithoutRecomputing seeds the on-disk cache
12+
// with a sentinel and asserts cachedMachineID returns it verbatim — proving
13+
// the cached path never reaches the (slow, forking) platform probe, which
14+
// could not produce the sentinel.
15+
func TestCachedMachineIDReusesCacheWithoutRecomputing(t *testing.T) {
16+
home := t.TempDir()
17+
t.Setenv("HOME", home)
18+
if runtime.GOOS == "windows" {
19+
t.Setenv("USERPROFILE", home)
20+
}
21+
22+
sentinel := strings.Repeat("ab12", 16) // 64 chars, valid shape
23+
dir := filepath.Join(home, ".beads")
24+
if err := os.MkdirAll(dir, 0o700); err != nil {
25+
t.Fatalf("mkdir: %v", err)
26+
}
27+
if err := os.WriteFile(filepath.Join(dir, machineIDCacheName), []byte(sentinel+"\n"), 0o600); err != nil {
28+
t.Fatalf("seed cache: %v", err)
29+
}
30+
31+
if got := cachedMachineID(AppName); got != sentinel {
32+
t.Errorf("cachedMachineID = %q, want cached sentinel %q", got, sentinel)
33+
}
34+
}
35+
36+
// TestCachedMachineIDComputesAndPersistsOnMiss exercises the cold path: no
37+
// cache file, so the ID is computed once and written to ~/.beads/machine-id
38+
// (0600) for every later invocation to reuse.
39+
func TestCachedMachineIDComputesAndPersistsOnMiss(t *testing.T) {
40+
home := t.TempDir()
41+
t.Setenv("HOME", home)
42+
if runtime.GOOS == "windows" {
43+
t.Setenv("USERPROFILE", home)
44+
}
45+
46+
first := cachedMachineID(AppName)
47+
if first == "" {
48+
t.Fatalf("cachedMachineID returned empty ID")
49+
}
50+
51+
path := filepath.Join(home, ".beads", machineIDCacheName)
52+
if !validMachineID(first) {
53+
// The platform probe failed (returns "invalid" in sandboxed CI);
54+
// a failure must NOT be cached, so the next run retries.
55+
if _, err := os.Stat(path); !os.IsNotExist(err) {
56+
t.Errorf("invalid probe result was cached at %s (stat err=%v)", path, err)
57+
}
58+
return
59+
}
60+
61+
data, err := os.ReadFile(path)
62+
if err != nil {
63+
t.Fatalf("cache not written: %v", err)
64+
}
65+
if got := strings.TrimSpace(string(data)); got != first {
66+
t.Errorf("cache content = %q, want %q", got, first)
67+
}
68+
if runtime.GOOS != "windows" {
69+
fi, err := os.Stat(path)
70+
if err != nil {
71+
t.Fatalf("stat cache: %v", err)
72+
}
73+
if perm := fi.Mode().Perm(); perm != 0o600 {
74+
t.Errorf("cache perms = %o, want 0600", perm)
75+
}
76+
}
77+
78+
// Second call returns the identical ID (now from cache).
79+
if second := cachedMachineID(AppName); second != first {
80+
t.Errorf("second cachedMachineID = %q, want %q", second, first)
81+
}
82+
}
83+
84+
// TestReadCachedMachineIDRejectsGarbage: a corrupt, oversized, multi-token, or
85+
// probe-failure ("invalid") cache must read as a miss so the ID is recomputed,
86+
// never fed into every event's distinct_id.
87+
func TestReadCachedMachineIDRejectsGarbage(t *testing.T) {
88+
dir := t.TempDir()
89+
cases := []struct {
90+
name string
91+
content string
92+
}{
93+
{name: "empty", content: ""},
94+
{name: "whitespace-only", content: " \n\t\n"},
95+
{name: "probe-failure-marker", content: "invalid\n"},
96+
{name: "embedded-space", content: "abc def\n"},
97+
{name: "multi-line", content: "abc123\nxyz789\n"},
98+
{name: "control-chars", content: "abc\x01def\n"},
99+
{name: "non-ascii", content: "abcédef\n"},
100+
{name: "oversized", content: strings.Repeat("a", maxMachineIDLen+1) + "\n"},
101+
}
102+
for _, tc := range cases {
103+
t.Run(tc.name, func(t *testing.T) {
104+
path := filepath.Join(dir, "cache-"+tc.name)
105+
if err := os.WriteFile(path, []byte(tc.content), 0o600); err != nil {
106+
t.Fatalf("write: %v", err)
107+
}
108+
if got := readCachedMachineID(path); got != "" {
109+
t.Errorf("readCachedMachineID(%q content=%q) = %q, want miss", tc.name, tc.content, got)
110+
}
111+
})
112+
}
113+
114+
// Positive control: a well-formed single-token cache is accepted, with
115+
// surrounding whitespace trimmed.
116+
path := filepath.Join(dir, "cache-good")
117+
if err := os.WriteFile(path, []byte(" deadbeef42\n"), 0o600); err != nil {
118+
t.Fatalf("write: %v", err)
119+
}
120+
if got := readCachedMachineID(path); got != "deadbeef42" {
121+
t.Errorf("readCachedMachineID(good) = %q, want %q", got, "deadbeef42")
122+
}
123+
}
124+
125+
// TestInitDisabledDoesNotTouchMachineID: a disabled invocation (the
126+
// BD_DISABLE_METRICS / DO_NOT_TRACK path — and every `bd --version`) must not
127+
// compute, read, or write a machine ID at all. The observable half of that
128+
// contract is that no cache file appears.
129+
func TestInitDisabledDoesNotTouchMachineID(t *testing.T) {
130+
home := t.TempDir()
131+
t.Setenv("HOME", home)
132+
if runtime.GOOS == "windows" {
133+
t.Setenv("USERPROFILE", home)
134+
}
135+
136+
if _, err := Init("0.0.0-test", false, ""); err != nil {
137+
t.Fatalf("Init: %v", err)
138+
}
139+
140+
path := filepath.Join(home, ".beads", machineIDCacheName)
141+
if _, err := os.Stat(path); !os.IsNotExist(err) {
142+
t.Errorf("disabled Init created machine-id cache at %s (stat err=%v)", path, err)
143+
}
144+
}
145+
146+
// TestWriteMachineIDCacheAtomicReplace: writing over an existing cache goes
147+
// through temp-file + rename, so no reader can observe a truncated ID and no
148+
// tmp litter survives.
149+
func TestWriteMachineIDCacheAtomicReplace(t *testing.T) {
150+
dir := t.TempDir()
151+
path := filepath.Join(dir, machineIDCacheName)
152+
if err := os.WriteFile(path, []byte("oldvalue\n"), 0o600); err != nil {
153+
t.Fatalf("seed: %v", err)
154+
}
155+
156+
writeMachineIDCache(path, "newvalue")
157+
158+
if got := readCachedMachineID(path); got != "newvalue" {
159+
t.Errorf("after replace, cache = %q, want %q", got, "newvalue")
160+
}
161+
entries, err := os.ReadDir(dir)
162+
if err != nil {
163+
t.Fatalf("readdir: %v", err)
164+
}
165+
for _, e := range entries {
166+
if strings.Contains(e.Name(), ".tmp-") {
167+
t.Errorf("temp file litter left behind: %s", e.Name())
168+
}
169+
}
170+
}

internal/metrics/metrics.go

Lines changed: 21 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,12 @@ const (
1919
EnvDoNotTrack = "DO_NOT_TRACK"
2020

2121
DefaultEndpoint = "https://gastownhall-eventsapi.com/mp/collect"
22+
23+
// queuedEventExt is the extension the eventkit FileEmitter gives queued
24+
// event batches in DataDir. Re-exported here (this file holds the fenced
25+
// eventkit import — see computeMachineID) so spawn.go's pending-events
26+
// check can recognize them.
27+
queuedEventExt = eventkit.DefaultFileExt
2228
)
2329

2430
var (
@@ -50,6 +56,11 @@ func Init(version string, enable bool, metricsEndpoint string) (func(context.Con
5056
}
5157

5258
var emitter eventkit.Emitter = eventkit.NullEmitter{}
59+
// The distinct ID is resolved only on the enabled path: computing it can
60+
// fork a platform probe (see cachedMachineID), and a disabled collector
61+
// never emits an event that would carry it. The placeholder below is inert
62+
// — NullEmitter drops everything and WithDisabled gates emission anyway.
63+
distinctID := "disabled"
5364
if enabled {
5465
dir, err := DataDir()
5566
if err != nil {
@@ -60,10 +71,11 @@ func Init(version string, enable bool, metricsEndpoint string) (func(context.Con
6071
return func(context.Context) {}, fmt.Errorf("metrics: file emitter: %w", err)
6172
}
6273
emitter = fe
74+
distinctID = cachedMachineID(AppName)
6375
}
6476

6577
c := eventkit.NewCollector(emitter,
66-
eventkit.WithDistinctID(eventkit.MachineID(AppName)),
78+
eventkit.WithDistinctID(distinctID),
6779
eventkit.WithAppName(AppName),
6880
eventkit.WithAppVersion(version),
6981
eventkit.WithDisabled(func() bool { return !enabled }),
@@ -79,6 +91,14 @@ func Global() *eventkit.Collector {
7991
return eventkit.Global()
8092
}
8193

94+
// computeMachineID is the raw (slow) platform machine-id probe. It lives here
95+
// rather than in machineid.go because eventkit imports are depguard-fenced to
96+
// this file and flusher.go (.golangci.yml dolt-storage-boundary). Callers want
97+
// cachedMachineID, which pays this cost at most once per machine.
98+
func computeMachineID(appName string) string {
99+
return eventkit.MachineID(appName)
100+
}
101+
82102
// closeFlushTimeout bounds how long CloseAndFlush waits for the collector to
83103
// write queued events before detaching the uploader; it mirrors the budget
84104
// main() has always used for its post-command metrics tail.

0 commit comments

Comments
 (0)