From ea216f8e732311d237e5d884a11d4459d9f5841f Mon Sep 17 00:00:00 2001 From: Maycon Santos Date: Mon, 14 Sep 2026 19:42:02 +0200 Subject: [PATCH] [management] Speed up test store setup and summarize the unit test run (#7518) Management / Unit (amd64, mysql) hit the 20 minute go test budget on #7516. The package was not hung: each of the 133 test store creations in management/server paid about 1.6s on MySQL for CREATE DATABASE, the pre-migrations, a 40-table AutoMigrate and the post-migrations, which puts the package at 10 minutes on a healthy runner and over the budget on a slow one. The migration now runs once per test binary into a template database and each test database is cloned from it, with CREATE DATABASE ... TEMPLATE on Postgres and a replay of SHOW CREATE TABLE on MySQL. The MySQL test container also drops the binary log, doublewrite buffer and per-commit redo fsync. Two goroutine leaks in the test helpers are fixed. tools/gotestsummary turns the go test -json stream into a readable log, and the Management unit and integration jobs now pipe through it, so a timeout names the tests still running. On MySQL, management/server went from 10m16s to 6m36s. --- .github/workflows/golang-test-linux.yml | 39 ++- management/server/account_test.go | 10 +- management/server/store/sql_store.go | 69 ++-- management/server/store/store.go | 253 ++++++++++++++- management/server/testutil/store.go | 12 + tools/gotestsummary/main.go | 402 ++++++++++++++++++++++++ tools/gotestsummary/main_test.go | 180 +++++++++++ 7 files changed, 923 insertions(+), 42 deletions(-) create mode 100644 tools/gotestsummary/main.go create mode 100644 tools/gotestsummary/main_test.go diff --git a/.github/workflows/golang-test-linux.yml b/.github/workflows/golang-test-linux.yml index 9e3caa17a..449eb14fa 100644 --- a/.github/workflows/golang-test-linux.yml +++ b/.github/workflows/golang-test-linux.yml @@ -514,14 +514,32 @@ jobs: if: matrix.store == 'mysql' run: docker pull mlsmaycon/warmed-mysql:8 + # The -json stream goes through tools/gotestsummary so the log shows one + # line per test, the output of failed tests, the head of a timeout panic + # with the still-running tests, and the slowest tests per package. - name: Test + shell: bash run: | + set -o pipefail CGO_ENABLED=1 GOARCH=${{ matrix.arch }} \ NETBIRD_STORE_ENGINE=${{ matrix.store }} \ CI=true \ - go test -tags=devcert -coverprofile=coverage.txt \ + go test -json -tags=devcert -coverprofile=coverage.txt \ -exec "sudo --preserve-env=CI,NETBIRD_STORE_ENGINE" \ - -timeout 20m ./management/... ./shared/management/... + -timeout 20m ./management/... ./shared/management/... \ + | tee management-test-events.jsonl \ + | go run ./tools/gotestsummary + + # The summary trims long outputs; the raw stream keeps every line for + # the failures that need it. A green run has no use for it. + - name: Upload raw test events + if: failure() + uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a #v7.0.1 + with: + name: management-unit-test-events-${{ matrix.store }} + path: management-test-events.jsonl + if-no-files-found: ignore + retention-days: 14 - name: Upload coverage reports to Codecov if: matrix.arch == 'amd64' @@ -771,12 +789,27 @@ jobs: - name: check git status run: git --no-pager diff --exit-code + # Same summary as the unit job: a timeout here names the tests still + # running instead of ending in a goroutine dump. - name: Test + shell: bash run: | + set -o pipefail CGO_ENABLED=1 GOARCH=${{ matrix.arch }} \ NETBIRD_STORE_ENGINE=${{ matrix.store }} \ CI=true \ - mage integrationtest:all -gotestflags="-coverprofile=coverage.txt" + mage integrationtest:all -gotestflags="-json -coverprofile=coverage.txt" \ + | tee management-integration-test-events.jsonl \ + | go run ./tools/gotestsummary + + - name: Upload raw test events + if: failure() + uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a #v7.0.1 + with: + name: management-integration-test-events-${{ matrix.store }} + path: management-integration-test-events.jsonl + if-no-files-found: ignore + retention-days: 14 - name: Upload coverage reports to Codecov if: matrix.arch == 'amd64' diff --git a/management/server/account_test.go b/management/server/account_test.go index bd7bf2d97..c63782ca8 100644 --- a/management/server/account_test.go +++ b/management/server/account_test.go @@ -3516,7 +3516,13 @@ func buildTestManager(t testing.TB, store store.Store, nmdataStore *networkmapdb eventStore := &activity.InMemoryEventStore{} - metrics, err := telemetry.NewDefaultAppMetrics(context.Background()) + // Everything built here watches this context; cancelling it on cleanup stops + // the metrics flushers, caches and controllers instead of leaking them for + // the rest of the package run. + ctx, cancel := context.WithCancel(context.Background()) + t.Cleanup(cancel) + + metrics, err := telemetry.NewDefaultAppMetrics(ctx) if err != nil { return nil, nil, err } @@ -3535,8 +3541,6 @@ func buildTestManager(t testing.TB, store store.Store, nmdataStore *networkmapdb Return(nil). AnyTimes() - ctx := context.Background() - cacheStore, err := cache.NewStore(ctx, 100*time.Millisecond, 300*time.Millisecond, 100) if err != nil { return nil, nil, err diff --git a/management/server/store/sql_store.go b/management/server/store/sql_store.go index 08ec45395..d2d197a03 100644 --- a/management/server/store/sql_store.go +++ b/management/server/store/sql_store.go @@ -3154,7 +3154,12 @@ func NewMysqlStore(ctx context.Context, dsn string, metrics telemetry.AppMetrics return nil, err } - return NewSqlStore(ctx, db, types.MysqlStoreEngine, metrics, skipMigration) + store, err := NewSqlStore(ctx, db, types.MysqlStoreEngine, metrics, skipMigration) + if err != nil { + closeGormDB(db) + return nil, err + } + return store, nil } func getGormConfig() *gorm.Config { @@ -3213,23 +3218,20 @@ func NewSqliteStoreFromFileStore(ctx context.Context, fileStore *FileStore, data // NewPostgresqlStoreFromSqlStore restores a store from SqlStore and stores Postgres DB. func NewPostgresqlStoreFromSqlStore(ctx context.Context, sqliteStore *SqlStore, dsn string, metrics telemetry.AppMetrics) (*SqlStore, error) { - store, err := NewPostgresqlStoreForTests(ctx, dsn, metrics, false) + return newPostgresqlStoreFromSqlStore(ctx, sqliteStore, dsn, metrics, false) +} + +func newPostgresqlStoreFromSqlStore(ctx context.Context, sqliteStore *SqlStore, dsn string, metrics telemetry.AppMetrics, skipMigration bool) (*SqlStore, error) { + store, err := NewPostgresqlStoreForTests(ctx, dsn, metrics, skipMigration) if err != nil { return nil, err } - err = store.SaveInstallationID(ctx, sqliteStore.GetInstallationID()) - if err != nil { + if err := seedFromSqliteStore(ctx, store, sqliteStore); err != nil { + closeStore(ctx, store) return nil, err } - for _, account := range sqliteStore.GetAllAccounts(ctx) { - err := store.SaveAccount(ctx, account) - if err != nil { - return nil, err - } - } - return store, nil } @@ -3241,11 +3243,14 @@ func NewPostgresqlStoreForTests(ctx context.Context, dsn string, metrics telemet } pool, err := connectToPgDbForTests(context.Background(), dsn) if err != nil { + closeGormDB(db) return nil, err } store, err := NewSqlStore(ctx, db, types.PostgresStoreEngine, metrics, skipMigration) if err != nil { + // Release the sessions, or the caller cannot drop the database. pool.Close() + closeGormDB(db) return nil, err } store.pool = pool @@ -3279,22 +3284,42 @@ func connectToPgDbForTests(ctx context.Context, dsn string) (*pgxpool.Pool, erro // NewMysqlStoreFromSqlStore restores a store from SqlStore and stores MySQL DB. func NewMysqlStoreFromSqlStore(ctx context.Context, sqliteStore *SqlStore, dsn string, metrics telemetry.AppMetrics) (*SqlStore, error) { - store, err := NewMysqlStore(ctx, dsn, metrics, false) - if err != nil { - return nil, err - } + return newMysqlStoreFromSqlStore(ctx, sqliteStore, dsn, metrics, false) +} - err = store.SaveInstallationID(ctx, sqliteStore.GetInstallationID()) - if err != nil { - return nil, err +// seedFromSqliteStore copies the installation ID and the accounts of the +// sqlite seed store into a freshly created engine store. +func seedFromSqliteStore(ctx context.Context, store, sqliteStore *SqlStore) error { + if err := store.SaveInstallationID(ctx, sqliteStore.GetInstallationID()); err != nil { + return err } - for _, account := range sqliteStore.GetAllAccounts(ctx) { - err := store.SaveAccount(ctx, account) - if err != nil { - return nil, err + if err := store.SaveAccount(ctx, account); err != nil { + return err } } + return nil +} + +// closeStore releases a store that is not handed to the caller, so a failed +// seed does not leak its connection and pool. +func closeStore(ctx context.Context, store *SqlStore) { + store.Close(ctx) + if store.pool != nil { + store.pool.Close() + } +} + +func newMysqlStoreFromSqlStore(ctx context.Context, sqliteStore *SqlStore, dsn string, metrics telemetry.AppMetrics, skipMigration bool) (*SqlStore, error) { + store, err := NewMysqlStore(ctx, dsn, metrics, skipMigration) + if err != nil { + return nil, err + } + + if err := seedFromSqliteStore(ctx, store, sqliteStore); err != nil { + closeStore(ctx, store) + return nil, err + } return store, nil } diff --git a/management/server/store/store.go b/management/server/store/store.go index 6886536b9..7a92de0a6 100644 --- a/management/server/store/store.go +++ b/management/server/store/store.go @@ -4,6 +4,7 @@ package store import ( "context" + "database/sql" "errors" "fmt" "net" @@ -15,6 +16,7 @@ import ( "runtime" "slices" "strings" + "sync" "time" "github.com/google/uuid" @@ -732,6 +734,7 @@ func NewTestStoreFromSQL(ctx context.Context, filename string, dataDir string) ( time.Sleep(100 * time.Millisecond) } } + store.Close(ctx) return nil, nil, fmt.Errorf("failed to create test store after %d attempts: %v", maxRetries, err) } @@ -758,14 +761,15 @@ func addAllGroupToAccount(ctx context.Context, store Store) error { return nil } -func getSqlStoreEngine(ctx context.Context, store *SqlStore, kind types.Engine) (Store, func(), error) { +func getSqlStoreEngine(ctx context.Context, sqliteStore *SqlStore, kind types.Engine) (Store, func(), error) { + store := sqliteStore var cleanup func() var err error switch kind { case types.PostgresStoreEngine: - store, cleanup, err = newReusedPostgresStore(ctx, store, kind) + store, cleanup, err = newReusedPostgresStore(ctx, sqliteStore, kind) case types.MysqlStoreEngine: - store, cleanup, err = newReusedMysqlStore(ctx, store, kind) + store, cleanup, err = newReusedMysqlStore(ctx, sqliteStore, kind) default: cleanup = func() { // sqlite doesn't need to be cleaned up @@ -781,6 +785,11 @@ func getSqlStoreEngine(ctx context.Context, store *SqlStore, kind types.Engine) if store.pool != nil { store.pool.Close() } + if store != sqliteStore { + // The sqlite store only seeded the engine under test; without this + // every test leaks its connection and the opener goroutines. + sqliteStore.Close(ctx) + } } return store, closeConnection, nil @@ -805,19 +814,23 @@ func newReusedPostgresStore(ctx context.Context, store *SqlStore, kind types.Eng return nil, nil, fmt.Errorf("failed to open postgres connection: %v", err) } - dsn, cleanup, err := createRandomDB(dsn, db, kind) - - sqlDB, _ := db.DB() - if sqlDB != nil { - sqlDB.Close() + template, err := postgresSchemaTemplate(ctx, dsn, db) + if err != nil { + closeGormDB(db) + return nil, nil, err } + dsn, cleanup, err := createRandomDB(dsn, db, kind, template) + + closeGormDB(db) + if err != nil { return nil, nil, err } - store, err = NewPostgresqlStoreFromSqlStore(ctx, store, dsn, nil) + store, err = newPostgresqlStoreFromSqlStore(ctx, store, dsn, nil, true) if err != nil { + cleanup() return nil, nil, err } @@ -850,7 +863,13 @@ func newReusedMysqlStore(ctx context.Context, store *SqlStore, kind types.Engine sqlDB.SetMaxOpenConns(1) sqlDB.SetMaxIdleConns(1) - dsn, cleanup, err := createRandomDB(dsn, db, kind) + tableDDL, err := mysqlSchemaTemplate(ctx, dsn, db) + if err != nil { + sqlDB.Close() + return nil, nil, err + } + + dsn, cleanup, err := createRandomDB(dsn, db, kind, "") sqlDB.Close() @@ -858,14 +877,200 @@ func newReusedMysqlStore(ctx context.Context, store *SqlStore, kind types.Engine return nil, nil, err } - store, err = NewMysqlStoreFromSqlStore(ctx, store, dsn, nil) + if err := cloneMysqlSchema(ctx, dsn, tableDDL); err != nil { + cleanup() + return nil, nil, err + } + + store, err = newMysqlStoreFromSqlStore(ctx, store, dsn, nil, true) if err != nil { + cleanup() return nil, nil, err } return store, cleanup, nil } +// schemaTemplates remembers, per engine and server, a database that went +// through the full migration once in this process. Every later test database +// is cloned from it, so a test pays for CREATE DATABASE and a schema copy +// instead of the 40-table AutoMigrate plus every pre and post migration, which +// is what made each MySQL test store cost well over a second in CI. +var ( + schemaTemplatesMu sync.Mutex + schemaTemplates = map[string]*schemaTemplate{} +) + +type schemaTemplate struct { + dbName string + // tableDDL holds the CREATE TABLE statements of the template. MySQL has no + // server-side database template, so the schema is replayed statement by + // statement into each test database. + tableDDL []string +} + +func schemaTemplateKey(engine types.Engine, dsn string) string { + return string(engine) + "|" + dsn +} + +func newTestDBName(prefix string) string { + return fmt.Sprintf("%s_%s", prefix, strings.ReplaceAll(uuid.New().String(), "-", "_")) +} + +// postgresSchemaTemplate returns the name of a fully migrated database that +// CREATE DATABASE ... TEMPLATE can copy, creating it on first use. +func postgresSchemaTemplate(ctx context.Context, baseDSN string, admin *gorm.DB) (string, error) { + schemaTemplatesMu.Lock() + defer schemaTemplatesMu.Unlock() + + key := schemaTemplateKey(types.PostgresStoreEngine, baseDSN) + if tpl, ok := schemaTemplates[key]; ok { + return tpl.dbName, nil + } + + name := newTestDBName("test_template") + if err := admin.Exec(fmt.Sprintf("CREATE DATABASE %s", name)).Error; err != nil { + return "", fmt.Errorf("create postgres template database: %w", err) + } + + tplStore, err := NewPostgresqlStoreForTests(ctx, replaceDBName(baseDSN, name), nil, false) + if err != nil { + dropDatabase(admin, name) + return "", fmt.Errorf("migrate postgres template database: %w", err) + } + // TEMPLATE refuses a source that still has sessions, so release both handles + // before the first clone. + tplStore.Close(ctx) + if tplStore.pool != nil { + tplStore.pool.Close() + } + + schemaTemplates[key] = &schemaTemplate{dbName: name} + return name, nil +} + +// mysqlSchemaTemplate returns the CREATE TABLE statements of a fully migrated +// database, migrating one on first use. +func mysqlSchemaTemplate(ctx context.Context, baseDSN string, admin *gorm.DB) ([]string, error) { + schemaTemplatesMu.Lock() + defer schemaTemplatesMu.Unlock() + + key := schemaTemplateKey(types.MysqlStoreEngine, baseDSN) + if tpl, ok := schemaTemplates[key]; ok { + return tpl.tableDDL, nil + } + + name := newTestDBName("test_template") + if err := admin.Exec(fmt.Sprintf("CREATE DATABASE %s", name)).Error; err != nil { + return nil, fmt.Errorf("create mysql template database: %w", err) + } + + tplStore, err := NewMysqlStore(ctx, replaceDBName(baseDSN, name), nil, false) + if err != nil { + dropDatabase(admin, name) + return nil, fmt.Errorf("migrate mysql template database: %w", err) + } + tableDDL, err := mysqlTableDDL(ctx, tplStore.db, name) + tplStore.Close(ctx) + if err != nil { + dropDatabase(admin, name) + return nil, err + } + + schemaTemplates[key] = &schemaTemplate{dbName: name, tableDDL: tableDDL} + return tableDDL, nil +} + +func mysqlTableDDL(ctx context.Context, db *gorm.DB, dbName string) ([]string, error) { + sqlDB, err := db.DB() + if err != nil { + return nil, err + } + + tables, err := mysqlTableNames(ctx, sqlDB, dbName) + if err != nil { + return nil, err + } + + tableDDL := make([]string, 0, len(tables)) + for _, table := range tables { + var name, createStmt string + row := sqlDB.QueryRowContext(ctx, fmt.Sprintf("SHOW CREATE TABLE %s.%s", dbName, table)) + if err := row.Scan(&name, &createStmt); err != nil { + return nil, fmt.Errorf("read create statement of %s: %w", table, err) + } + tableDDL = append(tableDDL, createStmt) + } + return tableDDL, nil +} + +func mysqlTableNames(ctx context.Context, sqlDB *sql.DB, dbName string) ([]string, error) { + rows, err := sqlDB.QueryContext(ctx, fmt.Sprintf("SHOW TABLES FROM %s", dbName)) + if err != nil { + return nil, fmt.Errorf("list template tables: %w", err) + } + defer rows.Close() + + var tables []string + for rows.Next() { + var table string + if err := rows.Scan(&table); err != nil { + return nil, fmt.Errorf("scan template table name: %w", err) + } + tables = append(tables, table) + } + if err := rows.Err(); err != nil { + return nil, fmt.Errorf("list template tables: %w", err) + } + return tables, nil +} + +// cloneMysqlSchema replays the template's CREATE TABLE statements into the +// database the DSN points at. +func cloneMysqlSchema(ctx context.Context, dsn string, tableDDL []string) error { + db, err := gorm.Open(mysql.Open(dsn+"?charset=utf8&parseTime=True&loc=Local"), getGormConfig()) + if err != nil { + return fmt.Errorf("connect to test database: %w", err) + } + sqlDB, err := db.DB() + if err != nil { + return err + } + defer sqlDB.Close() + + // The statements come out of SHOW TABLES in name order, not dependency + // order, and their foreign keys reference tables of the session's default + // database. Pin a single connection so the session setting below covers + // every statement, and connect straight to the new database so unqualified + // references land there. + sqlDB.SetMaxOpenConns(1) + if _, err := sqlDB.ExecContext(ctx, "SET FOREIGN_KEY_CHECKS = 0"); err != nil { + return fmt.Errorf("disable foreign key checks: %w", err) + } + for _, stmt := range tableDDL { + if _, err := sqlDB.ExecContext(ctx, stmt); err != nil { + return fmt.Errorf("replay table definition: %w", err) + } + } + return nil +} + +// dropDatabase removes a template that never became usable, so a failed setup +// does not leave it behind on a shared server. The server may still be tearing +// down the sessions the failed migration held, so the drop retries while +// Postgres reports the database as in use. +func dropDatabase(admin *gorm.DB, name string) { + if err := execWithTemplateRetry(admin, fmt.Sprintf("DROP DATABASE IF EXISTS %s", name)); err != nil { + log.Warnf("failed to drop template database %s: %v", name, err) + } +} + +func closeGormDB(db *gorm.DB) { + if sqlDB, _ := db.DB(); sqlDB != nil { + sqlDB.Close() + } +} + func openDBWithRetry(dsn string, engine types.Engine, maxRetries int) (*gorm.DB, error) { var db *gorm.DB var err error @@ -891,10 +1096,16 @@ func openDBWithRetry(dsn string, engine types.Engine, maxRetries int) (*gorm.DB, return nil, err } -func createRandomDB(dsn string, db *gorm.DB, engine types.Engine) (string, func(), error) { - dbName := fmt.Sprintf("test_db_%s", strings.ReplaceAll(uuid.New().String(), "-", "_")) +// createRandomDB creates a uniquely named database for one test. On postgres a +// non-empty template is copied server-side with CREATE DATABASE ... TEMPLATE. +func createRandomDB(dsn string, db *gorm.DB, engine types.Engine, template string) (string, func(), error) { + dbName := newTestDBName("test_db") - if err := db.Exec(fmt.Sprintf("CREATE DATABASE %s", dbName)).Error; err != nil { + createStmt := fmt.Sprintf("CREATE DATABASE %s", dbName) + if template != "" && engine == types.PostgresStoreEngine { + createStmt = fmt.Sprintf("CREATE DATABASE %s TEMPLATE %s", dbName, template) + } + if err := execWithTemplateRetry(db, createStmt); err != nil { return "", nil, fmt.Errorf("failed to create database: %v", err) } @@ -960,6 +1171,20 @@ func createRandomDB(dsn string, db *gorm.DB, engine types.Engine) (string, func( return replaceDBName(dsn, dbName), cleanup, nil } +// execWithTemplateRetry runs a statement, retrying briefly when postgres still +// sees the template's just-closed sessions and refuses to copy it. +func execWithTemplateRetry(db *gorm.DB, stmt string) error { + var err error + for attempt := 0; attempt < 20; attempt++ { + err = db.Exec(stmt).Error + if err == nil || !strings.Contains(err.Error(), "is being accessed by other users") { + return err + } + time.Sleep(100 * time.Millisecond) + } + return err +} + func replaceDBName(dsn, newDBName string) string { re := regexp.MustCompile(`(?P
[:/@])(?P[^/?]+)(?P\?|$)`)
 	return re.ReplaceAllString(dsn, `${pre}`+newDBName+`${post}`)
diff --git a/management/server/testutil/store.go b/management/server/testutil/store.go
index 07699e2c3..3854c1173 100644
--- a/management/server/testutil/store.go
+++ b/management/server/testutil/store.go
@@ -37,6 +37,18 @@ func CreateMysqlTestContainer() (func(), string, error) {
 		mysql.WithDatabase("testing"),
 		mysql.WithUsername("root"),
 		mysql.WithPassword("testing"),
+		// Every test creates and drops a database with about 40 tables, so with
+		// the server defaults the run is dominated by durability work: each
+		// CREATE TABLE fsyncs the redo log, the binary log and the doublewrite
+		// buffer. None of it protects anything in a container that is discarded
+		// after the run. Tables stay in per-table files on purpose: in the shared
+		// system tablespace the cost of every CREATE and DROP grew with the number
+		// of databases the run had already created.
+		testcontainers.WithCmd("mysqld",
+			"--innodb-flush-log-at-trx-commit=0",
+			"--innodb-doublewrite=OFF",
+			"--skip-log-bin",
+		),
 		testcontainers.WithWaitStrategy(
 			wait.ForLog("/usr/sbin/mysqld: ready for connections").
 				WithOccurrence(1).WithStartupTimeout(15*time.Second).WithPollInterval(100*time.Millisecond),
diff --git a/tools/gotestsummary/main.go b/tools/gotestsummary/main.go
new file mode 100644
index 000000000..2a5487fc6
--- /dev/null
+++ b/tools/gotestsummary/main.go
@@ -0,0 +1,402 @@
+// Package main turns a `go test -json` stream into a readable CI log.
+//
+// It prints one line per top-level test as it finishes, the captured output of
+// every failed test, the head of a package-level panic (which is where Go
+// reports "test timed out" and the list of still-running tests), and ends with
+// the per-package durations and the slowest tests. The exit code is always zero
+// unless the input cannot be read; the `go test` exit code is what CI should act
+// on, so run the two with `set -o pipefail`.
+//
+// Usage:
+//
+//	go test -json ./... | go run ./tools/gotestsummary
+//	go run ./tools/gotestsummary -slowest 60 test-output.jsonl
+package main
+
+import (
+	"bufio"
+	"encoding/json"
+	"flag"
+	"fmt"
+	"io"
+	"os"
+	"sort"
+	"strings"
+	"time"
+)
+
+const (
+	modulePrefix = "github.com/netbirdio/netbird/"
+
+	// failedTestOutputLines bounds how much captured output a single failed
+	// test may print, so one noisy failure cannot flood the job log.
+	failedTestOutputLines = 200
+	// panicHeadLines is enough for the "panic: test timed out" header, the
+	// "running tests:" list, and the first few goroutines of the dump.
+	panicHeadLines = 150
+	// bufferedOutputLines bounds the per-test output kept in memory while the
+	// test runs; only the tail is kept once the cap is reached.
+	bufferedOutputLines = 400
+)
+
+type event struct {
+	Action  string  `json:"Action"`
+	Package string  `json:"Package"`
+	Test    string  `json:"Test"`
+	Output  string  `json:"Output"`
+	Elapsed float64 `json:"Elapsed"`
+	// ImportPath is set instead of Package on build events. It carries a
+	// " [pkg.test]" suffix naming the test binary the package was compiled
+	// for, and the same package can be built for several binaries at once.
+	ImportPath string `json:"ImportPath"`
+	// FailedBuild names the ImportPath whose build failure made the package
+	// fail; go test reports the package fail event after the build-fail one.
+	FailedBuild string `json:"FailedBuild"`
+}
+
+type testKey struct {
+	pkg, name string
+}
+
+type testResult struct {
+	pkg, name string
+	action    string
+	elapsed   time.Duration
+}
+
+type packageResult struct {
+	pkg     string
+	action  string
+	elapsed time.Duration
+}
+
+type summarizer struct {
+	out io.Writer
+
+	output  map[testKey][]string
+	dropped map[testKey]int
+	// pkgOutput keeps what a package printed outside any test, which is where
+	// compiler diagnostics of a failed build end up.
+	pkgOutput map[string][]string
+	// failedBuilds holds the ImportPaths whose build failed and has not been
+	// reported through a package fail event yet.
+	failedBuilds map[string]bool
+	tests        []testResult
+	packages     []packageResult
+	// panics holds the head of a panic per package. Package streams interleave
+	// in a go test -json run, so one package's dump must not swallow another's
+	// output.
+	panics map[string][]string
+}
+
+func newSummarizer(out io.Writer) *summarizer {
+	return &summarizer{
+		out:          out,
+		output:       make(map[testKey][]string),
+		dropped:      make(map[testKey]int),
+		pkgOutput:    make(map[string][]string),
+		failedBuilds: make(map[string]bool),
+		panics:       make(map[string][]string),
+	}
+}
+
+func main() {
+	slowest := flag.Int("slowest", 40, "number of slowest top-level tests to list")
+	flag.Parse()
+
+	if err := run(flag.Arg(0), *slowest); err != nil {
+		fmt.Fprintln(os.Stderr, err)
+		os.Exit(1)
+	}
+}
+
+func run(path string, slowest int) error {
+	in := os.Stdin
+	if path != "" {
+		f, err := os.Open(path)
+		if err != nil {
+			return fmt.Errorf("open %s: %w", path, err)
+		}
+		defer f.Close()
+		in = f
+	}
+
+	s := newSummarizer(os.Stdout)
+	if err := s.consume(in); err != nil {
+		return fmt.Errorf("read input: %w", err)
+	}
+	s.printSummary(slowest)
+	return nil
+}
+
+func (s *summarizer) consume(r io.Reader) error {
+	scanner := bufio.NewScanner(r)
+	scanner.Buffer(make([]byte, 0, 1024*1024), 16*1024*1024)
+	for scanner.Scan() {
+		line := scanner.Bytes()
+		var ev event
+		if err := json.Unmarshal(line, &ev); err != nil {
+			// Build errors and other non-JSON lines are passed through untouched.
+			fmt.Fprintln(s.out, string(line))
+			continue
+		}
+		s.handle(ev)
+	}
+	return scanner.Err()
+}
+
+func (s *summarizer) handle(ev event) {
+	if ev.Package == "" {
+		// Keep the full path as the key so concurrent builds of one package for
+		// different test binaries do not share, and delete, each other's state.
+		ev.Package = ev.ImportPath
+	}
+	key := testKey{pkg: ev.Package, name: ev.Test}
+	switch ev.Action {
+	case "run":
+		// Register the test even before it prints anything, so a test that
+		// hangs silently still shows up as unfinished.
+		if ev.Test != "" {
+			if _, ok := s.output[key]; !ok {
+				s.output[key] = []string{}
+			}
+		}
+	case "output":
+		s.handleOutput(key, strings.TrimRight(ev.Output, "\n"))
+	case "build-output":
+		// Compiler output may carry several lines per event and is never test
+		// output, so it skips the panic detection.
+		for _, line := range strings.Split(strings.TrimRight(ev.Output, "\n"), "\n") {
+			s.pkgOutput[key.pkg] = appendBounded(s.pkgOutput[key.pkg], line)
+		}
+	case "build-fail":
+		// The package fail event that follows carries FailedBuild and reports
+		// the compiler output; this only remembers the build in case it never
+		// comes.
+		s.failedBuilds[key.pkg] = true
+	case "pass", "fail", "skip":
+		if ev.Test == "" {
+			s.handlePackageResult(ev)
+			return
+		}
+		s.handleTestResult(key, ev)
+	}
+}
+
+func (s *summarizer) handleOutput(key testKey, line string) {
+	if strings.HasPrefix(line, "panic: ") || strings.HasPrefix(line, "fatal error: ") {
+		if _, ok := s.panics[key.pkg]; !ok {
+			s.panics[key.pkg] = []string{}
+		}
+	}
+	if head, ok := s.panics[key.pkg]; ok {
+		// The goroutine dump that follows a panic is kept in the panic head only;
+		// letting it flood the per-test buffers would hide the test's own output.
+		if len(head) < panicHeadLines {
+			s.panics[key.pkg] = append(head, line)
+		}
+		return
+	}
+
+	if key.name == "" {
+		s.pkgOutput[key.pkg] = appendBounded(s.pkgOutput[key.pkg], line)
+		return
+	}
+	if len(s.output[key]) >= bufferedOutputLines {
+		s.dropped[key]++
+	}
+	s.output[key] = appendBounded(s.output[key], line)
+}
+
+// appendBounded keeps the most recent bufferedOutputLines lines.
+func appendBounded(buf []string, line string) []string {
+	if len(buf) >= bufferedOutputLines {
+		buf = buf[1:]
+	}
+	return append(buf, line)
+}
+
+func (s *summarizer) handleTestResult(key testKey, ev event) {
+	elapsed := time.Duration(ev.Elapsed * float64(time.Second))
+	s.tests = append(s.tests, testResult{
+		pkg:     ev.Package,
+		name:    ev.Test,
+		action:  ev.Action,
+		elapsed: elapsed,
+	})
+
+	if !strings.Contains(ev.Test, "/") || ev.Action == "fail" {
+		fmt.Fprintf(s.out, "--- %s: %s.%s (%s)\n", strings.ToUpper(ev.Action), shortPkg(ev.Package), ev.Test, elapsed.Round(time.Millisecond))
+	}
+	if ev.Action == "fail" {
+		s.printTestOutput(key)
+	}
+	delete(s.output, key)
+	delete(s.dropped, key)
+}
+
+func (s *summarizer) printTestOutput(key testKey) {
+	lines := s.output[key]
+	if len(lines) == 0 {
+		return
+	}
+	skipped := s.dropped[key]
+	if len(lines) > failedTestOutputLines {
+		skipped += len(lines) - failedTestOutputLines
+		lines = lines[len(lines)-failedTestOutputLines:]
+	}
+	if skipped > 0 {
+		fmt.Fprintf(s.out, "    ... %d earlier output lines omitted ...\n", skipped)
+	}
+	for _, l := range lines {
+		fmt.Fprintf(s.out, "    %s\n", l)
+	}
+}
+
+func (s *summarizer) handlePackageResult(ev event) {
+	elapsed := time.Duration(ev.Elapsed * float64(time.Second))
+	s.packages = append(s.packages, packageResult{pkg: ev.Package, action: ev.Action, elapsed: elapsed})
+
+	label := "ok  "
+	switch ev.Action {
+	case "fail", "build-fail":
+		label = "FAIL"
+	case "skip":
+		label = "skip"
+	}
+	fmt.Fprintf(s.out, "%s %s %s\n", label, shortPkg(ev.Package), elapsed.Round(time.Millisecond))
+
+	if label == "FAIL" {
+		if ev.FailedBuild != "" {
+			// Several test binaries can share one failed dependency, so its
+			// output stays available for the next package that names it.
+			s.printPackageOutput(ev.FailedBuild, "build output of %s")
+			delete(s.failedBuilds, ev.FailedBuild)
+		}
+		s.printPackageOutput(ev.Package, "output of %s outside tests")
+		s.printUnfinished(ev.Package)
+		s.printPanicHead(ev.Package)
+	}
+	delete(s.pkgOutput, ev.Package)
+	delete(s.panics, ev.Package)
+}
+
+// printUnclaimedBuildFailures reports the failed builds no package fail event
+// accounted for, so a compiler error never disappears from the log.
+func (s *summarizer) printUnclaimedBuildFailures() {
+	var builds []string
+	for b := range s.failedBuilds {
+		builds = append(builds, b)
+	}
+	sort.Strings(builds)
+	for _, b := range builds {
+		fmt.Fprintf(s.out, "FAIL %s [build failed]\n", shortPkg(b))
+		s.printPackageOutput(b, "build output of %s")
+	}
+}
+
+// printPackageOutput shows what a failed package printed outside its tests,
+// or the compiler errors of a failed build, under the given header.
+func (s *summarizer) printPackageOutput(pkg, header string) {
+	lines := s.pkgOutput[pkg]
+	if len(lines) == 0 {
+		return
+	}
+	if len(lines) > failedTestOutputLines {
+		lines = lines[len(lines)-failedTestOutputLines:]
+	}
+	fmt.Fprintf(s.out, "\n==== "+header+" ====\n", shortPkg(pkg))
+	for _, l := range lines {
+		fmt.Fprintf(s.out, "    %s\n", l)
+	}
+}
+
+func (s *summarizer) printPanicHead(pkg string) {
+	head := s.panics[pkg]
+	if len(head) == 0 {
+		return
+	}
+	fmt.Fprintf(s.out, "\n==== panic in %s (first %d lines) ====\n", shortPkg(pkg), len(head))
+	for _, l := range head {
+		fmt.Fprintln(s.out, l)
+	}
+	fmt.Fprintln(s.out, "==== end of panic head ====")
+	fmt.Fprintln(s.out)
+}
+
+// printUnfinished names the tests of a failed package that never reported a
+// result, which is what a timeout leaves behind, and shows their last output.
+func (s *summarizer) printUnfinished(pkg string) {
+	var keys []testKey
+	for key := range s.output {
+		if key.pkg == pkg && key.name != "" {
+			keys = append(keys, key)
+		}
+	}
+	if len(keys) == 0 {
+		return
+	}
+	sort.Slice(keys, func(i, j int) bool { return keys[i].name < keys[j].name })
+	fmt.Fprintf(s.out, "\n==== tests in %s that did not finish (%d) ====\n", shortPkg(pkg), len(keys))
+	for _, key := range keys {
+		fmt.Fprintf(s.out, "--- UNFINISHED: %s.%s\n", shortPkg(key.pkg), key.name)
+		s.printTestOutput(key)
+		delete(s.output, key)
+		delete(s.dropped, key)
+	}
+}
+
+func (s *summarizer) printSummary(slowest int) {
+	s.printUnclaimedBuildFailures()
+
+	fmt.Fprintln(s.out)
+	fmt.Fprintln(s.out, "==== package durations ====")
+	sort.Slice(s.packages, func(i, j int) bool { return s.packages[i].elapsed > s.packages[j].elapsed })
+	for _, p := range s.packages {
+		fmt.Fprintf(s.out, "%9s  %-4s  %s\n", p.elapsed.Round(time.Millisecond), p.action, shortPkg(p.pkg))
+	}
+
+	var failed []testResult
+	for _, t := range s.tests {
+		if t.action == "fail" {
+			failed = append(failed, t)
+		}
+	}
+	if len(failed) > 0 {
+		fmt.Fprintln(s.out)
+		fmt.Fprintf(s.out, "==== failed tests (%d) ====\n", len(failed))
+		for _, t := range failed {
+			fmt.Fprintf(s.out, "%9s  %s.%s\n", t.elapsed.Round(time.Millisecond), shortPkg(t.pkg), t.name)
+		}
+	}
+
+	s.printSlowest("slowest top-level tests", slowest, func(t testResult) bool { return !strings.Contains(t.name, "/") })
+	s.printSlowest("slowest subtests", slowest/2, func(t testResult) bool { return strings.Contains(t.name, "/") })
+}
+
+func (s *summarizer) printSlowest(title string, limit int, keep func(testResult) bool) {
+	var tests []testResult
+	for _, t := range s.tests {
+		if keep(t) {
+			tests = append(tests, t)
+		}
+	}
+	if len(tests) == 0 || limit <= 0 {
+		return
+	}
+	sort.Slice(tests, func(i, j int) bool { return tests[i].elapsed > tests[j].elapsed })
+	if len(tests) > limit {
+		tests = tests[:limit]
+	}
+
+	fmt.Fprintln(s.out)
+	fmt.Fprintf(s.out, "==== %s (%d) ====\n", title, len(tests))
+	for _, t := range tests {
+		fmt.Fprintf(s.out, "%9s  %-4s  %s.%s\n", t.elapsed.Round(time.Millisecond), t.action, shortPkg(t.pkg), t.name)
+	}
+}
+
+func shortPkg(pkg string) string {
+	pkg, _, _ = strings.Cut(pkg, " [")
+	return strings.TrimPrefix(pkg, modulePrefix)
+}
diff --git a/tools/gotestsummary/main_test.go b/tools/gotestsummary/main_test.go
new file mode 100644
index 000000000..d5b51e132
--- /dev/null
+++ b/tools/gotestsummary/main_test.go
@@ -0,0 +1,180 @@
+package main
+
+import (
+	"bytes"
+	"strings"
+	"testing"
+)
+
+func feed(t *testing.T, events string) string {
+	t.Helper()
+	var out bytes.Buffer
+	s := newSummarizer(&out)
+	if err := s.consume(strings.NewReader(events)); err != nil {
+		t.Fatalf("consume: %v", err)
+	}
+	s.printSummary(10)
+	return out.String()
+}
+
+func TestTimeoutReportsUnfinishedTestsAndPanicHead(t *testing.T) {
+	events := `
+{"Action":"run","Package":"a","Test":"TestHang"}
+{"Action":"output","Package":"a","Test":"TestHang","Output":"=== RUN   TestHang\n"}
+{"Action":"run","Package":"a","Test":"TestSilent"}
+{"Action":"output","Package":"a","Test":"TestHang","Output":"panic: test timed out after 1s\n"}
+{"Action":"output","Package":"a","Test":"TestHang","Output":"\trunning tests:\n"}
+{"Action":"output","Package":"a","Test":"TestHang","Output":"\t\tTestHang (1s)\n"}
+{"Action":"output","Package":"a","Test":"TestHang","Output":"goroutine 7 [running]:\n"}
+{"Action":"fail","Package":"a","Elapsed":1.0}
+`
+	got := feed(t, events)
+	for _, want := range []string{
+		"--- UNFINISHED: a.TestHang",
+		"--- UNFINISHED: a.TestSilent",
+		"==== panic in a (first 4 lines) ====",
+		"\t\tTestHang (1s)",
+		"    === RUN   TestHang",
+	} {
+		if !strings.Contains(got, want) {
+			t.Errorf("output lacks %q:\n%s", want, got)
+		}
+	}
+	if strings.Contains(got, "    goroutine 7 [running]:") {
+		t.Errorf("goroutine dump leaked into the test's own output:\n%s", got)
+	}
+}
+
+func TestPanicInOnePackageKeepsOtherPackageOutput(t *testing.T) {
+	events := `
+{"Action":"run","Package":"a","Test":"TestHang"}
+{"Action":"output","Package":"a","Test":"TestHang","Output":"panic: test timed out after 1s\n"}
+{"Action":"run","Package":"b","Test":"TestOther"}
+{"Action":"output","Package":"b","Test":"TestOther","Output":"    other_test.go:9: expected 1, got 2\n"}
+{"Action":"output","Package":"a","Test":"TestHang","Output":"goroutine 7 [running]:\n"}
+{"Action":"fail","Package":"b","Test":"TestOther","Elapsed":0.01}
+{"Action":"fail","Package":"b","Elapsed":0.02}
+{"Action":"fail","Package":"a","Elapsed":1.0}
+`
+	got := feed(t, events)
+	if !strings.Contains(got, "    other_test.go:9: expected 1, got 2") {
+		t.Errorf("other package's output was swallowed by the panic head:\n%s", got)
+	}
+	if strings.Contains(got, "panic in b") {
+		t.Errorf("panic head attributed to the wrong package:\n%s", got)
+	}
+	if !strings.Contains(got, "==== panic in a (first 2 lines) ====") {
+		t.Errorf("panic head missing for package a:\n%s", got)
+	}
+}
+
+func TestBuildFailureShowsCompilerOutput(t *testing.T) {
+	// The event sequence go test emits for a build failure: the build events
+	// name the test binary, then the package itself fails with FailedBuild.
+	events := `
+{"Action":"build-output","ImportPath":"a [a.test]","Output":"# a [a.test]\na_test.go:7:2: undefined: nope\na_test.go:9:2: undefined: nope2\n"}
+{"Action":"build-fail","ImportPath":"a [a.test]"}
+{"Action":"start","Package":"a"}
+{"Action":"output","Package":"a","Output":"FAIL\ta [build failed]\n"}
+{"Action":"fail","Package":"a","Elapsed":0,"FailedBuild":"a [a.test]"}
+`
+	got := feed(t, events)
+	for _, want := range []string{
+		"==== build output of a ====",
+		"    a_test.go:7:2: undefined: nope\n    a_test.go:9:2: undefined: nope2",
+		"FAIL\ta [build failed]",
+	} {
+		if !strings.Contains(got, want) {
+			t.Errorf("output lacks %q:\n%s", want, got)
+		}
+	}
+	if n := strings.Count(got, "FAIL a 0s"); n != 1 {
+		t.Errorf("expected one FAIL line for the package, got %d:\n%s", n, got)
+	}
+	if n := strings.Count(got, "undefined: nope2"); n != 1 {
+		t.Errorf("expected the compiler output once, got %d:\n%s", n, got)
+	}
+}
+
+func TestFailedDependencyOutputIsShownForEveryImporter(t *testing.T) {
+	events := `
+{"Action":"build-output","ImportPath":"m/x","Output":"# m/x\nx.go:3:11: undefined: y\n"}
+{"Action":"build-fail","ImportPath":"m/x"}
+{"Action":"start","Package":"m/a"}
+{"Action":"output","Package":"m/a","Output":"FAIL\tm/a [build failed]\n"}
+{"Action":"fail","Package":"m/a","Elapsed":0,"FailedBuild":"m/x"}
+{"Action":"start","Package":"m/b"}
+{"Action":"output","Package":"m/b","Output":"FAIL\tm/b [build failed]\n"}
+{"Action":"fail","Package":"m/b","Elapsed":0,"FailedBuild":"m/x"}
+`
+	got := feed(t, events)
+	if n := strings.Count(got, "x.go:3:11: undefined: y"); n != 2 {
+		t.Errorf("expected the dependency's compiler output under both packages, got %d:\n%s", n, got)
+	}
+	if strings.Contains(got, "FAIL m/x") {
+		t.Errorf("the dependency must not be reported as a package of its own:\n%s", got)
+	}
+}
+
+func TestBuildFailureWithoutPackageEventIsStillReported(t *testing.T) {
+	events := `
+{"Action":"build-output","ImportPath":"a [a.test]","Output":"a_test.go:7:2: undefined: nope\n"}
+{"Action":"build-fail","ImportPath":"a [a.test]"}
+`
+	got := feed(t, events)
+	for _, want := range []string{"FAIL a [build failed]", "==== build output of a ====", "undefined: nope"} {
+		if !strings.Contains(got, want) {
+			t.Errorf("output lacks %q:\n%s", want, got)
+		}
+	}
+}
+
+func TestCompilerPanicIsBuildOutputNotTestPanic(t *testing.T) {
+	events := `
+{"Action":"build-output","ImportPath":"a [a.test]","Output":"# a [a.test]\npanic: internal compiler error\n\ngoroutine 1 [running]:\n"}
+{"Action":"build-fail","ImportPath":"a [a.test]"}
+{"Action":"start","Package":"a"}
+{"Action":"output","Package":"a","Output":"FAIL\ta [build failed]\n"}
+{"Action":"fail","Package":"a","Elapsed":0,"FailedBuild":"a [a.test]"}
+`
+	got := feed(t, events)
+	if !strings.Contains(got, "==== build output of a ====\n    # a [a.test]\n    panic: internal compiler error") {
+		t.Errorf("compiler diagnostic missing from the build output block:\n%s", got)
+	}
+	if strings.Contains(got, "==== panic in") {
+		t.Errorf("compiler output must not be reported as a test panic:\n%s", got)
+	}
+}
+
+func TestBuildVariantsOfOnePackageKeepSeparateOutput(t *testing.T) {
+	events := `
+{"Action":"build-output","ImportPath":"a [a.test]","Output":"a.go:1:1: broken for a.test\n"}
+{"Action":"build-output","ImportPath":"a [b.test]","Output":"a.go:1:1: broken for b.test\n"}
+{"Action":"build-fail","ImportPath":"a [a.test]"}
+{"Action":"build-fail","ImportPath":"a [b.test]"}
+{"Action":"start","Package":"a"}
+{"Action":"fail","Package":"a","Elapsed":0,"FailedBuild":"a [a.test]"}
+{"Action":"start","Package":"b"}
+{"Action":"fail","Package":"b","Elapsed":0,"FailedBuild":"a [b.test]"}
+`
+	got := feed(t, events)
+	if strings.Count(got, "==== build output of a ====") != 2 {
+		t.Errorf("expected one output block per build variant:\n%s", got)
+	}
+	for _, want := range []string{"broken for a.test", "broken for b.test"} {
+		if strings.Count(got, want) != 1 {
+			t.Errorf("expected %q exactly once:\n%s", want, got)
+		}
+	}
+}
+
+func TestPassingPackageOutputIsNotPrinted(t *testing.T) {
+	events := `
+{"Action":"output","Package":"a","Output":"level=info msg=\"noise between tests\"\n"}
+{"Action":"pass","Package":"a","Elapsed":0.5}
+`
+	got := feed(t, events)
+	if strings.Contains(got, "noise between tests") {
+		t.Errorf("package output of a passing package should stay quiet:\n%s", got)
+	}
+}