stats/opentelemetry: add trace event for name resolution delay #8074

vinothkumarr227 · 2025-02-10T10:40:32Z

stats/opentelemetry: add trace event for name resolution delay.

RELEASE NOTES: None

codecov · 2025-02-10T10:50:12Z

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 82.24%. Comparing base (af07815) to head (f092d0f).
Report is 3 commits behind head on master.

Additional details and impacted files

@@            Coverage Diff             @@
##           master    #8074      +/-   ##
==========================================
- Coverage   82.30%   82.24%   -0.06%     
==========================================
  Files         392      392              
  Lines       39132    39150      +18     
==========================================
- Hits        32207    32199       -8     
- Misses       5603     5621      +18     
- Partials     1322     1330       +8

Files with missing lines	Coverage Δ
clientconn.go	`90.82% <100.00%> (+0.26%)`	⬆️
stats/opentelemetry/client_metrics.go	`89.44% <100.00%> (+0.05%)`	⬆️
stats/opentelemetry/client_tracing.go	`83.33% <100.00%> (+6.86%)`	⬆️
stats/opentelemetry/opentelemetry.go	`75.00% <ø> (ø)`
stream.go	`81.55% <100.00%> (+0.03%)`	⬆️

... and 27 files with indirect coverage changes

🚀 New features to boost your workflow:

❄ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

clientconn.go

purnesh42H · 2025-02-19T07:30:44Z

stats/handlers.go

