profiler: log cpuProfileRate when starting a trace (#2030)

profiler/profile.go

@@ -8,6 +8,7 @@ package profiler
 import (
 	"bytes"
 	"compress/gzip"
+	"context"
 	"errors"
 	"fmt"
 	"io"
@@ -194,6 +195,7 @@ var profileTypes = map[ProfileType]profileType{
 			if err := trace.Start(lt); err != nil {
 				return nil, err
 			}
+			traceLogCPUProfileRate(p.cfg.cpuProfileRate)
 			select {
 			case <-p.exit: // Profiling was stopped
 			case <-time.After(p.cfg.period): // The profiling cycle has ended
@@ -205,6 +207,19 @@ var profileTypes = map[ProfileType]profileType{
 	},
 }
 
+// traceLogCPUProfileRate logs the cpuProfileRate to the execution tracer if
+// its not 0. This gives us a better chance to correctly guess the CPU duration
+// of traceEvCPUSample events. It will not work correctly if the user is
+// calling runtime.SetCPUProfileRate() themselves, and there is no way to
+// handle this scenario given the current APIs. See
+// https://github.com/golang/go/issues/60701 for a proposal to improve the
+// situation.
+func traceLogCPUProfileRate(cpuProfileRate int) {
+	if cpuProfileRate != 0 {
+		trace.Log(context.Background(), "cpuProfileRate", fmt.Sprintf("%d", cpuProfileRate))
+	}
+}
+
 // defaultExecutionTraceSizeLimit is the default upper bound, in bytes,
 // of an executiont trace.
 //

profiler/profiler_test.go

@@ -6,10 +6,12 @@
 package profiler
 
 import (
+	"bytes"
 	"context"
 	"encoding/json"
 	"fmt"
 	"io"
+	"math/rand"
 	"net"
 	"net/http"
 	"net/http/httptest"
@@ -465,12 +467,22 @@ func TestExecutionTrace(t *testing.T) {
 	server := httptest.NewServer(&mockBackend{t: t, profiles: got})
 	defer server.Close()
 
+	// cpuProfileRate is picked randomly so we can check for it in the trace
+	// data to reduce the chance that it occurs in the trace data for some other
+	// reduce. In theory we could use the entire int64 space, but when we do
+	// this the runtime can crash with the error shown below.
+	//
+	// runtime: kevent on fd 3 failed with 60
+	// fatal error: runtime: netpoll failed
+	cpuProfileRate := int(9999 + rand.Int63n(9999))
+
 	t.Setenv("DD_PROFILING_EXECUTION_TRACE_ENABLED", "true")
 	t.Setenv("DD_PROFILING_EXECUTION_TRACE_PERIOD", "3s")
 	err := Start(
 		WithAgentAddr(server.Listener.Addr().String()),
 		WithProfileTypes(CPUProfile),
 		WithPeriod(1*time.Second),
+		CPUProfileRate(int(cpuProfileRate)),
 	)
 	require.NoError(t, err)
 	defer Stop()
@@ -489,6 +501,7 @@ func TestExecutionTrace(t *testing.T) {
 		t.Log(m.event.Attachments, m.tags)
 		if contains(m.event.Attachments, "go.trace") && contains(m.tags, "go_execution_traced:yes") {
 			seenTraces++
+			assertContainsCPUProfileRateLog(t, m.attachments["go.trace"], cpuProfileRate)
 		}
 	}
 	// With a trace frequency of 3 seconds and a profiling period of 1
@@ -499,6 +512,13 @@ func TestExecutionTrace(t *testing.T) {
 	}
 }
 
+// assertContainsCPUProfileRateLog checks for the presence of the log written by
+// traceLogCPUProfileRate. It's a bit hacky, but probably good enough for now :).
+func assertContainsCPUProfileRateLog(t *testing.T, traceData []byte, cpuProfileRate int) {
+	assert.True(t, bytes.Contains(traceData, []byte("cpuProfileRate")))
+	assert.True(t, bytes.Contains(traceData, []byte(fmt.Sprintf("%d", cpuProfileRate))))
+}
+
 // TestEndpointCounts verfies that the unit of work feature works end to end.
 func TestEndpointCounts(t *testing.T) {
 	for _, enabled := range []bool{true, false} {