Add acceptance test that fails when a package init() is slow by pietern · Pull Request #7406 · databricks/cli

pietern · 2026-11-09T11:54:43Z

Changes

New acceptance test acceptance/inittime runs $CLI --version with GODEBUG=inittrace=1 and:

logs every package's init() clock time to LOG.inittime, sorted slowest first, on all OSes;
fails on Linux if the total init time exceeds 10 ms (~5 ms today on linux/amd64).

Times are minimums over 5 runs (extended to 20 while the total is over the threshold), so load from parallel tests doesn't cause flakes. The threshold is not enforced on macOS and Windows, where clocks are too coarse or noisy (Windows can quantize to the ~15.6 ms system tick).

Example log (linux/amd64, truncated):

Minimum init() clock time in ms over 5 runs:
 5.32 total
 0.84 github.com/databricks/cli/cmd/air
 0.58 encoding/gob
 0.37 crypto/internal/fips140/v1.0.0-c2097c7c/check
 0.28 github.com/databricks/cli/bundle/config
 0.25 github.com/databricks/cli/libs/structs/structpath
 0.19 github.com/Masterminds/semver/v3
 0.16 crypto/internal/fips140/v1.0.0-c2097c7c/mlkem
 0.15 github.com/databricks/cli/libs/dyn/dynvar
 0.10 github.com/databricks/cli/bundle/internal/validation/generated
 0.10 github.com/databricks/databricks-sdk-go/apierr
 ...

Why

go-runewidth v0.0.27 arrived through a transitive Charm upgrade and added ~20 ms to every invocation, unnoticed until #7391. Checking the total rather than individual packages also catches a slow drip of small regressions, and the log shows which packages contribute.

Tests

Passes locally on linux/amd64.
With --max-ms 3 the check fails: FAIL: package init() takes 5.27 ms in total, over 3 ms.

This pull request and its description were written by Isaac.

denik · 2026-11-09T11:57:23Z

@@ -0,0 +1 @@
+OK: package init times are within threshold


Is it a good idea to record the packages as well (sorted, without timings), to track what's happening in init? or will it add too much churn?

Good idea. Latest has a copy that should be ~stable and not introduce much churn.

Please take a look.

github-actions · 2026-11-09T12:01:58Z

Commit: 990715253 | Workflow run

Regression test report

Selected 1 changed tests (limit=20, 0 not selected)

1 tests: regression=0 unreleased=0 coverage=0 failing=1

test	branch	main (`9605618`)	latest (v1.25.0)
TestAccept/inittime	❌	✅	✅

TestAccept/inittime: branch ❌ | main (9605618) ✅ | latest (v1.25.0) ✅

branch:

