Skip to content

Commit a0b1cae

Browse files
mikeland73claude
andauthored
perf(telemetry): reuse opened project, cache device ID, throttle uploads (#3021)
## Summary Implements items 2–4 of `specs/perf-improvements.md`, which together remove fixed telemetry costs from every command (including every `devbox global shellenv` and every direnv reload). **2. Don't re-open the project after every command** - The telemetry post-run hook returns immediately when telemetry is disabled (`DO_NOT_TRACK`, or builds without keys). Before, it still ran `devbox.Open`. - `devbox.Open` now records the project it returned (`devbox.LastOpened()`), and telemetry reads packages and the nixpkgs commit from that project instead of opening it again (which re-parsed devbox.json/devbox.lock and reloaded plugins). - That also gets rid of the `--config` bug: the old code looked the flag up on the root command, so it never found it. - Behavior change: commands that never open a project (e.g. `version`, `search`) now report no packages. Before, they reported whatever project was in the cwd. **3. Cache the device ID** - The salted `machineid.ProtectedID` is written to `$XDG_STATE_HOME/devbox/telemetry/device-id` and read from there on later runs. This skips `ioreg` on macOS (~20ms). **4. Throttle `devbox upload-telemetry`** - The uploader is spawned at most once every 30 minutes. In between, events stay buffered on disk as they do today. It still runs right away when an error was reported (so Sentry errors arrive promptly and the Sentry transport's 30-event buffer isn't exceeded) or when 50+ events are buffered. - The last upload time goes in `$XDG_STATE_HOME/devbox/telemetry/last-upload` before the child starts, so commands running at the same time don't all spawn one. A timestamp in the future is ignored. - Sentry events now set `Timestamp` when they're created, since they may be uploaded later. ## Testing - `go test ./internal/telemetry/ ./internal/boxcli/midcobra/`: new tests for the device ID cache (hit and miss) and `shouldUpload` (never uploaded, recent, stale, future timestamp, error, threshold). Updated the `getPackagesAndCommitHash` test. - `golangci-lint run` on the changed packages: 0 issues. - Timing on macOS, with binaries built with fake telemetry keys and network blocked by a proxy, averaged over 20 runs in this repo: | Command | main | this PR | |---|---|---| | `devbox version` | 106.6ms | 85.8ms | | `devbox list` | 106.1ms | 86.3ms | Most of the remaining cost is `nix --version` (~75ms), which `newTrackMessage` calls through `nix.Version()`. Item 1 (a separate PR) caches it. 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
1 parent 30b2b60 commit a0b1cae

6 files changed

Lines changed: 233 additions & 56 deletions

File tree

‎internal/boxcli/midcobra/telemetry.go‎

Lines changed: 12 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -12,7 +12,6 @@ import (
1212
"github.com/spf13/pflag"
1313
"go.jetify.com/devbox/internal/boxcli/featureflag"
1414
"go.jetify.com/devbox/internal/devbox"
15-
"go.jetify.com/devbox/internal/devbox/devopt"
1615
"go.jetify.com/devbox/internal/envir"
1716
"go.jetify.com/devbox/internal/telemetry"
1817
)
@@ -40,6 +39,10 @@ func (m *telemetryMiddleware) postRun(cmd *cobra.Command, args []string, runErr
4039
defer trace.StartRegion(cmd.Context(), "telemetryPostRun").End()
4140
defer telemetry.Stop()
4241

42+
if !telemetry.Enabled() {
43+
return
44+
}
45+
4346
meta := telemetry.Metadata{
4447
FeatureFlags: featureflag.All(),
4548
CloudRegion: os.Getenv(envir.DevboxRegion),
@@ -54,7 +57,7 @@ func (m *telemetryMiddleware) postRun(cmd *cobra.Command, args []string, runErr
5457
meta.Command = subcmd.CommandPath()
5558
meta.CommandFlags = flags
5659

57-
meta.Packages, meta.NixpkgsHash = getPackagesAndCommitHash(subcmd)
60+
meta.Packages, meta.NixpkgsHash = getPackagesAndCommitHash()
5861
meta.InShell = envir.IsDevboxShellEnabled()
5962
meta.InBrowser = envir.IsInBrowser()
6063
meta.InCloud = envir.IsDevboxCloud()
@@ -81,28 +84,15 @@ func getSubcommand(cmd *cobra.Command, args []string) (subcmd *cobra.Command, fl
8184
return subcmd, flags, err
8285
}
8386

84-
func getPackagesAndCommitHash(c *cobra.Command) ([]string, string) {
85-
configFlag := c.Flag("config")
86-
// for shell, run, and add command, path can be set via --config
87-
// if --config is not set, default to current directory which is ""
88-
// the only exception is the init command, for the path can be set with args
89-
// since after running init there will be no packages set in devbox.json
90-
// we can safely ignore this case.
91-
var path string
92-
if configFlag != nil {
93-
path = configFlag.Value.String()
94-
}
95-
96-
box, err := devbox.Open(&devopt.Opts{
97-
Dir: path,
98-
Stderr: os.Stderr,
99-
IgnoreWarnings: true,
100-
SkipVersionCheck: true,
101-
})
102-
if err != nil {
87+
// getPackagesAndCommitHash returns the packages and nixpkgs commit of the
88+
// project that the command opened. It reuses the already-opened project instead
89+
// of opening it again, which would re-parse the config and reload plugins.
90+
// Commands that don't open a project report no packages.
91+
func getPackagesAndCommitHash() ([]string, string) {
92+
box := devbox.LastOpened()
93+
if box == nil {
10394
return []string{}, ""
10495
}
105-
10696
return box.AllPackageNamesIncludingRemovedTriggerPackages(),
10797
box.Lockfile().Stdenv().Rev
10898
}

‎internal/boxcli/midcobra/telemetry_test.go‎

Lines changed: 3 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -3,7 +3,6 @@ package midcobra
33
import (
44
"testing"
55

6-
"github.com/spf13/cobra"
76
"go.jetify.com/devbox/internal/devbox"
87
"go.jetify.com/devbox/internal/devbox/devopt"
98
)
@@ -17,30 +16,17 @@ func TestGetPackagesAndCommitHash(t *testing.T) {
1716
box, err := devbox.Open(&devopt.Opts{
1817
Dir: dir,
1918
})
20-
// Create a mock cobra command
21-
cmd := &cobra.Command{
22-
Use: "test",
23-
Run: func(cmd *cobra.Command, args []string) {},
24-
}
25-
26-
// Add a mock flag to the command
27-
cmd.Flags().String("config", "", "config file")
28-
if err := cmd.Flags().Set("config", dir); err != nil {
29-
t.Errorf("Expected no error, got %s", err)
19+
if err != nil {
20+
t.Fatalf("Expected no error, got %s", err)
3021
}
3122

32-
// Call the function with the mock command
33-
packages, commitHash := getPackagesAndCommitHash(cmd)
23+
packages, commitHash := getPackagesAndCommitHash()
3424

3525
// Check if the returned packages and commitHash are as expected
3626
if len(packages) != 0 {
3727
t.Errorf("Expected no packages, got %d", len(packages))
3828
}
3929

40-
if err != nil {
41-
t.Errorf("Expected no error, got %s", err)
42-
}
43-
4430
if commitHash != box.Lockfile().Stdenv().Rev {
4531
t.Errorf("Expected commitHash %s, got %s", box.Lockfile().Stdenv().Rev, commitHash)
4632
}

‎internal/devbox/devbox.go‎

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@ import (
1818
"slices"
1919
"strconv"
2020
"strings"
21+
"sync/atomic"
2122
"time"
2223

2324
"github.com/briandowns/spinner"
@@ -76,6 +77,16 @@ type Devbox struct {
7677

7778
var legacyPackagesWarningHasBeenShown = false
7879

80+
// lastOpened is the project most recently returned by Open. Telemetry reads it
81+
// after a command runs so that it doesn't have to open the project again.
82+
var lastOpened atomic.Pointer[Devbox]
83+
84+
// LastOpened returns the project most recently returned by Open, or nil if
85+
// this process hasn't opened one.
86+
func LastOpened() *Devbox {
87+
return lastOpened.Load()
88+
}
89+
7990
func InitConfig(dir string) error {
8091
_, err := devconfig.Init(dir)
8192
return err
@@ -185,6 +196,7 @@ func Open(opts *devopt.Opts) (*Devbox, error) {
185196
)
186197
}
187198

199+
lastOpened.Store(box)
188200
return box, nil
189201
}
190202

‎internal/telemetry/telemetry.go‎

Lines changed: 98 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -51,7 +51,20 @@ var (
5151
// procStartTime records the start time of the current process.
5252
procStartTime = time.Now()
5353
needsFlush atomic.Bool
54-
started bool
54+
// uploadNow skips upload throttling. It's set when an error is buffered
55+
// so that errors are reported promptly.
56+
uploadNow atomic.Bool
57+
started bool
58+
)
59+
60+
const (
61+
// uploadInterval is the minimum time between spawning upload processes.
62+
// Events are buffered on disk in the meantime.
63+
uploadInterval = 30 * time.Minute
64+
65+
// uploadThreshold is the number of buffered events that triggers an
66+
// upload before uploadInterval has passed.
67+
uploadThreshold = 50
5568
)
5669

5770
// Start enables telemetry for the current program.
@@ -60,12 +73,33 @@ func Start() {
6073
return
6174
}
6275

63-
const deviceSalt = "64ee464f-9450-4b14-8d9c-014c0012ac1a"
64-
deviceID, _ = machineid.ProtectedID(deviceSalt)
65-
76+
deviceID = loadDeviceID()
6677
started = true
6778
}
6879

80+
// Enabled reports whether telemetry was started for the current program.
81+
func Enabled() bool {
82+
return started
83+
}
84+
85+
// loadDeviceID returns the device ID cached in the state dir, computing and
86+
// caching it if needed. Computing it is slow on macOS because it runs ioreg.
87+
func loadDeviceID() string {
88+
if data, err := os.ReadFile(deviceIDFile); err == nil {
89+
if id := strings.TrimSpace(string(data)); id != "" {
90+
return id
91+
}
92+
}
93+
94+
const deviceSalt = "64ee464f-9450-4b14-8d9c-014c0012ac1a"
95+
id, err := machineid.ProtectedID(deviceSalt)
96+
if err != nil {
97+
return ""
98+
}
99+
_ = writeStateFile(deviceIDFile, []byte(id))
100+
return id
101+
}
102+
69103
func userID() string {
70104
if username := os.Getenv(envir.GitHubUsername); username != "" {
71105
const uidSalt = "d6134cd5-347d-4b7c-a2d0-295c0f677948"
@@ -78,18 +112,58 @@ func userID() string {
78112
return ""
79113
}
80114

81-
// Stop stops gathering telemetry and flushes buffered events to disk.
115+
// Stop stops gathering telemetry and, if it's time for an upload, uploads
116+
// buffered events in a separate process.
82117
func Stop() {
83118
if !started || !needsFlush.Load() {
84119
return
85120
}
121+
started = false
122+
if !shouldUpload() {
123+
return
124+
}
125+
126+
// Record the upload time before spawning so that other commands running
127+
// at the same time don't also spawn an uploader.
128+
_ = writeStateFile(lastUploadFile, []byte(strconv.FormatInt(time.Now().Unix(), 10)))
86129

87130
// Report errors in a separate process so we don't block exiting.
88131
exe, err := os.Executable()
89132
if err == nil {
90133
_ = exec.Command(exe, "upload-telemetry").Start()
91134
}
92-
started = false
135+
}
136+
137+
// shouldUpload reports whether buffered events should be uploaded now. Uploads
138+
// happen at most once per uploadInterval unless an error was reported or
139+
// there are at least uploadThreshold buffered events.
140+
func shouldUpload() bool {
141+
if uploadNow.Load() {
142+
return true
143+
}
144+
data, err := os.ReadFile(lastUploadFile)
145+
if err != nil {
146+
return true
147+
}
148+
lastUpload, err := strconv.ParseInt(strings.TrimSpace(string(data)), 10, 64)
149+
if err != nil {
150+
return true
151+
}
152+
// A last upload time in the future means the clock changed, so don't
153+
// trust it.
154+
if age := time.Since(time.Unix(lastUpload, 0)); age < 0 || age >= uploadInterval {
155+
return true
156+
}
157+
return bufferedEventCount() >= uploadThreshold
158+
}
159+
160+
func bufferedEventCount() int {
161+
count := 0
162+
for _, dir := range []string{segmentBufferDir, sentryBufferDir} {
163+
entries, _ := os.ReadDir(dir)
164+
count += len(entries)
165+
}
166+
return count
93167
}
94168

95169
func Event(e EventName, meta Metadata) {
@@ -132,7 +206,10 @@ func Error(err error, meta Metadata) {
132206
nixVersion := cmp.Or(nix.Version(), "unknown")
133207

134208
event := &sentry.Event{
135-
EventID: sentry.EventID(ExecutionID),
209+
EventID: sentry.EventID(ExecutionID),
210+
// Uploads are throttled, so record when the error happened rather
211+
// than when it's uploaded.
212+
Timestamp: time.Now(),
136213
Level: sentry.LevelError,
137214
User: sentry.User{ID: deviceID},
138215
Exception: newSentryException(redact.Error(errToLog)),
@@ -174,6 +251,7 @@ func Error(err error, meta Metadata) {
174251
event.User.ID = uid
175252
}
176253
bufferSentryEvent(event)
254+
uploadNow.Store(true)
177255

178256
msgID, msg := commandEvent(meta)
179257
msg.Properties["failed"] = true
@@ -258,6 +336,9 @@ func (m *Metadata) pkgContext() map[string]any {
258336
var (
259337
sentryBufferDir = xdg.StateSubpath(filepath.FromSlash("devbox/sentry"))
260338
segmentBufferDir = xdg.StateSubpath(filepath.FromSlash("devbox/segment"))
339+
340+
deviceIDFile = xdg.StateSubpath(filepath.FromSlash("devbox/telemetry/device-id"))
341+
lastUploadFile = xdg.StateSubpath(filepath.FromSlash("devbox/telemetry/last-upload"))
261342
)
262343

263344
func Upload() {
@@ -326,18 +407,23 @@ func bufferEvent(file string, event any) {
326407
if err != nil {
327408
return
328409
}
410+
if writeStateFile(file, data) == nil {
411+
needsFlush.Store(true)
412+
}
413+
}
329414

330-
err = os.WriteFile(file, data, 0o600)
415+
// writeStateFile writes data to a file in the XDG state dir, creating its
416+
// parent directory if needed.
417+
func writeStateFile(file string, data []byte) error {
418+
err := os.WriteFile(file, data, 0o600)
331419
if errors.Is(err, fs.ErrNotExist) {
332420
// XDG specifies perms 0700.
333421
if err := os.MkdirAll(filepath.Dir(file), 0o700); err != nil {
334-
return
422+
return err
335423
}
336424
err = os.WriteFile(file, data, 0o600)
337425
}
338-
if err == nil {
339-
needsFlush.Store(true)
340-
}
426+
return err
341427
}
342428

343429
func newEventID() string {

0 commit comments

Comments
 (0)