tracer: load unwinder eBPF programs concurrently

Signed-off-by: Alban Crequy <albancrequy@microsoft.com>
Assisted-by: Claude Opus 5

Author: alban

tracer/ebpf_integration_test.go

@@ -7,6 +7,7 @@ package tracer_test
 
 import (
 	"context"
+	"log/slog"
 	"os"
 	"runtime"
 	"slices"
@@ -22,6 +23,7 @@ import (
 
 	"go.opentelemetry.io/otel/metric/noop"
 
+	"go.opentelemetry.io/ebpf-profiler/internal/log"
 	"go.opentelemetry.io/ebpf-profiler/interpreter/interpreterconfig"
 	"go.opentelemetry.io/ebpf-profiler/libpf"
 	"go.opentelemetry.io/ebpf-profiler/metrics"
@@ -288,3 +290,36 @@ func TestAllTracers(t *testing.T) {
 		})
 	}
 }
+
+// BenchmarkNewTracer measures the cost of the whole tracer startup path,
+// which is dominated by loading eBPF maps and programs into the kernel.
+//
+// Run with:
+//
+//	sudo go test -tags integration -run='^$' -bench=BenchmarkNewTracer \
+//	    -benchtime=5x -count=10 ./tracer/
+func BenchmarkNewTracer(b *testing.B) {
+	// Keep the benchmark output parseable by benchstat.
+	log.SetLevel(slog.LevelError)
+
+	ctx := b.Context()
+
+	for b.Loop() {
+		tr, err := tracer.NewTracer(ctx, &tracer.Config{
+			Intervals:              &mockIntervals{},
+			InterpretersConfig:     interpreterconfig.AllInterpreters(),
+			FilterErrorFrames:      false,
+			SamplesPerSecond:       20,
+			MapScaleFactor:         0,
+			KernelVersionCheck:     true,
+			BPFVerifierLogLevel:    0,
+			ProbabilisticInterval:  100,
+			ProbabilisticThreshold: 100,
+		})
+		require.NoError(b, err)
+
+		b.StopTimer()
+		tr.Close()
+		b.StartTimer()
+	}
+}

tracer/tracer.go

@@ -26,6 +26,7 @@ import (
 	"github.com/cilium/ebpf/features"
 	"github.com/cilium/ebpf/link"
 	"github.com/elastic/go-perf"
+	"golang.org/x/sync/errgroup"
 
 	"go.opentelemetry.io/ebpf-profiler/internal/linux"
 	"go.opentelemetry.io/ebpf-profiler/internal/log"
@@ -453,19 +454,29 @@ func initializeMapsAndPrograms(kmod *kallsyms.Module, cfg *Config, origins *orig
 		}
 	}
 