acceptance_test.go:1345: 
        	Error Trace:	/home/runner/work/cli/cli/libs/testdiff/testdiff.go:22
        	            				/home/runner/work/cli/cli/acceptance/acceptance_test.go:1345
        	            				/home/runner/work/cli/cli/acceptance/acceptance_test.go:1086
        	            				/home/runner/work/cli/cli/acceptance/acceptance_test.go:642
        	Error:      	Not equal: 
        	            	expected: "OK: total package init() time is within 10 ms\n"
        	            	actual  : "FAIL: package init() takes 12.70 ms in total, over 10 ms; this delays every CLI invocation.\nTo investigate:\n  GODEBUG=inittrace=1 databricks --version 2>&1 | sort -k5 -n -r | head\n  go mod why -m <module>\n\nExit code: 1\n"
        	            	
        	            	Diff:
        	            	--- Expected
        	            	+++ Actual
        	            	@@ -1,2 +1,7 @@
        	            	-OK: total package init() time is within 10 ms
        	            	+FAIL: package init() takes 12.70 ms in total, over 10 ms; this delays every CLI invocation.
        	            	+To investigate:
        	            	+  GODEBUG=inittrace=1 databricks --version 2>&1 | sort -k5 -n -r | head
        	            	+  go mod why -m <module>
        	            	 
        	            	+Exit code: 1
        	            	+
        	Test:       	TestAccept/inittime
        	Messages:   	inittime/output.txt vs /tmp/TestAcceptinittime1336976768/002/output.txt
    acceptance_test.go:1123: 
        LOG.inittime: Minimum init() clock time in ms over 20 runs:
        LOG.inittime: 12.70 total
        LOG.inittime:  0.82 github.com/databricks/cli/cmd/air
        LOG.inittime:  0.81 encoding/gob
        LOG.inittime:  0.54 github.com/databricks/cli/bundle/config
        LOG.inittime:  0.48 github.com/databricks/cli/libs/structs/structpath
        LOG.inittime:  0.44 crypto/internal/fips140/v1.0.0-c2097c7c/check
        LOG.inittime:  0.35 crypto/internal/fips140/v1.0.0-c2097c7c/mlkem
        LOG.inittime:  0.35 github.com/Masterminds/semver/v3
        LOG.inittime:  0.32 github.com/databricks/cli/libs/dyn/dynvar
        LOG.inittime:  0.21 github.com/atotto/clipboard
        LOG.inittime:  0.21 github.com/databricks/databricks-sdk-go/apierr
        LOG.inittime:  0.20 github.com/databricks/cli/bundle/internal/validation/generated
        LOG.inittime:  0.15 github.com/databricks/cli/libs/localenv
        LOG.inittime:  0.13 github.com/BurntSushi/toml/internal
        LOG.inittime:  0.12 github.com/charmbracelet/bubbletea
        LOG.inittime:  0.12 google.golang.org/grpc
        LOG.inittime:  0.10 github.com/databricks/cli/bundle/terraform_dabs_map
        LOG.inittime:  0.10 github.com/databricks/cli/libs/tags
        LOG.inittime:  0.10 golang.org/x/crypto/ssh
        LOG.inittime:  0.09 google.golang.org/protobuf/internal/encoding/json
        LOG.inittime:  0.08 github.com/databricks/cli/libs/telemetry
        LOG.inittime:  0.08 github.com/databricks/cli/bundle/libraries
        LOG.inittime:  0.08 google.golang.org/protobuf/internal/detrand
        LOG.inittime:  0.07 github.com/databricks/databricks-sdk-go/config
        LOG.inittime:  0.07 github.com/databricks/databricks-sdk-go/useragent
        LOG.inittime:  0.07 go.yaml.in/yaml/v3
        LOG.inittime:  0.06 github.com/charmbracelet/x/ansi
        LOG.inittime:  0.06 google.golang.org/grpc/internal/binarylog
        LOG.inittime:  0.06 github.com/databricks/cli/bundle/direct/dresources
        LOG.inittime:  0.06 golang.org/x/net/trace
        LOG.inittime:  0.06 github.com/databricks/cli/libs/template
        LOG.inittime:  0.05 github.com/databricks/cli/cmd/root
        LOG.inittime:  0.05 github.com/google/s2a-go/internal/proto/common_go_proto
        LOG.inittime:  0.05 github.com/databricks/cli/libs/apps/generator
        LOG.inittime:  0.05 github.com/databricks/databricks-sdk-go/service/compute
        LOG.inittime:  0.05 github.com/google/s2a-go/internal/proto/v2/s2a_go_proto
        LOG.inittime:  0.05 github.com/databricks/sdk-go/core/clientinfo
        LOG.inittime:  0.05 gopkg.in/yaml%2ev3
        LOG.inittime:  0.04 github.com/google/s2a-go/internal/proto/s2a_go_proto
        LOG.inittime:  0.04 net/rpc
        LOG.inittime:  0.04 github.com/databricks/cli/libs/genie/agentstream
        LOG.inittime:  0.04 html/template
        LOG.inittime:  0.03 github.com/klauspost/compress/flate
        LOG.inittime:  0.03 github.com/mattn/go-runewidth
        LOG.inittime:  0.03 cloud.google.com/go/auth/credentials/internal/externalaccount
        LOG.inittime:  0.03 golang.org/x/oauth2/google/externalaccount
        LOG.inittime:  0.03 github.com/google/s2a-go/internal/proto/v2/common_go_proto
        LOG.inittime:  0.03 golang.org/x/text/language
        LOG.inittime:  0.03 unicode
        LOG.inittime:  0.03 github.com/dustin/go-humanize
        LOG.inittime:  0.03 golang.org/x/text/cases
        LOG.inittime:  0.03 github.com/databricks/cli/cmd/workspace/repos
        LOG.inittime:  0.02 crypto/internal/fips140/v1.0.0-c2097c7c/sha3
        LOG.inittime:  0.02 golang.org/x/net/http2/hpack
        LOG.inittime:  0.02 net/netip
        LOG.inittime:  0.02 cloud.google.com/go/auth/internal/trustboundary
        LOG.inittime:  0.02 github.com/databricks/cli/cmd/workspace/pipelines
        LOG.inittime:  0.02 encoding/xml
        LOG.inittime:  0.02 github.com/databricks/cli/libs/filer
        LOG.inittime:  0.02 github.com/databricks/cli/libs/git
        LOG.inittime:  0.02 google.golang.org/grpc/binarylog/grpc_binarylog_v1
        LOG.inittime:  0.02 hash/crc32
        LOG.inittime:  0.02 cloud.google.com/go/auth/credentials/idtoken
        LOG.inittime:  0.02 golang.org/x/text/internal/language
        LOG.inittime:  0.02 crypto/internal/fips140/v1.0.0-c2097c7c/edwards25519
        LOG.inittime:  0.02 github.com/databricks/cli/bundle/configsync
        LOG.inittime:  0.02 google.golang.org/protobuf/internal/filedesc
        LOG.inittime:  0.02 github.com/databricks/cli/cmd/workspace/postgres
        LOG.inittime:  0.01 crypto/tls
        LOG.inittime:  0.01 github.com/databricks/cli/libs/apps/prompt
        LOG.inittime:  0.01 os
        LOG.inittime:  0.01 github.com/charmbracelet/x/ansi/parser
        LOG.inittime:  0.01 go.opentelemetry.io/otel/semconv/v1%2e40%2e0
        LOG.inittime:  0.01 golang.org/x/text/internal/language/compact
        LOG.inittime:  0.01 golang.org/x/text/secure/precis
        LOG.inittime:  0.01 gopkg.in/ini%2ev1
        LOG.inittime:  0.01 crypto/x509
        LOG.inittime:  0.01 github.com/databricks/cli/libs/databrickscfg/cfgpickers
        LOG.inittime:  0.01 github.com/databricks/cli/experimental/ssh/internal/client
        LOG.inittime:  0.01 golang.org/x/sys/cpu
        LOG.inittime:  0.01 google.golang.org/grpc/grpclog
        LOG.inittime:  0.01 internal/godebug
        LOG.inittime:  0.01 crypto/internal/fips140/v1.0.0-c2097c7c/sha512
        LOG.inittime:  0.01 crypto/internal/fips140/v1.0.0-c2097c7c/tls13
        LOG.inittime:  0.01 encoding/base32
        LOG.inittime:  0.01 encoding/json/v2
        LOG.inittime:  0.01 github.com/databricks/cli/bundle/config/mutator/resourcemutator
        LOG.inittime:  0.01 github.com/databricks/cli/bundle/deploy/terraform
        LOG.inittime:  0.01 github.com/databricks/cli/libs/patchwheel
        LOG.inittime:  0.01 github.com/jackc/pgx/v5
        LOG.inittime:  0.01 google.golang.org/protobuf/encoding/protowire
        LOG.inittime:  0.01 github.com/databricks/cli/cmd/apps
        LOG.inittime:  0.01 github.com/databricks/cli/cmd/workspace/apps
        LOG.inittime:  0.01 github.com/google/s2a-go/internal/proto/s2a_context_go_proto
        LOG.inittime:  0.01 github.com/googleapis/enterprise-certificate-proxy/client
        LOG.inittime:  0.01 github.com/gorilla/websocket
        LOG.inittime:  0.01 github.com/jackc/pgx/v5/pgtype
        LOG.inittime:  0.01 google.golang.org/protobuf/types/known/anypb
        LOG.inittime:  0.01 vendor/golang.org/x/net/http2/hpack
        LOG.inittime: ... (250 more lines truncated, raise DATABRICKS_CLI_TEST_MAX_LOG to see more)
