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

Attention: Patch coverage is 77.41935% with 7 lines in your changes missing coverage. Please review.

Project coverage is 82.20%. Comparing base (e0d191d) to head (0a7df7e).
Report is 25 commits behind head on master.

Files with missing lines	Patch %	Lines
clientconn.go	50.00%	3 Missing and 1 partial ⚠️
stats/opentelemetry/trace.go	0.00%	2 Missing and 1 partial ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##           master    #8074      +/-   ##
==========================================
- Coverage   82.29%   82.20%   -0.10%     
==========================================
  Files         387      387              
  Lines       39065    38953     -112     
==========================================
- Hits        32150    32020     -130     
- Misses       5584     5608      +24     
+ Partials     1331     1325       -6

Files with missing lines	Coverage Δ
stats/opentelemetry/client_metrics.go	`89.44% <100.00%> (+0.05%)`	⬆️
stats/opentelemetry/opentelemetry.go	`75.00% <ø> (ø)`
stream.go	`81.55% <100.00%> (-0.14%)`	⬇️
stats/opentelemetry/trace.go	`78.43% <0.00%> (-4.91%)`	⬇️
clientconn.go	`90.55% <50.00%> (-1.63%)`	⬇️

... and 47 files with indirect coverage changes

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

clientconn.go

-func (cc *ClientConn) waitForResolvedAddrs(ctx context.Context) error {
+// context expires, whichever happens first.
+//
+// If the name resolution took longer than expected (indicating a delay before


nit: If the name resolution did not succeed in first attempt, it returns true indicating delay in name resolution completion. In all other cases, including name resolution failure and name resolution succeeding in first attempt, it returns false.

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.

purnesh42H · 2025-02-19T07:31:48Z

stats/opentelemetry/opentelemetry.go

@@ -211,6 +211,8 @@ type attemptInfo struct {
 	countSentMsg        uint32
 	countRecvMsg        uint32
 	previousRPCAttempts uint32
+	// nameResolutionDelayed indicates if the RPC was delayed by address resolution.


same comment as above about docstring

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

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

stream.go

 		return nil, err
 	}
+	if isDelayed {


i think its fine to always add the nameResolutionDelay key. It will be either true/false. That we don't have to check again and again.

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

purnesh42H · 2025-02-19T07:48:41Z

stream.go

 		return nil, err
 	}
+	if isDelayed {
+		ctx = context.WithValue(ctx, nameResolutionDelayKey, isDelayed)


instead of adding it to context, can't we add to the rpcInfo below at line 233? and then we can pass that rpcInfo to newClientStreamWithParams. We can also just pass the bool value

Adding something less scoped like this to context has several downsides like context pollution, ambiguity, potential for misuse. It is because context is passed to different parts of application or even beyond current application

Thank you for the suggestion. I’ve updated the code to move nameResolutionDelay to rpcInfo as recommended. rpcInfo is now passed to newClientStreamWithParams,

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

purnesh42H · 2025-02-21T05:36:04Z

just to give you more context

The firstResolveEvent is a grpcsync.Event (a custom synchronization primitive). It's used to signal whether the name resolver has sent at least one address update. HasFired() is a method on this event that tells you if the signal has already been sent.
If firstResolveEvent.HasFired() returns true, it means the resolver has already provided addresses at least once. In this case, there is no need to wait, so we can immediately return nil to signal that resolution has already occurred in the past. This is the fast path indicating no delay in name resolution
case <-cc.firstResolveEvent.Done() is part of a select statement. It's waiting for a signal on the cc.firstResolveEvent.Done() channel. The select statement will block here until something is sent on the firstResolveEvent.Done() channel. When something is sent on this channel, it means the firstResolveEvent has been fired. This is the waiting path. If cc.firstResolveEvent.HasFired() was false in the previous step, the code enters the select block. This case is specifically waiting for the resolver to send the first address update. Until then, it will block. So, its indicated delayed name resolution because rpc was blocked

purnesh42H · 2025-02-21T05:38:06Z

Test Case 1: Fast Path (Line 699)

Setup:
Create a ClientConn with a manual resolver that immediately returns a set of addresses.
Make one RPC call (or call a function that uses waitForResolvedAddrs).
Verify:
The first RPC call should pass without blocking. Because the resolver returned addresses quickly.
Make another RPC call
When the second RPC call happens, the firstResolveEvent will already be fired.

Test Case 2: Waiting Path (Line 703)

Setup:
Create a ClientConn with a manual resolver that delays returning any addresses.
Start an RPC call (or call a function that uses waitForResolvedAddrs).
The RPC should block.
Verify:
The RPC should block (we can use a channel mechanism to block/unblock. There are examples in resolver tests).
After a timeout or a manual trigger, make the manual resolver return addresses.
The blocked RPC should now continue and complete.

vinothkumarr227 · 2025-02-24T04:55:32Z

Test Case 1: Fast Path (Line 699)

Setup: Create a ClientConn with a manual resolver that immediately returns a set of addresses. Make one RPC call (or call a function that uses waitForResolvedAddrs). Verify: The first RPC call should pass without blocking. Because the resolver returned addresses quickly. Make another RPC call When the second RPC call happens, the firstResolveEvent will already be fired.

Test Case 2: Waiting Path (Line 703)

Setup: Create a ClientConn with a manual resolver that delays returning any addresses. Start an RPC call (or call a function that uses waitForResolvedAddrs). The RPC should block. Verify: The RPC should block (we can use a channel mechanism to block/unblock. There are examples in resolver tests). After a timeout or a manual trigger, make the manual resolver return addresses. The blocked RPC should now continue and complete.

Done

purnesh42H · 2025-02-24T05:25:09Z

clientconn.go

-func (cc *ClientConn) waitForResolvedAddrs(ctx context.Context) error {
+// context expires, whichever happens first.
+//
+// If the name resolution did not succeed in first attempt, it returns true


This statement is not entirely correct. Please modify this based on my other comment where I provided more background. If firstResolveEvent.HasFired() returns true, it means the resolver has already provided addresses at least once. In this case, there is no need to wait, so we can immediately return nil to signal that resolution has already occurred in the past. This is the fast path indicating no delay in name resolution.

other case is specifically waiting for the resolver to send the first address update. Until then, it will block. So, its indicated delayed name resolution.

Please modify the docstring accordingly and mention when we return true and when not. Your first statement should mention that the bool return value indicate whether there wait for resolved address happened or not. If it didn't happen or there was an error, its false. It we were blocked for name resolution then it happened, so value is true.

purnesh42H · 2025-02-24T05:30:18Z

stream.go

 	var mc serviceconfig.MethodConfig
 	var onCommit func()
 	newStream := func(ctx context.Context, done func()) (iresolver.ClientStream, error) {
-		return newClientStreamWithParams(ctx, desc, cc, method, mc, onCommit, done, opts...)
+		return newClientStreamWithParams(ctx, desc, cc, method, mc, onCommit, done, rpcInfo, opts...)


what if we just send the bool value instead of struct? Does it work? If yes, then that's more simple.

purnesh42H · 2025-02-24T05:31:32Z

test/clientconn_test.go

@@ -53,7 +55,7 @@ func (s) TestClientConnClose_WithPendingRPC(t *testing.T) {
 	go func() {
 		// This RPC would block until the ClientConn is closed, because the
 		// resolver has not provided its first update yet.
-		_, err := client.EmptyCall(ctx, &testpb.Empty{})


keep it testpb please. Don't change this. This workaround is done only for google3 because there protos are separated from server defs.

purnesh42H · 2025-02-24T05:32:08Z

test/clientconn_test.go

+
+// EmptyCall is a simple RPC that returns an empty response.
+func (s *server) EmptyCall(_ context.Context, _ *testgrpc.Empty) (*testgrpc.Empty, error) {
+	return &testgrpc.Empty{}, nil


same. It should be testpb.Empty{}

purnesh42H · 2025-02-24T05:40:49Z

test/clientconn_test.go

+
+// startTestGRPCServer initializes a test gRPC server on a random port.
+// Returns the server address and a cleanup function.
+func startTestGRPCServer(t *testing.T) (string, func()) {


can we use stubserver instead? Please see the other tests in the package for stubserver and use in the same for empty call

purnesh42H · 2025-02-24T05:44:57Z

test/clientconn_test.go

+	client := testgrpc.NewTestServiceClient(clientConn)
+
+	// First RPC call should succeed immediately
+	if _, err := client.EmptyCall(ctx, &testgrpc.Empty{}); err != nil {


This doesn't verify if name resolution field is set or not. We should have some way of verifying the nameResolutionDelay field.

I think if you pass the statsHandler in grpc.NewClient then you can check the value of the bool field that you are setting

purnesh42H · 2025-02-24T05:46:49Z

test/clientconn_test.go

+	defer cleanup()
+
+	// Create a stats handler to track name resolution delay
+	statsHandler := &testStatsHandler{}


You can do the same for non delay test as well.

I added this one for the non-delay test as well

purnesh42H · 2025-02-24T05:47:49Z

test/clientconn_test.go

+	}
+	t.Log("Second RPC succeeded after resolver update, confirming resolution completion.")
+
+	if !statsHandler.nameResolutionDelayed {


We should do the same in non delay case. It will be reverse of this there

I added this one for the non-delay test as well

purnesh42H · 2025-02-24T05:48:42Z

test/clientconn_test.go

+	}()
+
+	// Simulate a delay before updating resolver
+	time.Sleep(2 * time.Second)


We should not use time.Sleep. You should use the resolutionReady channel to unblock resolution

Refer this test https://github.com/grpc/grpc-go/blob/master/internal/resolver/dns/dns_resolver_test.go#L641. I think you can structure this test in similar way.

Block on resolutionReady in a select block and for case <- resolutionReady:, update resolver state to unblock. Is there a way we can make the first RPC wait for resolution instead of failing?

purnesh42H · 2025-02-24T05:49:30Z

test/clientconn_test.go

+	resolverBuilder.UpdateState(resolver.State{Addresses: []resolver.Address{{Addr: serverAddress}}})
+
+	// Second RPC should succeed after resolver update
+	ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)


please use single context throughout test which is cancelable.

janardhanvissa · 2025-02-25T07:42:36Z

test/clientconn_test.go

+	defer cancel()
+	client := testgrpc.NewTestServiceClient(clientConn)
+	// First RPC call should succeed immediately.
+	if _, err := client.EmptyCall(ctx, &testgrpc.Empty{}); err != nil {


It should be a testpb.Empty{}

janardhanvissa · 2025-02-25T07:46:01Z

test/clientconn_test.go

+	defer cleanup()
+
+	statsHandler := &testStatsHandler{}
+	resolverBuilder := manual.NewBuilderWithScheme("instant")


keep it simple like rb := manual.NewBuilderWithScheme("")

janardhanvissa · 2025-02-25T07:47:06Z

test/clientconn_test.go

+	resolverBuilder := manual.NewBuilderWithScheme("instant")
+	resolverBuilder.InitialState(resolver.State{Addresses: []resolver.Address{{Addr: stub.Address}}})
+	// Create a ClientConn using the manual resolver.
+	clientConn, err := grpc.NewClient(resolverBuilder.Scheme()+":///test.server",


keep it simple like cc, err := grpc.NewClient(resolverBuilder.Scheme()+":///test.server",

janardhanvissa · 2025-02-25T08:05:43Z

test/clientconn_test.go

+		close(resolutionReady)
+	case <-rpcCompleted:
+		t.Fatal("RPC completed prematurely before resolution was updated!")
+	case <-time.After(5 * time.Second):


Use test context for timeout

case <-ctx.Done(): t.Fatalf("Test setup timed out: %v", ctx.Err()) }

janardhanvissa · 2025-02-25T08:05:44Z

test/clientconn_test.go

+			t.Fatalf("RPC failed after resolution: %v", err)
+		}
+		t.Log("RPC completed successfully after resolution.")
+	case <-time.After(5 * time.Second):


same here, use test context for timeout

janardhanvissa · 2025-02-25T08:11:14Z

test/clientconn_test.go

+		grpc.WithStatsHandler(statsHandler),
+	)
+	if err != nil {
+		t.Fatalf("grpc.NewClient error: %v", err)


this can be t.Fatalf("NewClient() failed: %v", err)

janardhanvissa · 2025-02-25T08:12:52Z

test/clientconn_test.go

+	defer cleanup()
+
+	statsHandler := &testStatsHandler{}
+	clientConn, resolverBuilder := createTestClient(t, "delayed", statsHandler)


this can be cc, rb := createTestClient(t, "delayed", statsHandler)

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 3 commits February 21, 2025 12:16

Fixed the test cases

89a2bfa

small tweaks

797db0a

cleanup code

099d604

vinothkumarr227 requested a review from purnesh42H February 24, 2025 05:06

purnesh42H reviewed Feb 24, 2025

View reviewed changes

vinothkumarr227 added 2 commits February 25, 2025 05:51

Fixed the review changes

7493d5f

small tweaks

50a187f

janardhanvissa reviewed Feb 25, 2025

View reviewed changes

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

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

purnesh42H commented Feb 21, 2025

purnesh42H commented Feb 21, 2025

vinothkumarr227 commented Feb 24, 2025

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

janardhanvissa Feb 25, 2025 • edited Loading

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

janardhanvissa Feb 25, 2025 •

edited

Loading