-	if err = loadPerfUnwinders(coll, ebpfProgs, ebpfMaps["perf_progs"], tailCallProgs,
-		cfg.BPFVerifierLogLevel); err != nil {
-		return nil, nil, nil, fmt.Errorf("failed to load perf eBPF programs: %v", err)
+	// The perf and the probe unwinders refer to disjoint sets of program
+	// specifications ("perf_" and "kprobe_" prefixed), and the probe unwinders only
+	// depend on already loaded maps, not on the loaded perf programs. Collect the load
+	// jobs of both so that all of them are verified by the kernel concurrently.
+	perfJobs, err := perfUnwinderJobs(coll, ebpfMaps["perf_progs"], tailCallProgs)
+	if err != nil {
+		return nil, nil, nil, fmt.Errorf("failed to prepare perf eBPF programs: %v", err)
 	}
 
 	// Load the tail call destinations so custom probes can use it.
-	// loadProbeUnwinders repoints the probe unwinder's per_cpu_records references
+	// probeUnwinderJobs repoints the probe unwinder's per_cpu_records references
 	// to per_cpu_records_kp so a perf sampler can't clobber an in-flight uprobe unwind;
 	// the perf unwinder keeps per_cpu_records.
-	if err = loadProbeUnwinders(coll, ebpfProgs, ebpfMaps["kprobe_progs"], tailCallProgs,
-		cfg.BPFVerifierLogLevel, ebpfMaps["perf_progs"].FD(),
-		ebpfMaps["per_cpu_records"].FD(), ebpfMaps["per_cpu_records_kp"]); err != nil {
-		return nil, nil, nil, fmt.Errorf("failed to load kprobe eBPF programs: %v", err)
+	probeJobs, err := probeUnwinderJobs(coll, ebpfMaps["kprobe_progs"], tailCallProgs,
+		ebpfMaps["perf_progs"].FD(), ebpfMaps["per_cpu_records"].FD(),
+		ebpfMaps["per_cpu_records_kp"])
+	if err != nil {
+		return nil, nil, nil, fmt.Errorf("failed to prepare kprobe eBPF programs: %v", err)
+	}
+
+	if err = loadPrograms(append(perfJobs, probeJobs...), cfg.BPFVerifierLogLevel,
+		ebpfProgs); err != nil {
+		return nil, nil, nil, fmt.Errorf("failed to load unwinder eBPF programs: %v", err)
 	}
 
 	if err = removeTemporaryMaps(ebpfMaps); err != nil {
@@ -718,10 +729,18 @@ func loadPerfUnwinders(coll *cebpf.CollectionSpec, ebpfProgs map[string]*cebpf.P
 	tailcallMap *cebpf.Map, tailCallProgs []ProgLoaderHelper,
 	bpfVerifierLogLevel uint32,
 ) error {
-	programOptions := cebpf.ProgramOptions{
-		LogLevel: cebpf.LogLevel(bpfVerifierLogLevel),
+	jobs, err := perfUnwinderJobs(coll, tailcallMap, tailCallProgs)
+	if err != nil {
+		return err
 	}
+	return loadPrograms(jobs, bpfVerifierLogLevel, ebpfProgs)
+}
 
+// perfUnwinderJobs collects the load jobs for all perf eBPF programs and their tail
+// call targets. It only prepares the jobs, it does not load anything into the kernel.
+func perfUnwinderJobs(coll *cebpf.CollectionSpec, tailcallMap *cebpf.Map,
+	tailCallProgs []ProgLoaderHelper,
+) ([]loadJob, error) {
 	progs := make([]ProgLoaderHelper, len(tailCallProgs)+3)
 	copy(progs, tailCallProgs)
 
@@ -743,6 +762,7 @@ func loadPerfUnwinders(coll *cebpf.CollectionSpec, ebpfProgs map[string]*cebpf.P
 			Enable:           true,
 		})
 
+	jobs := make([]loadJob, 0, len(progs))
 	for _, unwindProg := range progs {
 		if !unwindProg.Enable {
 			continue
@@ -755,16 +775,18 @@ func loadPerfUnwinders(coll *cebpf.CollectionSpec, ebpfProgs map[string]*cebpf.P
 
 		progSpec, ok := coll.Programs[unwindProgName]
 		if !ok {
-			return fmt.Errorf("program %s does not exist", unwindProgName)
+			return nil, fmt.Errorf("program %s does not exist", unwindProgName)
 		}
 
-		if err := loadProgram(ebpfProgs, tailcallMap, unwindProg.ProgID, progSpec,
-			programOptions, unwindProg.NoTailCallTarget); err != nil {
-			return err
-		}
+		jobs = append(jobs, loadJob{
+			progID:           unwindProg.ProgID,
+			progSpec:         progSpec,
+			tailcallMap:      tailcallMap,
+			noTailCallTarget: unwindProg.NoTailCallTarget,
+		})
 	}
 
-	return nil
+	return jobs, nil
 }
 
 // progArrayReferences returns a list of instructions which load a specified tail
@@ -795,10 +817,21 @@ func loadProbeUnwinders(coll *cebpf.CollectionSpec, ebpfProgs map[string]*cebpf.
 	bpfVerifierLogLevel uint32, perfTailCallMapFD int,
 	perCPURecordsFD int, perCPURecordsKprobeMap *cebpf.Map,
 ) error {
-	programOptions := cebpf.ProgramOptions{
-		LogLevel: cebpf.LogLevel(bpfVerifierLogLevel),
+	jobs, err := probeUnwinderJobs(coll, tailcallMap, progs, perfTailCallMapFD,
+		perCPURecordsFD, perCPURecordsKprobeMap)
+	if err != nil {
+		return err
 	}
+	return loadPrograms(jobs, bpfVerifierLogLevel, ebpfProgs)
+}
 
+// probeUnwinderJobs rewrites the probe program specifications and collects their load
+// jobs. It only prepares the jobs, it does not load anything into the kernel.
+func probeUnwinderJobs(coll *cebpf.CollectionSpec, tailcallMap *cebpf.Map,
+	progs []ProgLoaderHelper, perfTailCallMapFD int,
+	perCPURecordsFD int, perCPURecordsKprobeMap *cebpf.Map,
+) ([]loadJob, error) {
+	jobs := make([]loadJob, 0, len(progs))
 	for _, unwindProg := range progs {
 		if !unwindProg.Enable {
 			continue
@@ -811,79 +844,173 @@ func loadProbeUnwinders(coll *cebpf.CollectionSpec, ebpfProgs map[string]*cebpf.
 
 		progSpec, ok := coll.Programs[unwindProgName]
 		if !ok {
-			return fmt.Errorf("program %s does not exist", unwindProgName)
+			return nil, fmt.Errorf("program %s does not exist", unwindProgName)
 		}
 
 		// Replace the prog array for the tail calls.
 		insns := progArrayReferences(perfTailCallMapFD, progSpec.Instructions)
 		for _, ins := range insns {
 			if err := progSpec.Instructions[ins].AssociateMap(tailcallMap); err != nil {
-				return fmt.Errorf("failed to rewrite map ptr: %v", err)
+				return nil, fmt.Errorf("failed to rewrite map ptr: %v", err)
 			}
 		}
 
 		// Repoint per_cpu_records to the probe unwinder's own record map.
 		recInsns := progArrayReferences(perCPURecordsFD, progSpec.Instructions)
 		for _, ins := range recInsns {
 			if err := progSpec.Instructions[ins].AssociateMap(perCPURecordsKprobeMap); err != nil {
-				return fmt.Errorf("failed to rewrite per_cpu_records ptr: %v", err)
+				return nil, fmt.Errorf("failed to rewrite per_cpu_records ptr: %v", err)
 			}
 		}
 
-		if err := loadProgram(ebpfProgs, tailcallMap, unwindProg.ProgID, progSpec,
-			programOptions, unwindProg.NoTailCallTarget); err != nil {
-			return err
-		}
+		jobs = append(jobs, loadJob{
+			progID:           unwindProg.ProgID,
+			progSpec:         progSpec,
+			tailcallMap:      tailcallMap,
+			noTailCallTarget: unwindProg.NoTailCallTarget,
+		})
 	}
 
-	return nil
+	return jobs, nil
 }
 
-// loadProgram loads an eBPF program from progSpec and populates the related maps.
-func loadProgram(ebpfProgs map[string]*cebpf.Program, tailcallMap *cebpf.Map,
-	progID uint32, progSpec *cebpf.ProgramSpec, programOptions cebpf.ProgramOptions,
-	noTailCallTarget bool,
+// loadJob describes a single eBPF program that needs to be loaded into the kernel.
+type loadJob struct {
+	// progID is the tail call map index of the program, unused if noTailCallTarget.
+	progID uint32
+	// progSpec is the specification of the program to load. Each job refers to a
+	// distinct spec, so jobs can be verified concurrently.
+	progSpec *cebpf.ProgramSpec
+	// tailcallMap is the prog array the loaded program is registered in.
+	tailcallMap *cebpf.Map
+	// noTailCallTarget indicates the program is not the destination of a tail call.
+	noTailCallTarget bool
+	// prog is the loaded program, populated by loadPrograms.
+	prog *cebpf.Program
+	// err is the error returned by the kernel, populated by loadPrograms.
+	err error
+}
+
+// loadPrograms loads the given eBPF programs into the kernel and populates the related
+// maps.
+//
+// Loading a program is dominated by the time the kernel spends in the verifier, and each
+// program is verified independently of the others, so the programs are loaded
+// concurrently. Everything that mutates shared state (registering the programs and
+// updating the tail call maps) is done sequentially once all programs are loaded.
+func loadPrograms(jobs []loadJob, bpfVerifierLogLevel uint32,
+	ebpfProgs map[string]*cebpf.Program,
 ) error {
+	if len(jobs) == 0 {
+		return nil
+	}
+
+	programOptions := cebpf.ProgramOptions{
+		LogLevel: cebpf.LogLevel(bpfVerifierLogLevel),
+	}
+
+	// Raise the memlock rlimit once for all programs. It is a process wide resource
+	// limit, so it must not be modified while other programs are being loaded.
 	restoreRlimit, err := rlimit.MaximizeMemlock()
 	if err != nil {
 		return fmt.Errorf("failed to adjust rlimit: %v", err)
 	}
 	defer restoreRlimit()
 
-	// Load the eBPF program into the kernel. If no error is returned,
-	// the eBPF program can be used/called/triggered from now on.
-	unwinder, err := cebpf.NewProgramWithOptions(progSpec, programOptions)
-	if err != nil {
-		// These errors tend to have hundreds of lines (or more),
-		// so we print each line individually.
-		if ve, ok := err.(*cebpf.VerifierError); ok {
-			for _, line := range ve.Log {
-				log.Errorf("%s", line)
-			}
-		} else {
-			scanner := bufio.NewScanner(strings.NewReader(err.Error()))
-			for scanner.Scan() {
-				log.Errorf("%s", scanner.Text())
+	eg := &errgroup.Group{}
+	eg.SetLimit(min(runtime.GOMAXPROCS(0), len(jobs)))
+	for i := range jobs {
+		job := &jobs[i]
+		eg.Go(func() error {
+			// Load the eBPF program into the kernel. If no error is returned,
+			// the eBPF program can be used/called/triggered from now on.
+			prog, err := cebpf.NewProgramWithOptions(job.progSpec, programOptions)
+			if err != nil {
+				// The error is only recorded here and reported once all loads
+				// have finished: verifier errors are hundreds of lines long and
+				// are logged line by line, so logging them from several
+				// goroutines would interleave them into an unreadable mess.
+				job.err = err
+				return err
 			}
-		}
-		return fmt.Errorf("failed to load %s", progSpec.Name)
+			job.prog = prog
+			return nil
+		})
 	}
-	ebpfProgs[progSpec.Name] = unwinder
+	loadErr := eg.Wait()
 
-	if noTailCallTarget {
-		return nil
+	// Hand over every program that did load, so that a partially failed load is
+	// still cleaned up by the caller.
+	for i := range jobs {
+		if jobs[i].prog != nil {
+			ebpfProgs[jobs[i].progSpec.Name] = jobs[i].prog
+		}
 	}
-	fd := uint32(unwinder.FD())
-	if err := tailcallMap.Update(unsafe.Pointer(&progID), unsafe.Pointer(&fd),
-		cebpf.UpdateAny); err != nil {
-		// Every eBPF program that is loaded within loadUnwinders can be the
-		// destination of a tail call of another eBPF program. If we can not update
-		// the eBPF map that manages these destinations our unwinding will fail.
-		return fmt.Errorf("failed to update tailcall map: %v", err)
+	if loadErr != nil {
+		return reportLoadErrors(jobs)
+	}
+
+	for i := range jobs {
+		job := &jobs[i]
+		if job.noTailCallTarget {
+			continue
+		}
+		fd := uint32(job.prog.FD())
+		if err := job.tailcallMap.Update(unsafe.Pointer(&job.progID), unsafe.Pointer(&fd),
+			cebpf.UpdateAny); err != nil {
+			// Every eBPF program that is loaded within loadUnwinders can be the
+			// destination of a tail call of another eBPF program. If we can not update
+			// the eBPF map that manages these destinations our unwinding will fail.
+			return fmt.Errorf("failed to update tailcall map: %v", err)
+		}
 	}
 	return nil
 }
 
+// reportLoadErrors logs the failures recorded by loadPrograms and returns the error
+// of the first job that failed, in job order, so that the reported error does not
+// depend on the order in which the loads happened to complete.
+//
+// A single unsupported instruction usually makes every program fail, and the kernel
+// log of one failure is already hundreds of lines long, so only the first one is
+// logged in full and the others are summarized.
+func reportLoadErrors(jobs []loadJob) error {
+	var firstErr error
+	var alsoFailed []string
+	for i := range jobs {
+		job := &jobs[i]
+		if job.err == nil {
+			continue
+		}
+		if firstErr == nil {
+			logLoadError(job.err)
+			firstErr = fmt.Errorf("failed to load %s", job.progSpec.Name)
+			continue
+		}
+		alsoFailed = append(alsoFailed, job.progSpec.Name)
+	}
+	if len(alsoFailed) > 0 {
+		log.Errorf("%d other eBPF programs failed to load: %s",
+			len(alsoFailed), strings.Join(alsoFailed, ", "))
+	}
+	return firstErr
+}
+
+// logLoadError logs a program load error. These errors tend to have hundreds of
+// lines (or more), so we print each line individually.
+func logLoadError(err error) {
+	if ve, ok := errors.AsType[*cebpf.VerifierError](err); ok {
+		for _, line := range ve.Log {
+			log.Errorf("%s", line)
+		}
+		return
+	}
+	scanner := bufio.NewScanner(strings.NewReader(err.Error()))
+	for scanner.Scan() {
+		log.Errorf("%s", scanner.Text())
+	}
+}
+
 // enableEvent removes the entry of given eventType from the inhibitEvents map
 // so that the eBPF code will send the event again.
 func (t *Tracer) enableEvent(eventType int) {