FAIL

eng-dev-ecosystem-bot · 2026-11-09T12:21:04Z

✅ Integration test report

Commit: 96b9183

Run: 42778602148

	Env	✅pass	🙈skip	Time
✅	aws linux-2core-8gb	271	16	3:55
✅	aws-windows-latest-4core-16gb	273	14	3:12
✅	azure linux-2core-8gb	270	16	3:54
✅	azure-windows-latest-4core-16gb	272	14	2:59
✅	gcp linux-2core-8gb	271	16	3:58
✅	gcp-windows-latest-4core-16gb	273	14	3:15

Top 3 slowest tests (at least 2 minutes):

duration	env	testname
3:09	gcp-windows-latest-4core-16gb	TestAccept
3:05	aws-windows-latest-4core-16gb	TestAccept
2:56	azure-windows-latest-4core-16gb	TestAccept

go-runewidth v0.0.26/v0.0.27 filled a 2 MB table in init(), adding ~20 ms to every CLI invocation. It arrived through a transitive Charm upgrade and went unnoticed (fixed in #7391). The new acceptance test runs `$CLI --version` with GODEBUG=inittrace=1 and fails if any package's init clock exceeds 5 ms. Each package is judged by its minimum over 5 runs, extended up to 20 runs while a check fails, so load from parallel tests does not cause flakes while a real regression fails on every run. It also records a per-package init time budget in out.initlimits.txt, initialized at 4x the measured minimum (at least 0.1 ms; unlisted packages get 0.1 ms). A package that exceeds its budget gets a new one, so several- fold slowdowns show up as a diff in review without flaking on noise. The test runs on linux/amd64 only: Windows inittrace clocks can be quantized to the system tick, and the set of packages with an init differs per architecture. Co-authored-by: Isaac <no-reply@databricks.com>

Co-authored-by: Isaac <no-reply@databricks.com>

denik · 2026-11-10T11:00:25Z

+            f"FAIL: package init() takes {total:.2f} ms in total, over {args.max_ms:g} ms; this delays every CLI invocation."
+        )
+        print("To investigate:")
+        print("  GODEBUG=inittrace=1 databricks --version 2>&1 | sort -k5 -n -r | head")


