mirror of
https://github.com/coder/coder.git
synced 2026-10-16 06:37:58 +08:00
ci: fail the test process with a heap profile when memory passes a per-runner limit (#30487)
test: add memory guard and heap profiles for CI timeouts Add a memory guard to `cli`, `agent`, and `enterprise/cli` to diagnose recurring macOS `test-go-pg` timeouts. Recent logs show runaway memory usage and heavy swapping, but the allocation source remains unknown. - Check Go runtime memory once per second, with per-process CI limits of 5 GiB on macOS and 6 GiB on Linux and Windows. Disabled when `CODER_TEST_MEMORY_LIMIT_MIB` is unset. - On exceeding the limit, save a heap profile, attempt a second profile after forced GC with a five-second wait limit, then panic with memory usage, profile paths, and all goroutine stacks. - Upload heap profiles from unsuccessful CI jobs on every OS, retaining them for seven days. - Test guard lifecycle, environment parsing, panic diagnostics, profile validity, and post-GC allocation attribution. Validate with race tests, vet, lint, and a manual macOS test. Refs https://linear.app/codercom/issue/PLAT-251/flake-test-go-pg-macos-job-timeoutcancelled Refs https://github.com/coder/internal/issues/1365
This commit is contained in:
@@ -167,6 +167,12 @@ runs:
|
||||
RACE_DETECTION: ${{ inputs.race-detection }}
|
||||
GOTESTSUM_JSONFILE_INPUT: ${{ inputs.gotestsum-json-file }}
|
||||
EMBEDDED_PG_PATH: ${{ steps.postgres-path.outputs.path || inputs.embedded-pg-path }}
|
||||
# This limit assumes make's -tags=testsmallbatch. See testutil.MemoryLimitEnv.
|
||||
# macOS gets a lower limit: the runner has 17 GiB and cli.test peaks
|
||||
# at about 3.5 GiB there, so 5120 MiB keeps a 1.4x margin while
|
||||
# tripping before a runaway allocation reaches the compressor and
|
||||
# swap. See coder/internal#1365.
|
||||
CODER_TEST_MEMORY_LIMIT_MIB: ${{ runner.os == 'macOS' && '5120' || '6144' }}
|
||||
TS_DEBUG_DISCO: "true"
|
||||
TS_DEBUG_DERP: "true"
|
||||
LC_CTYPE: "en_US.UTF-8"
|
||||
@@ -249,6 +255,15 @@ runs:
|
||||
if-no-files-found: ignore
|
||||
retention-days: 7
|
||||
|
||||
- name: Upload heap profiles
|
||||
if: always() && !success()
|
||||
uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a # v7.0.1
|
||||
with:
|
||||
name: heap-profiles-${{ github.job }}-${{ runner.os }}
|
||||
path: ${{ runner.temp }}/heap-*.pprof
|
||||
if-no-files-found: ignore
|
||||
retention-days: 7
|
||||
|
||||
- name: Upload PostgreSQL diagnostics (Windows)
|
||||
if: always() && runner.os == 'Windows' && !success()
|
||||
uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a # v7.0.1
|
||||
|
||||
@@ -72,6 +72,8 @@ func TestMain(m *testing.M) {
|
||||
}
|
||||
// Report multi-second pauses of the whole process, see coder/internal#1365.
|
||||
testutil.StartStallDetector(5 * time.Second)
|
||||
// Fail with a heap profile before a runaway allocation pushes the runner into swap.
|
||||
testutil.StartMemoryGuardFromEnv()
|
||||
goleak.VerifyTestMain(m, testutil.GoleakOptions...)
|
||||
}
|
||||
|
||||
|
||||
@@ -34,6 +34,8 @@ import (
|
||||
func TestMain(m *testing.M) {
|
||||
// Report multi-second pauses of the whole process, see coder/internal#1365.
|
||||
testutil.StartStallDetector(5 * time.Second)
|
||||
// Fail with a heap profile before a runaway allocation pushes the runner into swap.
|
||||
testutil.StartMemoryGuardFromEnv()
|
||||
if runtime.GOOS == "windows" {
|
||||
// Don't run goleak on windows tests, they're super flaky right now.
|
||||
// See: https://github.com/coder/coder/issues/8954
|
||||
|
||||
@@ -11,5 +11,7 @@ import (
|
||||
func TestMain(m *testing.M) {
|
||||
// Report multi-second pauses of the whole process, see coder/internal#1365.
|
||||
testutil.StartStallDetector(5 * time.Second)
|
||||
// Fail with a heap profile before a runaway allocation pushes the runner into swap.
|
||||
testutil.StartMemoryGuardFromEnv()
|
||||
os.Exit(m.Run())
|
||||
}
|
||||
|
||||
@@ -200,6 +200,7 @@ require (
|
||||
github.com/google/go-cmp v0.7.0
|
||||
github.com/google/go-github/v43 v43.0.1-0.20220414155304-00e42332e405
|
||||
github.com/google/go-github/v61 v61.0.0
|
||||
github.com/google/pprof v0.0.0-20250607225305-033d6d78b36a
|
||||
github.com/google/uuid v1.6.0
|
||||
github.com/hashicorp/go-multierror v1.1.1
|
||||
github.com/hashicorp/go-reap v0.0.0-20170704170343-bf58d8a43e7b
|
||||
@@ -373,7 +374,6 @@ require (
|
||||
github.com/google/btree v1.1.3 // indirect
|
||||
github.com/google/go-querystring v1.2.0 // indirect
|
||||
github.com/google/nftables v0.2.0 // indirect
|
||||
github.com/google/pprof v0.0.0-20250607225305-033d6d78b36a // indirect
|
||||
github.com/google/s2a-go v0.1.11 // indirect
|
||||
github.com/google/shlex v0.0.0-20191202100458-e7afc7fbc510 // indirect
|
||||
github.com/googleapis/enterprise-certificate-proxy v0.3.22 // indirect
|
||||
|
||||
@@ -0,0 +1,7 @@
|
||||
package testutil
|
||||
|
||||
var (
|
||||
WatchMemory = watchMemory
|
||||
WriteHeapProfile = writeHeapProfile
|
||||
WriteHeapProfiles = writeHeapProfiles
|
||||
)
|
||||
@@ -23,4 +23,6 @@ var GoleakOptions []goleak.Option = []goleak.Option{
|
||||
goleak.IgnoreAnyFunction("github.com/Microsoft/go-winio.ioCompletionProcessor"),
|
||||
// The stall detector started from TestMain runs until the process exits.
|
||||
goleak.IgnoreTopFunction("github.com/coder/coder/v2/testutil.StartStallDetector.func1"),
|
||||
// Same for the memory guard.
|
||||
goleak.IgnoreTopFunction("github.com/coder/coder/v2/testutil.watchMemory.func1"),
|
||||
}
|
||||
|
||||
@@ -0,0 +1,159 @@
|
||||
package testutil
|
||||
|
||||
import (
|
||||
"fmt"
|
||||
"os"
|
||||
"path/filepath"
|
||||
"runtime"
|
||||
"runtime/debug"
|
||||
"runtime/metrics"
|
||||
"runtime/pprof"
|
||||
"strconv"
|
||||
"time"
|
||||
|
||||
"golang.org/x/xerrors"
|
||||
)
|
||||
|
||||
// MemoryLimitEnv is the environment variable StartMemoryGuardFromEnv reads
|
||||
// the limit from, in MiB. CI sets it per runner in test-go-pg/action.yaml:
|
||||
// 5120 on macOS, whose 17 GiB runner must trip before the compressor and
|
||||
// swap absorb a runaway allocation, and 6144 elsewhere. The values assume
|
||||
// -tags=testsmallbatch, which keeps wireguard-go's memory use low; without
|
||||
// that tag, a plain `go test` run can activate the guard with no real leak.
|
||||
const MemoryLimitEnv = "CODER_TEST_MEMORY_LIMIT_MIB"
|
||||
|
||||
// heapProfileGCTimeout bounds the forced collection that precedes the
|
||||
// second heap profile. A runaway test keeps allocating while the
|
||||
// collection runs, and the process must fail before the runner starts
|
||||
// swapping, so the second profile is skipped when the collection takes
|
||||
// longer than this.
|
||||
const heapProfileGCTimeout = 5 * time.Second
|
||||
|
||||
// StartMemoryGuardFromEnv is like StartMemoryGuard, but reads the limit
|
||||
// from MemoryLimitEnv and does nothing when it is unset. Call the
|
||||
// returned function to stop it.
|
||||
func StartMemoryGuardFromEnv() func() {
|
||||
val := os.Getenv(MemoryLimitEnv)
|
||||
if val == "" {
|
||||
return func() {}
|
||||
}
|
||||
mib, err := strconv.ParseUint(val, 10, 64)
|
||||
if err != nil {
|
||||
panic(fmt.Sprintf("%s=%q is not a valid MiB count: %v", MemoryLimitEnv, val, err))
|
||||
}
|
||||
return StartMemoryGuard(mib << 20)
|
||||
}
|
||||
|
||||
// StartMemoryGuard ends the test process once its memory use passes
|
||||
// limit. It writes heap profiles first, then panics with a dump of
|
||||
// every goroutine the way a test timeout does. Without it a runaway
|
||||
// allocation pushes the runner into swap and the process dies before
|
||||
// the test timeout can produce a dump, see coder/internal#1365. Call
|
||||
// the returned function to stop it.
|
||||
func StartMemoryGuard(limit uint64) func() {
|
||||
return watchMemory(limit, func(total uint64) {
|
||||
dir := os.Getenv("RUNNER_TEMP")
|
||||
if dir == "" {
|
||||
dir = os.TempDir()
|
||||
}
|
||||
immediate, collected, err := writeHeapProfiles(dir, heapProfileGCTimeout)
|
||||
report := "heap profile: " + immediate
|
||||
switch {
|
||||
case err != nil:
|
||||
report += "; " + err.Error()
|
||||
case collected == "":
|
||||
report += fmt.Sprintf("; no profile after collection, it did not finish within %s", heapProfileGCTimeout)
|
||||
default:
|
||||
report += "; heap profile after collection: " + collected
|
||||
}
|
||||
debug.SetTraceback("all")
|
||||
panic(fmt.Sprintf("memory guard: test process uses %d MiB, over the %d MiB limit; %s",
|
||||
total>>20, limit>>20, report))
|
||||
})
|
||||
}
|
||||
|
||||
func watchMemory(limit uint64, exceeded func(total uint64)) func() {
|
||||
done := make(chan struct{})
|
||||
stopped := make(chan struct{})
|
||||
go func() {
|
||||
defer close(stopped)
|
||||
ticker := time.NewTicker(time.Second)
|
||||
defer ticker.Stop()
|
||||
sample := []metrics.Sample{{Name: "/memory/classes/total:bytes"}}
|
||||
for {
|
||||
select {
|
||||
case <-done:
|
||||
return
|
||||
case <-ticker.C:
|
||||
}
|
||||
metrics.Read(sample)
|
||||
total := sample[0].Value.Uint64()
|
||||
if total < limit {
|
||||
continue
|
||||
}
|
||||
exceeded(total)
|
||||
return
|
||||
}
|
||||
}()
|
||||
return func() {
|
||||
close(done)
|
||||
<-stopped
|
||||
}
|
||||
}
|
||||
|
||||
// writeHeapProfiles writes a heap profile at once and a second one after
|
||||
// a forced collection, and returns the path of each. The runtime
|
||||
// publishes allocation samples only after the second mark termination
|
||||
// that follows them (see memRecord in runtime/mprof.go), so the first
|
||||
// profile can miss the burst that tripped the guard even in its
|
||||
// alloc_space view. The collection may run long or never finish when
|
||||
// memory is this high, so collected is empty when it does not finish
|
||||
// within gcTimeout. The immediate profile is kept in that case.
|
||||
func writeHeapProfiles(dir string, gcTimeout time.Duration) (immediate, collected string, err error) {
|
||||
immediate, err = writeHeapProfile(dir, "")
|
||||
if err != nil {
|
||||
return "", "", xerrors.Errorf("write heap profile: %w", err)
|
||||
}
|
||||
if !collectWithin(gcTimeout) {
|
||||
return immediate, "", nil
|
||||
}
|
||||
collected, err = writeHeapProfile(dir, "-after-gc")
|
||||
if err != nil {
|
||||
return immediate, "", xerrors.Errorf("write heap profile after collection: %w", err)
|
||||
}
|
||||
return immediate, collected, nil
|
||||
}
|
||||
|
||||
// collectWithin runs a garbage collection and reports whether it
|
||||
// finished within timeout. The collection keeps running otherwise.
|
||||
func collectWithin(timeout time.Duration) bool {
|
||||
done := make(chan struct{})
|
||||
go func() {
|
||||
defer close(done)
|
||||
runtime.GC()
|
||||
}()
|
||||
select {
|
||||
case <-done:
|
||||
return true
|
||||
case <-time.After(timeout):
|
||||
return false
|
||||
}
|
||||
}
|
||||
|
||||
func writeHeapProfile(dir, suffix string) (string, error) {
|
||||
name := fmt.Sprintf("heap-%s-%s%s.pprof",
|
||||
filepath.Base(os.Args[0]), time.Now().UTC().Format("20060102T150405Z"), suffix)
|
||||
path := filepath.Join(dir, name)
|
||||
f, err := os.Create(path)
|
||||
if err != nil {
|
||||
return "", err
|
||||
}
|
||||
if err := pprof.Lookup("heap").WriteTo(f, 0); err != nil {
|
||||
_ = f.Close()
|
||||
return "", err
|
||||
}
|
||||
if err := f.Close(); err != nil {
|
||||
return "", err
|
||||
}
|
||||
return path, nil
|
||||
}
|
||||
@@ -0,0 +1,213 @@
|
||||
package testutil_test
|
||||
|
||||
import (
|
||||
"math"
|
||||
"os"
|
||||
"os/exec"
|
||||
"path/filepath"
|
||||
"runtime"
|
||||
"strings"
|
||||
"testing"
|
||||
"time"
|
||||
|
||||
"github.com/google/pprof/profile"
|
||||
"github.com/stretchr/testify/require"
|
||||
|
||||
"github.com/coder/coder/v2/testutil"
|
||||
)
|
||||
|
||||
func TestStartMemoryGuard(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
t.Run("Exceeded", func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
exceeded := make(chan uint64, 1)
|
||||
stop := testutil.WatchMemory(1, func(total uint64) {
|
||||
exceeded <- total
|
||||
})
|
||||
defer stop()
|
||||
|
||||
select {
|
||||
case total := <-exceeded:
|
||||
require.NotZero(t, total)
|
||||
case <-time.After(testutil.WaitShort):
|
||||
t.Fatal("memory guard did not trip")
|
||||
}
|
||||
})
|
||||
|
||||
t.Run("Stops", func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
stop := testutil.WatchMemory(math.MaxUint64, func(uint64) {
|
||||
t.Error("memory guard tripped below the limit")
|
||||
})
|
||||
stopped := make(chan struct{})
|
||||
go func() {
|
||||
defer close(stopped)
|
||||
stop()
|
||||
}()
|
||||
select {
|
||||
case <-stopped:
|
||||
case <-time.After(testutil.WaitShort):
|
||||
t.Fatal("memory guard did not stop")
|
||||
}
|
||||
})
|
||||
}
|
||||
|
||||
func TestStartMemoryGuardFromEnv(t *testing.T) {
|
||||
t.Run("Unset", func(t *testing.T) {
|
||||
t.Setenv(testutil.MemoryLimitEnv, "")
|
||||
stop := testutil.StartMemoryGuardFromEnv()
|
||||
stop()
|
||||
})
|
||||
|
||||
t.Run("InvalidValue", func(t *testing.T) {
|
||||
t.Setenv(testutil.MemoryLimitEnv, "not-a-number")
|
||||
require.Panics(t, func() {
|
||||
testutil.StartMemoryGuardFromEnv()
|
||||
})
|
||||
})
|
||||
}
|
||||
|
||||
// memoryGuardFromEnvSubprocessEnv marks the re-executed test binary that
|
||||
// runs the env-configured guard until it panics.
|
||||
const memoryGuardFromEnvSubprocessEnv = "CODER_TEST_MEMORY_GUARD_FROM_ENV_SUBPROCESS"
|
||||
|
||||
func TestStartMemoryGuardFromEnvTrips(t *testing.T) {
|
||||
if os.Getenv(memoryGuardFromEnvSubprocessEnv) == "1" {
|
||||
testutil.StartMemoryGuardFromEnv()
|
||||
<-time.After(testutil.WaitLong)
|
||||
t.Fatal("memory guard did not trip")
|
||||
}
|
||||
t.Parallel()
|
||||
|
||||
ctx := testutil.Context(t, testutil.WaitLong)
|
||||
//nolint:gosec // Test-controlled arguments.
|
||||
cmd := exec.CommandContext(ctx, os.Args[0], "-test.run=^"+t.Name()+"$", "-test.v")
|
||||
cmd.Env = append(os.Environ(),
|
||||
memoryGuardFromEnvSubprocessEnv+"=1",
|
||||
testutil.MemoryLimitEnv+"=0",
|
||||
"RUNNER_TEMP="+t.TempDir())
|
||||
out, err := cmd.CombinedOutput()
|
||||
t.Logf("subprocess output:\n%s", out)
|
||||
|
||||
var exitErr *exec.ExitError
|
||||
require.ErrorAs(t, err, &exitErr, "subprocess did not fail")
|
||||
require.Equal(t, 2, exitErr.ExitCode(), "subprocess did not exit from a panic")
|
||||
require.Contains(t, string(out), "panic: memory guard: test process uses")
|
||||
require.Contains(t, string(out), "over the 0 MiB limit")
|
||||
}
|
||||
|
||||
// memoryGuardSubprocessEnv marks the re-executed test binary that runs
|
||||
// the guard until it trips.
|
||||
const memoryGuardSubprocessEnv = "CODER_TEST_MEMORY_GUARD_SUBPROCESS"
|
||||
|
||||
func TestStartMemoryGuardTrips(t *testing.T) {
|
||||
if os.Getenv(memoryGuardSubprocessEnv) == "1" {
|
||||
testutil.StartMemoryGuard(1)
|
||||
<-time.After(testutil.WaitLong)
|
||||
t.Fatal("memory guard did not trip")
|
||||
}
|
||||
t.Parallel()
|
||||
|
||||
dir := t.TempDir()
|
||||
ctx := testutil.Context(t, testutil.WaitLong)
|
||||
//nolint:gosec // Test-controlled arguments.
|
||||
cmd := exec.CommandContext(ctx, os.Args[0], "-test.run=^"+t.Name()+"$", "-test.v")
|
||||
cmd.Env = append(os.Environ(), memoryGuardSubprocessEnv+"=1", "RUNNER_TEMP="+dir)
|
||||
out, err := cmd.CombinedOutput()
|
||||
t.Logf("subprocess output:\n%s", out)
|
||||
|
||||
var exitErr *exec.ExitError
|
||||
require.ErrorAs(t, err, &exitErr, "subprocess did not fail")
|
||||
require.Equal(t, 2, exitErr.ExitCode(), "subprocess did not exit from a panic")
|
||||
require.Contains(t, string(out), "panic: memory guard: test process uses")
|
||||
require.Contains(t, string(out), "over the 0 MiB limit")
|
||||
require.Contains(t, string(out), "heap profile after collection:")
|
||||
// The test goroutine is not the one that panics, so its presence
|
||||
// shows the dump covers every goroutine.
|
||||
require.Contains(t, string(out), t.Name()+"(")
|
||||
|
||||
profiles, err := filepath.Glob(filepath.Join(dir, "heap-*.pprof"))
|
||||
require.NoError(t, err)
|
||||
require.Len(t, profiles, 2, "expected an immediate and a post-collection profile")
|
||||
for _, path := range profiles {
|
||||
f, err := os.Open(path)
|
||||
require.NoError(t, err)
|
||||
prof, err := profile.Parse(f)
|
||||
_ = f.Close()
|
||||
require.NoError(t, err, "profile %s is not readable", path)
|
||||
require.NotEmpty(t, prof.Sample, "profile %s has no samples", path)
|
||||
}
|
||||
}
|
||||
|
||||
func TestWriteHeapProfile(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
dir := t.TempDir()
|
||||
path, err := testutil.WriteHeapProfile(dir, "")
|
||||
require.NoError(t, err)
|
||||
info, err := os.Stat(path)
|
||||
require.NoError(t, err)
|
||||
require.NotZero(t, info.Size())
|
||||
}
|
||||
|
||||
func TestWriteHeapProfiles(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
// Two collections publish everything allocated so far. The burst
|
||||
// below then sits in an unpublished profile cycle, as it would when
|
||||
// the guard trips, until the forced collection in WriteHeapProfiles
|
||||
// publishes it. The allocation is large enough that the profiler
|
||||
// cannot skip it at the default sampling rate.
|
||||
runtime.GC() //nolint:revive // Two collections publish everything allocated so far.
|
||||
runtime.GC() //nolint:revive // See above.
|
||||
burst := allocateBurst()
|
||||
|
||||
immediate, collected, err := testutil.WriteHeapProfiles(t.TempDir(), testutil.WaitLong)
|
||||
require.NoError(t, err)
|
||||
require.FileExists(t, immediate)
|
||||
require.NotEmpty(t, collected, "collection did not finish")
|
||||
require.True(t, allocatedIn(t, collected, "allocateBurst"),
|
||||
"profile after collection misses the burst")
|
||||
runtime.KeepAlive(burst)
|
||||
}
|
||||
|
||||
//go:noinline
|
||||
func allocateBurst() []byte {
|
||||
return make([]byte, 32<<20)
|
||||
}
|
||||
|
||||
// allocatedIn reports whether the heap profile at path attributes
|
||||
// allocated space to a function with the given name.
|
||||
func allocatedIn(t *testing.T, path, function string) bool {
|
||||
t.Helper()
|
||||
f, err := os.Open(path)
|
||||
require.NoError(t, err)
|
||||
defer f.Close()
|
||||
prof, err := profile.Parse(f)
|
||||
require.NoError(t, err)
|
||||
|
||||
allocSpace := -1
|
||||
for i, st := range prof.SampleType {
|
||||
if st.Type == "alloc_space" {
|
||||
allocSpace = i
|
||||
}
|
||||
}
|
||||
require.NotEqual(t, -1, allocSpace, "profile has no alloc_space samples")
|
||||
|
||||
for _, s := range prof.Sample {
|
||||
if s.Value[allocSpace] == 0 {
|
||||
continue
|
||||
}
|
||||
for _, loc := range s.Location {
|
||||
for _, line := range loc.Line {
|
||||
if strings.HasSuffix(line.Function.Name, "."+function) {
|
||||
return true
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
return false
|
||||
}
|
||||
Reference in New Issue
Block a user