@@ -38,6 +38,8 @@ type RPCTagInfo struct {
 	// FailFast indicates if this RPC is failfast.
 	// This field is only valid on client side, it's always false on server side.
 	FailFast bool
+	// NameResolutionDelay indicates if the RPC was delayed due to address resolution.


// NameResolutionDelay indicates if there was a delay in the name resolution.
// This field is only valid on client side, it's always false on server side.

stats/opentelemetry/opentelemetry.go

purnesh42H · 2025-02-19T07:33:07Z

stream.go

@@ -212,9 +216,13 @@ func newClientStream(ctx context.Context, desc *StreamDesc, cc *ClientConn, meth
 	}
 	// Provide an opportunity for the first RPC to see the first service config
 	// provided by the resolver.
-	if err := cc.waitForResolvedAddrs(ctx); err != nil {
+	isDelayed, err := cc.waitForResolvedAddrs(ctx)


nit: isDelayed -> nameResDelayed/nameResolutionDelayed

stream.go

purnesh42H · 2025-02-19T07:35:51Z

stream.go

@@ -416,8 +424,9 @@ func (cs *clientStream) newAttemptLocked(isTransparent bool) (*csAttempt, error)
 	method := cs.callHdr.Method
 	var beginTime time.Time
 	shs := cs.cc.dopts.copts.StatsHandlers
+	isDelayed, _ := ctx.Value(nameResolutionDelayKey).(bool)


same comment about naming the variable as above

stream.go

purnesh42H · 2025-02-19T07:55:49Z

stream.go

@@ -212,9 +216,13 @@ func newClientStream(ctx context.Context, desc *StreamDesc, cc *ClientConn, meth
 	}
 	// Provide an opportunity for the first RPC to see the first service config
 	// provided by the resolver.
-	if err := cc.waitForResolvedAddrs(ctx); err != nil {
+	isDelayed, err := cc.waitForResolvedAddrs(ctx)


returning a bool and error is not good practice for go. It breaks the established pattern of error handling in Go because returned bool indicates success/failure in general. Can we do something better? It might be fine if we can't but we can try to look for better ways.

I have an approach as follows:

Add a nameResolutionDelay field: Add a new nameResolutionDelay field to the ClientConn struct to store the delay state.
Modify waitForResolvedAddrs: Set the nameResolutionDelay field directly in ClientConn instead of returning a boolean.
Access in newAttemptLocked: Use the nameResolutionDelay field from ClientConn within newAttemptLocked.

i don't think we want to add the field to clientconn because clientconn is not restricted to only single rpc. Returning a struct sounds better but we don't have any other field apart from boolean field. Let's keep bool, err for now. But make sure docstring is updated to indicate the bool correctly.

test/clientconn_test.go

…few doc issues

clientconn.go

stats/opentelemetry/trace.go

test/clientconn_test.go

purnesh42H · 2025-02-27T05:46:16Z

test/clientconn_test.go

+	}()
+	// Simulate delayed resolution and unblock it via resolutionReady
+	go func() {
+		<-resolutionReady


Before <-resolutionReady, you can add the t.LogF("RPC waiting for resolved addresses")

test/clientconn_test.go

purnesh42H · 2025-02-28T10:15:35Z

stats/opentelemetry/trace.go

@@ -52,6 +52,9 @@ func populateSpan(rs stats.RPCStats, ai *attemptInfo) {
 		)
 		// increment previous rpc attempts applicable for next attempt
 		atomic.AddUint32(&ai.previousRPCAttempts, 1)
+		if ai.nameResolutionDelayed {


this is wrong. As per https://github.com/grpc/proposal/blob/master/A72-open-telemetry-tracing.md#tracing-information, "Delayed name resolution" should be an event in the call span not attempt span.

This should be right place https://github.com/grpc/grpc-go/blob/master/stats/opentelemetry/client_tracing.go#L34. Before creating the attempt span, you need to retrieve the current call span using trace.SpanFromContext and add an event to that span. Before that, also check if that event already exist or not. And only add, if it exist.

@purnesh42H Could you clarify this part: "Only add if it exists"? Should we check if the event has already been added and skip adding it if it has? Or did you mean we should check ai.nameResolutionDelayed before adding the event? Is there any other condition we should consider?

purnesh42H · 2025-02-28T10:30:45Z

test/clientconn_test.go

+	if _, err := client.EmptyCall(ctx, &testpb.Empty{}); err != nil {
+		t.Fatalf("First RPC failed unexpectedly: %v", err)
+	}
+	// Verify that name resolution did not happen.


this doesn't mean "name resolution did not happen". Either it should be "name resolution did not happen again" or "Verify that RPC was not blocked on waiting for resolver to return addresses indicating no name resolution delay". I prefer the latter.

test/clientconn_test.go

purnesh42H · 2025-03-04T06:10:15Z

stats/opentelemetry/client_tracing.go

@@ -30,7 +30,17 @@ import (
 // It creates a new outgoing carrier which serializes information about this
 // span into gRPC Metadata, if TextMapPropagator is provided in the trace
 // options. if TextMapPropagator is not provided, it returns the context as is.
+// Additionally, if name resolution was delayed (ai.nameResolutionDelayed is


this comment can be within the method instead of docstring

purnesh42H · 2025-03-04T06:11:20Z

stats/opentelemetry/client_tracing.go

 func (h *clientStatsHandler) traceTagRPC(ctx context.Context, ai *attemptInfo) (context.Context, *attemptInfo) {
+	callSpan := trace.SpanFromContext(ctx)
+	if ai.nameResolutionDelayed && !ai.nameResolutionEventAdded {


i don't think its the right way to maintain another boolean field for checking if event was already added or not. Can't we just check in the list if the event by that name already exist?

you can optionally declare a const with name "Delayed name resolution complete" for readability

@vinothkumarr227 i discussed this problem with @dfawley and he suggested to use atomic bool here and swap the value whenever we find true in any of the retry attempt and then add the event to call span only if we find it true.

clientconn.go

purnesh42H · 2025-03-04T06:17:22Z

stats/opentelemetry/opentelemetry.go

+	// complete" event has already been added to prevent duplicate event
+	// logging. This field is only applicable on the client side and is always
+	// false on the server side.
+	nameResolutionEventAdded bool


yeah that's not a good idea to maintain another field in this struct just for checking existence in the same package.

Yeah, I have now modified it by adding atomic.Bool for nameResolutionEventAdded.

purnesh42H · 2025-03-04T06:21:26Z

test/clientconn_test.go

+	if _, err := client.EmptyCall(ctx, &testpb.Empty{}); err != nil {
+		t.Fatalf("First RPC failed unexpectedly: %v", err)
+	}
+	// verifying that RPC was blocked on resolver to return addresses


comment seems wrong. it should be "verifying that RPC was not blocked on resolver indicating there was no delay in name resolution

purnesh42H · 2025-03-04T06:22:21Z

test/clientconn_test.go

+
+// TestStatsHandlerDetectsResolutionDelay verifies that if this is the
+// first time resolution is happening at the time of making RPC,
+// nameResolutionDelayed flag was set indicating there was a delay in name


nameResolutionDelayed is set

purnesh42H · 2025-03-06T12:16:14Z

stats/opentelemetry/client_tracing.go

+	// event is logged only once using an atomic flag, even across retries.
+	callSpan := trace.SpanFromContext(ctx)
+	if ai.nameResolutionDelayed && !ai.nameResolutionEventAdded.Swap(true) {
+		if callSpan.SpanContext().IsValid() {


nit: this can be part of the same top level if?

purnesh42H · 2025-03-06T12:18:09Z

stats/opentelemetry/e2e_test.go

@@ -1563,3 +1569,144 @@ func (s) TestRPCSpanErrorStatus(t *testing.T) {
 		t.Fatalf("got rpc error %s, want %s", spans[0].Status.Description, rpcErrorMsg)
 	}
 }
+
+type testStatsHandler struct {
+	nameResolutionDelayed atomic.Bool


Even for test, nameResolutionDelayed shouldn't be part of stats handler because the scope of it is per rpc.

purnesh42H · 2025-03-06T12:19:40Z

stats/opentelemetry/e2e_test.go

+// HandleRPC tracks if an RPC started with a delayed name resolution.
+func (h *testStatsHandler) HandleRPC(_ context.Context, rs stats.RPCStats) {
+	if _, ok := rs.(*stats.Begin); ok {
+		h.nameResolutionDelayed.CompareAndSwap(false, true)


hmmm.... HandleRPC is called for every event in the attempt. nameResolutionDelayed should be always handled in TagRPC which is called for every retry attempt of a call.

purnesh42H · 2025-03-06T12:29:59Z

stats/opentelemetry/e2e_test.go

+// indicating that the resolver took time to return addresses.
+// The test also ensures that retries happen as per the configured policy
+// and that the resolution delay event is added to the call span only once.
+func TestNameResolutionDelay_WithRetry(t *testing.T) {


@vinothkumarr227 can you write the test similar to how other tests are written? See TestSpan. You can write exact similar test with only difference being retries and manual resolver for delay. However, you shouldn't verify the name resolution flag in the test because that part is already being tested in the clientconn test. Only thing you need to modify is your expected call span grpc.testing.TestService.UnaryCallandgrpc.testing.TestService.FullDuplexCall to have "Delayed name resolution complete as one event.

I think if you do above, you wouldn't need a separate test stats handler for this test.

purnesh42H · 2025-03-06T12:50:58Z

stats/opentelemetry/client_tracing.go

+	// delay was detected and the event hasn't been recorded yet. Ensures the
+	// event is logged only once using an atomic flag, even across retries.
+	callSpan := trace.SpanFromContext(ctx)
+	if ai.nameResolutionDelayed && !ai.nameResolutionEventAdded.Swap(true) {


can't we do something like !atomic.SwapBool(ai.nameResolutionEventAdded, true) and nameResolutionEventAdded can be a regular bool type

I noticed that there isn't a method named SwapBool, so I used ai.nameResolutionEventAdded.Swap(true) to achieve the desired functionality

vinothkumarr227 added 2 commits February 10, 2025 10:38

Added add trace event for name resolution delay

d773e44

small tweaks

126b42f

vinothkumarr227 added 15 commits February 10, 2025 10:52

Removed unused parameter

dad6621

Removed unused parameter

37e1803

Fixed the duplicate import issues

9ae5cc8

refactor: simplify tests, fix SubConn deprecation, and add docs

f9b00e9

refactor: add function documentation and update variable names

3ce7799

Add test for 'Name resolution completed with delay' event check

76dc143

small tweaks

82f3ede

small tweaks

2ec49a9

Fixed the test cases

3af52f4

Added add trace event for name resolution delay

c0affc5

small tweaks

323b663

small tweaks

b76ed24

small tweaks

bc99c93

Fixed the name resolutions delay event test issues

e86b142

small tweaks

27914a2

arjan-bal requested a review from purnesh42H February 17, 2025 07:16

arjan-bal assigned purnesh42H Feb 17, 2025

arjan-bal added this to the 1.71 Release milestone Feb 17, 2025

arjan-bal added Type: Feature New features or improvements in behavior Area: Observability Includes Stats, Tracing, Channelz, Healthz, Binlog, Reflection, Admin, GCP Observability labels Feb 17, 2025

purnesh42H reviewed Feb 19, 2025

View reviewed changes

purnesh42H assigned vinothkumarr227 and unassigned purnesh42H Feb 19, 2025

arjan-bal modified the milestones: 1.71 Release, 1.72 Release Feb 19, 2025

vinothkumarr227 added 2 commits February 19, 2025 13:09

Refactor the integration of nameResolutionDelay in RPCInfo and fix a …

63bb794

…few doc issues

small tweaks

a4b6281

vinothkumarr227 added 2 commits February 25, 2025 08:22

Fixed the review changes

67bd066

small tweaks

0a7df7e

vinothkumarr227 requested review from janardhanvissa and purnesh42H February 25, 2025 10:46

small tweaks

442ff47

purnesh42H reviewed Feb 27, 2025

View reviewed changes

vinothkumarr227 added 3 commits February 27, 2025 12:13

Fixed the review changes

783b826

small tweaks

cd6e768

updated logs and fixed formatting

ec567ff

vinothkumarr227 requested a review from purnesh42H February 27, 2025 13:13

purnesh42H reviewed Feb 28, 2025

View reviewed changes

Fixed thew review changes

b7b54e2

vinothkumarr227 requested a review from purnesh42H March 3, 2025 07:41

purnesh42H reviewed Mar 4, 2025

View reviewed changes

vinothkumarr227 added 5 commits March 6, 2025 07:11

Fixed the review changes

684370e

Update traceTagRPC to track name resolution dely and added retry test

38c9783

Merge branch 'master' into name-resolution-delay-stats

dbf2a7e

small tweaks

f13fbe2

small tweaks

a3bab29

vinothkumarr227 requested a review from purnesh42H March 6, 2025 10:16

purnesh42H reviewed Mar 6, 2025

View reviewed changes

vinothkumarr227 added 7 commits March 7, 2025 15:02

Fixed the review changes

ab914bd

small tweaks

08abc09

small tweaks

7613c2c

small tweaks

b03fb20

Fixed the retry test issues

bbe7e30

small tweaks

d2fbf8a

small tweaks

f092d0f

vinothkumarr227 requested a review from purnesh42H March 10, 2025 06:27

stats/opentelemetry: add trace event for name resolution delay #8074

Are you sure you want to change the base?

stats/opentelemetry: add trace event for name resolution delay #8074

Conversation

vinothkumarr227 commented Feb 10, 2025 • edited Loading

codecov bot commented Feb 10, 2025 • edited Loading

Codecov Report

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vinothkumarr227 commented Feb 10, 2025 •

edited

Loading

codecov bot commented Feb 10, 2025 •

edited

Loading