Fix issue with Go request start timing (#1556)

grafana · Jan 22, 2025 · d53deed · d53deed
1 parent 1dad6ff
commit d53deed
Show file tree

Hide file tree

Showing 11 changed files with 28 additions and 71 deletions.
diff --git a/bpf/go_grpc.h b/bpf/go_grpc.h
@@ -238,14 +238,8 @@ int beyla_uprobe_server_handleStream_return(struct pt_regs *ctx) {
     trace->status = status;
     trace->content_length = 0;
     trace->method[0] = 0;
-
-    goroutine_metadata *g_metadata = bpf_map_lookup_elem(&ongoing_goroutines, &g_key);
-    if (g_metadata) {
-        trace->go_start_monotime_ns = g_metadata->timestamp;
-        bpf_map_delete_elem(&ongoing_goroutines, &g_key);
-    } else {
-        trace->go_start_monotime_ns = invocation->start_monotime_ns;
-    }
+    trace->go_start_monotime_ns = invocation->start_monotime_ns;
+    bpf_map_delete_elem(&ongoing_goroutines, &g_key);
 
     // Get method from transport.Stream.Method
     if (!read_go_str("grpc method",

diff --git a/bpf/go_nethttp.h b/bpf/go_nethttp.h
@@ -220,6 +220,8 @@ int beyla_uprobe_readRequestReturns(struct pt_regs *ctx) {
         if (bpf_map_update_elem(&ongoing_goroutines, &g_key, &metadata, BPF_ANY)) {
             bpf_dbg_printk("can't update active goroutine");
         }
+    } else {
+        g_metadata->timestamp = bpf_ktime_get_ns();
     }
 
     return 0;

diff --git a/pkg/internal/ebpf/gotracer/bpf_arm64_bpfel.o b/pkg/internal/ebpf/gotracer/bpf_arm64_bpfel.o
diff --git a/pkg/internal/ebpf/gotracer/bpf_debug_arm64_bpfel.o b/pkg/internal/ebpf/gotracer/bpf_debug_arm64_bpfel.o
diff --git a/pkg/internal/ebpf/gotracer/bpf_debug_x86_bpfel.o b/pkg/internal/ebpf/gotracer/bpf_debug_x86_bpfel.o
diff --git a/pkg/internal/ebpf/gotracer/bpf_tp_arm64_bpfel.o b/pkg/internal/ebpf/gotracer/bpf_tp_arm64_bpfel.o
diff --git a/pkg/internal/ebpf/gotracer/bpf_tp_debug_arm64_bpfel.o b/pkg/internal/ebpf/gotracer/bpf_tp_debug_arm64_bpfel.o
diff --git a/pkg/internal/ebpf/gotracer/bpf_tp_debug_x86_bpfel.o b/pkg/internal/ebpf/gotracer/bpf_tp_debug_x86_bpfel.o
diff --git a/pkg/internal/ebpf/gotracer/bpf_tp_x86_bpfel.o b/pkg/internal/ebpf/gotracer/bpf_tp_x86_bpfel.o
diff --git a/pkg/internal/ebpf/gotracer/bpf_x86_bpfel.o b/pkg/internal/ebpf/gotracer/bpf_x86_bpfel.o
diff --git a/test/integration/traces_test.go b/test/integration/traces_test.go
@@ -183,7 +183,7 @@ func testGRPCTracesForServiceName(t *testing.T, svcName string) {
 		traces := tq.FindBySpan(jaeger.Tag{Key: "rpc.method", Type: "string", Value: "/routeguide.RouteGuide/Debug"})
 		require.Len(t, traces, 1)
 		trace = traces[0]
-		require.Len(t, trace.Spans, 3) // parent - in queue - processing
+		require.Len(t, trace.Spans, 1) // parent
 	}, test.Interval(100*time.Millisecond))
 
 	// Check the information of the parent span
@@ -204,49 +204,8 @@ func testGRPCTracesForServiceName(t *testing.T, svcName string) {
 	)
 	assert.Empty(t, sd, sd.String())
 
-	// Check the information of the "in queue" span
-	res = trace.FindByOperationName("in queue")
-	require.Len(t, res, 1)
-	queue := res[0]
-	// Check parenthood
-	p, ok := trace.ParentOf(&queue)
-	require.True(t, ok)
-	assert.Equal(t, parent.TraceID, p.TraceID)
-	assert.Equal(t, parent.SpanID, p.SpanID)
-	// check reasonable start and end times
-	assert.GreaterOrEqual(t, queue.StartTime, parent.StartTime)
-	assert.LessOrEqual(t,
-		queue.StartTime+queue.Duration,
-		parent.StartTime+parent.Duration+1) // adding 1 to tolerate inaccuracies from rounding from ns to ms
-	// check span attributes
-	sd = queue.Diff(
-		jaeger.Tag{Key: "span.kind", Type: "string", Value: "internal"},
-	)
-	assert.Empty(t, sd, sd.String())
-
-	// Check the information of the "processing" span
-	res = trace.FindByOperationName("processing")
-	require.Len(t, res, 1)
-	processing := res[0]
-	// Check parenthood
-	p, ok = trace.ParentOf(&queue)
-	require.True(t, ok)
-	assert.Equal(t, parent.TraceID, p.TraceID)
-	require.False(t, strings.HasSuffix(parent.TraceID, "0000000000000000")) // the Debug call doesn't add any traceparent to the request header, the traceID is auto-generated won't look like this
-	assert.Equal(t, parent.SpanID, p.SpanID)
-	// check reasonable start and end times
-	assert.GreaterOrEqual(t, processing.StartTime, queue.StartTime+queue.Duration)
-	assert.LessOrEqual(t, processing.StartTime+processing.Duration, parent.StartTime+parent.Duration+1)
-	// check span attributes
-	sd = queue.Diff(
-		jaeger.Tag{Key: "span.kind", Type: "string", Value: "internal"},
-	)
-	assert.Empty(t, sd, sd.String())
-
 	// check process ID
 	require.Contains(t, trace.Processes, parent.ProcessID)
-	assert.Equal(t, parent.ProcessID, queue.ProcessID)
-	assert.Equal(t, parent.ProcessID, processing.ProcessID)
 	process := trace.Processes[parent.ProcessID]
 	assert.Equal(t, svcName, process.ServiceName)
 
@@ -599,10 +558,6 @@ func testHTTP2GRPCTracesNestedCalls(t *testing.T, contextPropagation bool) {
 
 	numNested := 1
 
-	if contextPropagation {
-		numNested = 2
-	}
-
 	// Check the information of the "in queue" span
 	res = trace.FindByOperationName("in queue")
 	require.Equal(t, len(res), numNested)
@@ -653,9 +608,15 @@ func testHTTP2GRPCTracesNestedCalls(t *testing.T, contextPropagation bool) {
 	)
 	assert.Empty(t, sd, sd.String())
 
+	numNestedGRPC := 1
+
+	if contextPropagation {
+		numNestedGRPC = 2
+	}
+
 	// Check the information of the "processing" span
 	res = trace.FindByOperationName("/routeguide.RouteGuide/GetFeature")
-	require.Len(t, res, numNested)
+	require.Len(t, res, numNestedGRPC)
 	for index := range res {
 		grpc := res[index]
 		if contextPropagation {