tracing: add background execution tracer

This commit adds a background go execution trace capture mechanism to
CRDB. The execution traces are captured with a duration and interval
set by cluster settings.

When the `obs.execution_tracer.interval` cluster setting is set to a
positive value, the execution tracer will be enabled on every node and
begin capturing traces with duration set by the
`obs.execution_tracer.duration` cluster setting (10s by default). The
traces will be captured in the log directory much like cpu and heap
profiles in a direcory named `executiontrace_dump`. The trace capture
will automatically garbage collect the oldest traces if the total
file size consumed by the execution traces exceeds the value of the
`obs.execution_tracer.total_dump_size_limit` cluster setting (4 GiB
by default).

It is encouraged to leave the dump size limit high, and the trace
capture duration low in order to allow for files that are more easily
consumable in external tools. One gigantic file will be much more
challenging to parse and navigate.

Please note that enabling execution trace capture will incur
a performance penalty. This is currently estimated at 1-2%
(https://go.dev/blog/execution-traces-2024#low-overhead-tracing). No
specific measurements have been made with CRDB at the time of this
commit.

Based on work in #146873
Part of: #97215

Release note (observability change, ops change): A new feature
that captures go execution traces on an automatic schedule is now
available. This feature will incur a performance penalty and customers
will typically use this under the guidance of Cockroach Labs support.
There are 3 cluster settings which manipulate this feature:
- `obs.execution_tracer.interval`: set to >0 to enable the tracer and
capture traces at the given interval.
- `obs.execution_tracer.duration`: sets the time over which each trace
captures data.
- `obs.execution_tracer.total_dump_size_limit` : sets the total amount
of disk space to allow execution traces to take up before the oldest
files are garbage collected automatically.

Author: dhartunian

pkg/BUILD.bazel

@@ -803,6 +803,7 @@ ALL_TESTS = [
     "//pkg/util/timeutil:timeutil_test",
     "//pkg/util/tochar:tochar_test",
     "//pkg/util/tracing/collector:collector_test",
+    "//pkg/util/tracing/goexectrace:goexectrace_test",
     "//pkg/util/tracing/grpcinterceptor:grpcinterceptor_test",
     "//pkg/util/tracing/service:service_test",
     "//pkg/util/tracing:tracing_test",
@@ -2747,6 +2748,8 @@ GO_TARGETS = [
     "//pkg/util/tochar:tochar_test",
     "//pkg/util/tracing/collector:collector",
     "//pkg/util/tracing/collector:collector_test",
+    "//pkg/util/tracing/goexectrace:goexectrace",
+    "//pkg/util/tracing/goexectrace:goexectrace_test",
     "//pkg/util/tracing/grpcinterceptor:grpcinterceptor",
     "//pkg/util/tracing/grpcinterceptor:grpcinterceptor_test",
     "//pkg/util/tracing/service:service",

pkg/base/constants.go

@@ -41,6 +41,10 @@ const (
 	// stores profiles when the periodic CPU profile dump is enabled.
 	CPUProfileDir = "pprof_dump"
 
+	// ExecutionTraceDir is the directory name that holds Go execution traces
+	// when the execution trace dumper is enabled.
+	ExecutionTraceDir = "executiontrace_dump"
+
 	// InflightTraceDir is the directory name where the job trace dumper stores traces
 	// when a job opts in to dumping its execution traces.
 	InflightTraceDir = "inflight_trace_dump"

pkg/cli/interactive_tests/test_log_flags.tcl

@@ -27,7 +27,7 @@ send "$argv start-single-node --insecure --store=path=logs/mystore2 --log-dir=\r
 eexpect "node starting"
 interrupt
 eexpect ":/# "
-send "ls logs/mystore2/logs 2>/dev/null | grep -vE 'heap_profiler|goroutine_dump|inflight_trace_dump|pprof_dump' | wc -l\r"
+send "ls logs/mystore2/logs 2>/dev/null | grep -vE 'executiontrace_dump|heap_profiler|goroutine_dump|inflight_trace_dump|pprof_dump' | wc -l\r"
 eexpect "0"
 eexpect ":/# "
 end_test

pkg/cli/log_flags.go

@@ -240,6 +240,7 @@ func setupLogging(ctx context.Context, cmd *cobra.Command, isServerCmd, applyCon
 	serverCfg.GoroutineDumpDirName = filepath.Join(outputDirectory, base.GoroutineDumpDir)
 	serverCfg.HeapProfileDirName = filepath.Join(outputDirectory, base.HeapProfileDir)
 	serverCfg.CPUProfileDirName = filepath.Join(outputDirectory, base.CPUProfileDir)
+	serverCfg.ExecutionTraceDirName = filepath.Join(outputDirectory, base.ExecutionTraceDir)
 	serverCfg.InflightTraceDirName = filepath.Join(outputDirectory, base.InflightTraceDir)
 
 	return nil

pkg/server/BUILD.bazel

@@ -342,6 +342,7 @@ go_library(
         "//pkg/util/timeutil/ptp",
         "//pkg/util/tracing",
         "//pkg/util/tracing/collector",
+        "//pkg/util/tracing/goexectrace",
         "//pkg/util/tracing/service",
         "//pkg/util/tracing/tracingpb",
         "//pkg/util/tracing/tracingservicepb",

pkg/server/config.go

@@ -183,6 +183,9 @@ type BaseConfig struct {
 	// Only used if DisableRuntimeStatsMonitor is false.
 	CPUProfileDirName string
 
+	// ExecutionTraceDirName is the directory name for Go execution traces.
+	ExecutionTraceDirName string
+
 	// InflightTraceDirName is the directory name for job traces.
 	InflightTraceDirName string
 

pkg/server/env_sampler.go

@@ -21,6 +21,7 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/util/mon"
 	"github.com/cockroachdb/cockroach/pkg/util/stop"
 	"github.com/cockroachdb/cockroach/pkg/util/timeutil"
+	"github.com/cockroachdb/cockroach/pkg/util/tracing/goexectrace"
 	"github.com/cockroachdb/errors"
 )
 
@@ -40,16 +41,17 @@ var jemallocPurgePeriod = settings.RegisterDurationSettingWithExplicitUnit(
 )
 
 type sampleEnvironmentCfg struct {
-	st                   *cluster.Settings
-	stopper              *stop.Stopper
-	minSampleInterval    time.Duration
-	goroutineDumpDirName string
-	heapProfileDirName   string
-	cpuProfileDirName    string
-	runtime              *status.RuntimeStatSampler
-	sessionRegistry      *sql.SessionRegistry
-	rootMemMonitor       *mon.BytesMonitor
-	cgoMemTarget         uint64
+	st                    *cluster.Settings
+	stopper               *stop.Stopper
+	minSampleInterval     time.Duration
+	goroutineDumpDirName  string
+	heapProfileDirName    string
+	cpuProfileDirName     string
+	executionTraceDirName string
+	runtime               *status.RuntimeStatSampler
+	sessionRegistry       *sql.SessionRegistry
+	rootMemMonitor        *mon.BytesMonitor
+	cgoMemTarget          uint64
 }
 
 // startSampleEnvironment starts a periodic loop that samples the environment and,
@@ -70,16 +72,17 @@ func startSampleEnvironment(
 		metricsSampleInterval = p.EnvironmentSampleInterval
 	}
 	cfg := sampleEnvironmentCfg{
-		st:                   srvCfg.Settings,
-		stopper:              stopper,
-		minSampleInterval:    metricsSampleInterval,
-		goroutineDumpDirName: srvCfg.GoroutineDumpDirName,
-		heapProfileDirName:   srvCfg.HeapProfileDirName,
-		cpuProfileDirName:    srvCfg.CPUProfileDirName,
-		runtime:              runtimeSampler,
-		sessionRegistry:      sessionRegistry,
-		rootMemMonitor:       rootMemMonitor,
-		cgoMemTarget:         max(uint64(pebbleCacheSize), 128*1024*1024),
+		st:                    srvCfg.Settings,
+		stopper:               stopper,
+		minSampleInterval:     metricsSampleInterval,
+		goroutineDumpDirName:  srvCfg.GoroutineDumpDirName,
+		heapProfileDirName:    srvCfg.HeapProfileDirName,
+		cpuProfileDirName:     srvCfg.CPUProfileDirName,
+		executionTraceDirName: srvCfg.ExecutionTraceDirName,
+		runtime:               runtimeSampler,
+		sessionRegistry:       sessionRegistry,
+		rootMemMonitor:        rootMemMonitor,
+		cgoMemTarget:          max(uint64(pebbleCacheSize), 128*1024*1024),
 	}
 	// Immediately record summaries once on server startup.
 
@@ -155,6 +158,15 @@ func startSampleEnvironment(
 		}
 	}
 
+	simpleFlightRecorder, err := goexectrace.NewFlightRecorder(cfg.st, 10*time.Second, cfg.executionTraceDirName)
+	if err != nil {
+		log.Warningf(ctx, "failed to initialize flight recorder: %v", err)
+	}
+	err = simpleFlightRecorder.Start(ctx, cfg.stopper)
+	if err != nil {
+		log.Warningf(ctx, "failed to start flight recorder: %v", err)
+	}
+
 	return cfg.stopper.RunAsyncTaskEx(ctx,
 		stop.TaskOpts{TaskName: "mem-logger", SpanOpt: stop.SterileRootSpan},
 		func(ctx context.Context) {

pkg/server/get_local_files_test.go

@@ -41,21 +41,28 @@ func TestGetLocalFiles(t *testing.T) {
 	if err := os.MkdirAll(testCPUDir, os.ModePerm); err != nil {
 		t.Fatal(err)
 	}
+	testExecutionTraceDir := filepath.Join(tempDir, "execution-trace")
+	if err := os.MkdirAll(testExecutionTraceDir, os.ModePerm); err != nil {
+		t.Fatal(err)
+	}
 
 	t.Run("read files successfully", func(t *testing.T) {
-		for _, test := range []string{"heap", "cpu"} {
+		for _, test := range []string{"heap", "cpu", "execution-trace"} {
 			t.Run(test, func(t *testing.T) {
 				testDir, typ := testHeapDir, serverpb.FileType_HEAP
 				if test == "cpu" {
 					testDir, typ = testCPUDir, serverpb.FileType_CPU
 				}
+				if test == "execution-trace" {
+					testDir, typ = testExecutionTraceDir, serverpb.FileType_EXECUTIONTRACE
+				}
 				fileName := fmt.Sprintf("im-in-the-%s-dir", test)
 				testFile := filepath.Join(testDir, fileName)
 				if err := os.WriteFile(testFile, []byte(fmt.Sprintf("%s stuff", test)), 0644); err != nil {
 					t.Fatal(err)
 				}
 				req := &serverpb.GetFilesRequest{NodeId: "local", Type: typ, Patterns: []string{"*"}}
-				res, err := getLocalFiles(req, testHeapDir, "", testCPUDir, os.Stat, os.ReadFile)
+				res, err := getLocalFiles(req, testHeapDir, "", testCPUDir, testExecutionTraceDir, os.Stat, os.ReadFile)
 				require.NoError(t, err)
 				require.Equal(t, 1, len(res.Files))
 				require.Equal(t, fileName, res.Files[0].Name)
@@ -74,7 +81,7 @@ func TestGetLocalFiles(t *testing.T) {
 		}
 		req := &serverpb.GetFilesRequest{
 			NodeId: "local", Type: serverpb.FileType_HEAP, Patterns: []string{"*"}}
-		_, err := getLocalFiles(req, testHeapDir, "", "", statFileWithErr, os.ReadFile)
+		_, err := getLocalFiles(req, testHeapDir, "", "", "", statFileWithErr, os.ReadFile)
 		require.ErrorContains(t, err, "stat error")
 	})
 
@@ -89,24 +96,29 @@ func TestGetLocalFiles(t *testing.T) {
 		}
 		req := &serverpb.GetFilesRequest{
 			NodeId: "local", Type: serverpb.FileType_HEAP, Patterns: []string{"*"}}
-		_, err := getLocalFiles(req, testHeapDir, "", "", os.Stat, readFileWithErr)
+		_, err := getLocalFiles(req, testHeapDir, "", "", "", os.Stat, readFileWithErr)
 		require.ErrorContains(t, err, "read error")
 	})
 
 	t.Run("dirs not implemented", func(t *testing.T) {
 		req := &serverpb.GetFilesRequest{
 			NodeId: "local", Type: serverpb.FileType_HEAP, Patterns: []string{"*"}}
-		_, err := getLocalFiles(req, "", "nonexistent", "nonexistent", os.Stat, os.ReadFile)
+		_, err := getLocalFiles(req, "", "nonexistent", "nonexistent", "", os.Stat, os.ReadFile)
 		require.ErrorContains(t, err, "dump directory not configured")
 
 		req = &serverpb.GetFilesRequest{
 			NodeId: "local", Type: serverpb.FileType_GOROUTINES, Patterns: []string{"*"}}
-		_, err = getLocalFiles(req, "nonexistent", "", "nonexistent", os.Stat, os.ReadFile)
+		_, err = getLocalFiles(req, "nonexistent", "", "nonexistent", "", os.Stat, os.ReadFile)
 		require.ErrorContains(t, err, "dump directory not configured")
 
 		req = &serverpb.GetFilesRequest{
 			NodeId: "local", Type: serverpb.FileType_CPU, Patterns: []string{"*"}}
-		_, err = getLocalFiles(req, "nonexistent", "nonexistent", "", os.Stat, os.ReadFile)
+		_, err = getLocalFiles(req, "nonexistent", "nonexistent", "", "", os.Stat, os.ReadFile)
+		require.ErrorContains(t, err, "dump directory not configured")
+
+		req = &serverpb.GetFilesRequest{
+			NodeId: "local", Type: serverpb.FileType_EXECUTIONTRACE, Patterns: []string{"*"}}
+		_, err = getLocalFiles(req, "nonexistent", "nonexistent", "nonexistent", "", os.Stat, os.ReadFile)
 		require.ErrorContains(t, err, "dump directory not configured")
 	})
 }

pkg/server/server_controller_new_server.go

@@ -239,6 +239,7 @@ func makeSharedProcessTenantServerConfig(
 	baseCfg.DefaultZoneConfig = kvServerCfg.BaseConfig.DefaultZoneConfig
 	baseCfg.HeapProfileDirName = kvServerCfg.BaseConfig.HeapProfileDirName
 	baseCfg.CPUProfileDirName = kvServerCfg.BaseConfig.CPUProfileDirName
+	baseCfg.ExecutionTraceDirName = kvServerCfg.BaseConfig.ExecutionTraceDirName
 	baseCfg.GoroutineDumpDirName = kvServerCfg.BaseConfig.GoroutineDumpDirName
 
 	// The ListenerFactory allows us to dynamically choose a
@@ -294,6 +295,7 @@ func makeSharedProcessTenantServerConfig(
 	baseCfg.GoroutineDumpDirName = ""
 	baseCfg.HeapProfileDirName = ""
 	baseCfg.CPUProfileDirName = ""
+	baseCfg.ExecutionTraceDirName = ""
 
 	// Expose the process-wide runtime metrics to the tenant's metric
 	// collector. Since they are process-wide, all tenants can see them.

pkg/server/serverpb/status.proto

@@ -794,6 +794,7 @@ enum FileType {
   HEAP = 0;
   GOROUTINES = 1;
   CPU = 2;
+  EXECUTIONTRACE = 3;
 }
 
 message File {