should we just run it here and record output? For historical runs. Can also drop sort and head.

WDYM for historical runs?

We already capture the timing in the log output.

Can do it in a follow up if we need to.

pietern requested a review from a team as a code owner November 9, 2026 11:54

pietern requested a review from anton-107 November 9, 2026 11:54

denik approved these changes Nov 9, 2026

View reviewed changes

pietern force-pushed the init-time-guard branch from 5467189 to c46add8 Compare November 9, 2026 12:41

pietern force-pushed the init-time-guard branch from c46add8 to 2dc7448 Compare November 9, 2026 12:53

Format init time budgets with a fixed two-decimal width

96b9183

Co-authored-by: Isaac <no-reply@databricks.com>

denik reviewed Nov 10, 2026

View reviewed changes

Comment thread acceptance/inittime/script Resolved

Comment thread acceptance/inittime/out.initlimits.txt Resolved

Comment thread acceptance/inittime/script Resolved

pietern and others added 2 commits November 10, 2026 10:36

Log init times on all OSes and fail on total init time on Linux

d187bdb

Co-authored-by: Isaac <no-reply@databricks.com>

Drop historical reference from inittime script

9907152

Co-authored-by: Isaac <no-reply@databricks.com>

pietern requested a review from denik November 10, 2026 10:44

denik approved these changes Nov 10, 2026

View reviewed changes

pietern added this pull request to the merge queue Nov 10, 2026

Merged via the queue into main with commit 9ff3801 Nov 10, 2026
27 checks passed

pietern deleted the init-time-guard branch November 10, 2026 11:18

denik added the test-only-fix PRs that update failing of flaky tests without changing CLI code. label Nov 11, 2026

denik mentioned this pull request Nov 11, 2026

acceptance/inittime: judge sum of per-package minimum init times #7490

Draft

Navigation Menu

Repository navigation

Add acceptance test that fails when a package init() is slow - #7406

Add acceptance test that fails when a package init() is slow#7406
pietern merged 4 commits into
mainfrom
init-time-guard

pietern commented Nov 9, 2026 •

edited

Loading

Uh oh!

denik Nov 9, 2026

Uh oh!

pietern Nov 9, 2026

Uh oh!

github-actions Bot commented Nov 9, 2026 •

edited

Loading

Uh oh!

eng-dev-ecosystem-bot commented Nov 9, 2026 •

edited

Loading

Uh oh!

Uh oh!

Uh oh!

Uh oh!

denik Nov 10, 2026

Uh oh!

pietern Nov 10, 2026

Uh oh!

pietern Nov 10, 2026

Uh oh!

Uh oh!

Reviewers

Uh oh!

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Conversation

pietern commented Nov 9, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Changes

Why

Tests

Uh oh!

denik Nov 9, 2026

Choose a reason for hiding this comment

Uh oh!

pietern Nov 9, 2026

Choose a reason for hiding this comment

Uh oh!

github-actions Bot commented Nov 9, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Regression test report

Uh oh!

eng-dev-ecosystem-bot commented Nov 9, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

✅ Integration test report

Uh oh!

Uh oh!

Uh oh!

Uh oh!

denik Nov 10, 2026

Choose a reason for hiding this comment

Uh oh!

pietern Nov 10, 2026

Choose a reason for hiding this comment

Uh oh!

pietern Nov 10, 2026

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Reviewers

Uh oh!

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

pietern commented Nov 9, 2026 •

edited

Loading

github-actions Bot commented Nov 9, 2026 •

edited

Loading

eng-dev-ecosystem-bot commented Nov 9, 2026 •

edited

Loading