Merge #149373

149373: tracing: add background execution tracer r=dhartunian a=dhartunian

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.

Co-authored-by: David Hartunian <[email protected]>

Author: craig[bot]

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 {