stats: Add RPC event for blocking for a picker update #6422

zasweq · 2023-06-29T19:47:45Z

This PR adds stats events representing blocking resolver resolve and blocking picker pick. The OpenCensus stats handler uses these callouts to add trace annotations, which provide a timestamp for debugging purposes.

Fixes #6418.

RELEASE NOTES:

stats: Add an RPC event for blocking caused by the LB policy's picker

dfawley · 2023-06-29T20:03:24Z

stats/stats.go

@@ -59,6 +59,26 @@ func (s *Begin) IsClient() bool { return s.Client }

 func (s *Begin) isRPCStats() {}

+// ResolverResolved represents an event that the resolved finished resolving if
+// the ClientConn blocks on resolver resolution while performing a RPC.
+type ResolverResolved struct{}


InitialResolverResult?

dfawley · 2023-06-29T20:08:10Z

stats/stats.go

+
+// PickerPicked represents an event that the picker finished picking if the ClientConn
+// blocks on picker picking while performing a RPC.
+type PickerPicked struct{}


PickerUpdated? (This one seems tricky to find something succinct for.)

Yeah needs to encapsulate all: https://github.com/grpc/grpc-go/blob/master/picker_wrapper.go#L87. PickedUpdated sounds fine to me.

dfawley · 2023-06-29T20:34:37Z

stats/stats.go

@@ -59,6 +59,27 @@ func (s *Begin) IsClient() bool { return s.Client }

 func (s *Begin) isRPCStats() {}

+// InitialResolverResult represents an event that the resolved finished


resolved->resolver

dfawley · 2023-06-29T20:34:47Z

stats/stats.go

@@ -59,6 +59,27 @@ func (s *Begin) IsClient() bool { return s.Client }

 func (s *Begin) isRPCStats() {}

+// InitialResolverResult represents an event that the resolved finished
+// resolving if the ClientConn blocks on resolver resolution while performing a


"...if the RPC occurred before the initial resolver result."?

My string is still technically correct, but yours falls under the subset of my language and is more specific :). Switched.

This is an external docstring, so we should find something that is as clear and concise as possible.

"blocks on resolver resolution" is confusing to read and technically the ClientConn doesn't block -- the RPC does.

Right, I agree. Will push once I finish tests.

dfawley · 2023-06-29T20:40:00Z

stats/stats.go

+// PickerUpdated represents an event that the picker finished picking if the
+// ClientConn blocks on picker picking while performing a RPC.


"PickerUpdated indicates that the LB Policy's picker was updated after the previous pick attempt returned ErrNoSubConnAvailable." Or something?

I don't think this is the only case that this gets triggered (see list of 4 in https://github.com/grpc/grpc-go/blob/master/picker_wrapper.go#L87). Any other ideas?

Yeah, that's true. I was trying to keep it simple. The alternative would be something more vague like "PickerUpdated indicates that the LB policy provided a new picker while the RPC was waiting for one."

Let's do the more vague one?

Sure.. "picker finished picking if the CC blocks on picker picking" makes no sense to me 😛

Please update to something like PickerUpdated indicates that the LB policy provided a new picker while the RPC was waiting for one.

easwars · 2023-06-29T21:10:04Z

picker_wrapper.go

+				for _, sh := range pw.statsHandlers {
+					sh.HandleRPC(ctx, &stats.PickerUpdated{})
+				}
+


Nit: nix newline.

Ah whoops. Deleted newline.

easwars · 2023-06-29T21:10:45Z

picker_wrapper.go

@@ -125,6 +130,10 @@ func (pw *pickerWrapper) pick(ctx context.Context, failfast bool, info balancer.
 					return nil, balancer.PickResult{}, status.Error(codes.Canceled, errStr)
 				}
 			case <-ch:
+				for _, sh := range pw.statsHandlers {


Maybe a comment here or where statsHandler field is defined about what this is for and how this is used?

Added comment on field: statsHandlers []stats.Handler // to record blocking picker calls

easwars · 2023-06-29T21:14:05Z

stats/stats.go

+
+// IsClient indicates if the stats information is from client side. Only Client
+// Side interfaces with a resolver, thus always returns true.
+func (irr *InitialResolverResult) IsClient() bool { return true }


Minor nit for all these methods. Since the receiver is not used, we don't even have to name it. So, this can simply be:

func (*InitialResolverResult) IsClient() bool { return true }

Hmmmmm ok I was actually wondering that too. Deleted, thanks.

dfawley

LGTM modulo testing

dfawley · 2023-07-05T19:16:42Z

test/retry_test.go

@@ -579,7 +581,7 @@ func (s) TestRetryStats(t *testing.T) {
 	// There is a race between receiving the payload (triggered by the
 	// application / gRPC library) and receiving the trailer (triggered at the
 	// transport layer).  Adjust the received stats accordingly if necessary.
-	const tIdx, pIdx = 13, 14
+	const tIdx, pIdx = 15, 16


Existing tests should probably filter out PickerUpdated events entirely, unless we know they are deterministic in those tests. And we should have a new test with a custom LB policy that confirms those events work as intended.

dfawley · 2023-07-05T19:17:38Z

stats/stats.go

+// PickerUpdated represents an event that the picker finished picking if the
+// ClientConn blocks on picker picking while performing a RPC.


Sure.. "picker finished picking if the CC blocks on picker picking" makes no sense to me 😛

dfawley · 2023-07-06T20:56:31Z

test/end2end_test.go

+func (h *statsHandlerRecordEvents) HandleRPC(_ context.Context, s stats.RPCStats) {
+	h.mu.Lock()
+	h.s = append(h.s, s)
+	h.mu.Unlock()


Nit: defer as a matter of course is probably a good idea.

dfawley · 2023-07-06T20:58:08Z

test/end2end_test.go

+}
+
+func (bp *blockingPicker) Pick(pi balancer.PickInfo) (balancer.PickResult, error) {
+	defer bp.pickDone()


FWIW defer doesn't actually do anything different than just calling it directly.

Does that guarantee the first pick hits err sub conn available before the client conn processes the new picker? And thus deterministically induce this event?

Switched anyway. But this worries me. I guess the client conn has already called into the picker so the new one won't overwrite that call into component.

I'm not saying you must change it, but noting that the functionally it is identical. defer x(); return <no function call> is the same as x(); return <no function call>. If you did:

defer x() return y()

...it would be the same as:

blah := y() x() return blah

Right, I had a feeling. So does the fact that another picker comes before the ErrNoSubConnAvailable logically cause any problems? Does that make it deterministic or is it guaranteed to finish the processing from the picker callout?

dfawley · 2023-07-06T21:03:50Z

test/end2end_test.go

+    	}
+  	]
+	}`


Please fix formatting

It looks solid on local. Idk why it's showing up like this on Github diff. Let me mess with it.

I messed with it and I think it looks better now. Let me know what you think.

dfawley · 2023-07-06T21:05:17Z

test/end2end_test.go

+	if pickerUpdatedCount == 0 {
+		t.Fatalf("sh.pickerUpdated count: %v, want: >0", pickerUpdatedCount)
+	}


This should be able to be deterministic and more specific... == 1 or == 2.

Yeah, it was determinisitc at 2 but switched to this to make sure. Switched back to 2.

dfawley · 2023-07-06T21:08:26Z

test/end2end_test.go

+		// Shouldn't happen, defensive programming. Registered from import of
+		// roundrobin package.
+		return nil


panic here instead of returning nil and maybe invoking some other panic later. And below.

Actually this one isn't needed as builder.Build will just panic if builder is nil.

Done. Why does this matter philosophically though? Test crashes closer to root cause of the crash?

Because if it fails then you want it to fail as close to where the error is as possible. If you cause another failure somewhere else it's harder to debug.

dfawley · 2023-07-06T21:13:28Z

test/end2end_test.go

+}
+func (*statsHandlerRecordEvents) HandleConn(context.Context, stats.ConnStats) {}
+
+type blockingPicker struct {


Why is this called blocking? Is that because of it queues?

Yeah. Induces a block. I'll call it triggerRPCBlockPicker.

Also switched the balancer type names accordingly.

dfawley · 2023-07-06T21:17:03Z

test/end2end_test.go

+}
+
+// TestPickerBlockingStatsCall tests the emission of a stats handler call that
+// represents the picker had to block due to ErrNoSubConnAvailable being


Terminology nit: the picker doesn't block. I guess the blockingPicker blocks. But more accurately, the RPC blocks (or in C++/Java: is queued) waiting for a new picker from the LB policy.

Switched language accordingly :).

dfawley · 2023-07-06T23:48:12Z

stats/stats.go

+// PickerUpdated represents an event that the picker finished picking if the
+// ClientConn blocks on picker picking while performing a RPC.


Please update to something like PickerUpdated indicates that the LB policy provided a new picker while the RPC was waiting for one.

dfawley

It seems the test is still flaky...

dfawley · 2023-07-07T17:22:36Z

test/end2end_test.go

+}
+
+func (bpb *triggerRPCBlockBalancer) UpdateClientConnState(s balancer.ClientConnState) error {
+	bpb.blockingPickerDone = grpcsync.NewEvent()


Why is this per-updateCCS instead of created in Build?

dfawley · 2023-07-07T18:34:40Z

test/end2end_test.go

+				bpb.blockingPickerDone.Fire()
+				bpb.stateMu.Lock()
+				cs := bpb.childState
+				bpb.stateMu.Unlock()
+				bpb.ClientConn.UpdateState(cs)
+			},
+		},
+	})
+	return err
+}
+
+func (bpb *triggerRPCBlockBalancer) UpdateState(state balancer.State) {
+	bpb.stateMu.Lock()
+	bpb.childState = state
+	bpb.stateMu.Unlock()
+	if bpb.blockingPickerDone.HasFired() { // guard first one to get a picker sending ErrNoSubConnAvailable first
+		bpb.ClientConn.UpdateState(state) // after the first rr picker update, cc will trigger more, so actually forward these


This dance seems racy.

Maybe it should be:

func UpdateState() { Lock(); defer Unlock() if HasFired() { UpdateState() } else { childState = state } } pickDone: func() { Lock(); defer Unlock() Fire(); UpdateState(childState) }

?

Also, maybe we should not update the picker at all (except the initial one at Build or the first UpdateCCS call) until the state is READY. Otherwise we might get an unpredictable number of updates.

Done. I messed around with it to what it is now.

dfawley · 2023-07-18T16:34:49Z

picker_wrapper.go

+		// a new one, or a picker errored with ErrNoSubConnAvailable or errored
+		// with failfast set to false, which will trigger a continue to the next
+		// iteration. In that second case the only way it gets to this codeblock
+		// is to receive a new picker either in UpdateState or the select above.


This is confusing because a new picker is always received by UpdateState, not by the select. Maybe this sentence is: "In the latter case, we only reach this when there is a new picker."

And isn't this true in either of the two cases? Basically, we only reach this point when: 1. there is a picker immediately on the first iteration, or 2. we have a new picker available. That's why we grab the picker on the following lines. The if ch != nil filters out the first case where we never needed to block.

Yeah, I guess the language I had is technically incorrect, but I was going for it either UpdateState() before the next iteration or it UpdateState() while blocking on the <-ch if the new one didn't come before the for. Yeah, the first case (either it's there, or it's not and we block) gets there, with it being there already not triggering conditional, and not being there triggering conditional. However, I think that it is more easily implied by conditional, but let me reword the comment and see if you like it more technically.

dfawley · 2023-07-18T16:37:55Z

test/end2end_test.go

+	builder := balancer.Get(roundrobin.Name)
+	rr := builder.Build(b, bOpts)
+	if rr == nil {
+		// Shouldn't happen, defensive programming.


Nit: generally, commenting a panic with "this shouldn't happen" isn't helpful. Obviously it shouldn't happen or else we wouldn't have made it panic. You can say why it shouldn't happen if it's interesting, or just leave the comment out if it's obvious or if the panic explains it (which is better than having a comment explaining it).

Ah, whoops, this was left over from when this wasn't an explicit panic. Deleted comment.

dfawley · 2023-07-18T16:39:48Z

test/end2end_test.go

+	err := bpb.Balancer.UpdateClientConnState(balancer.ClientConnState{
+		ResolverState: s.ResolverState,
+	})


Why not pass s directly?

I wanted to eat the config and send down nil, but I guess this gets nil as the config. Switched.

dfawley · 2023-07-18T16:41:56Z

test/end2end_test.go

+				bpb.blockingPickerDone.Fire()
+				bpb.stateMu.Lock()
+				defer bpb.stateMu.Unlock()


Shouldn't the lock be taken before firing the event here? Otherwise you might race between this and a call from the balancer, and do the UpdateState twice. It doesn't lead to a correctness issue, but it does seem wrong.

Ah, right. Luckily it didn't lead to non determinism of the assertion of the test, because it triggers another for iteration from the continue from ErrNoSubConnAvailable and an extra UpdateState doesn't affect picker count. However, for the intention of this testing struct, it is incorrect in that I desired to send one UpdateState. Good catch, switched.

dfawley · 2023-07-18T16:44:14Z

test/end2end_test.go

+	serviceconfig.LoadBalancingConfig
+}
+
+type triggerRPCBlockBalancer struct {


Comment: // triggerRPCBlockBalancer uses a child RR balancer, but blocks all UpdateState calls from it until the first Pick call. That first pick returns ErrNoSubConnAvailable to make the RPC block and trigger the appropriate stats handler callout. or something

Added comment, alongside a little more. Thanks for suggestion.

dfawley · 2023-07-18T16:45:31Z

test/end2end_test.go

+	sc := internal.ParseServiceConfig.(func(string) *serviceconfig.ParseResult)(lbCfgJSON)
+	mr := manual.NewBuilderWithScheme("pickerupdatedbalancer")
+	defer mr.Close()
+	print("ss.Address when setting: ", ss.Address)


Remove or change to t.Log

Whoops, sorry, deleted.

Add trace events for blocking resolver resolve and blocking picker pick

942bdd9

zasweq requested a review from dfawley June 29, 2023 19:47

zasweq assigned dfawley Jun 29, 2023

zasweq added Type: Feature New features or improvements in behavior Type: Internal Cleanup Refactors, etc and removed Type: Internal Cleanup Refactors, etc labels Jun 29, 2023

zasweq added this to the 1.57 Release milestone Jun 29, 2023

zasweq changed the title ~~stats: Add events for blocking resolver resolve and blocking picker pick~~ stats: Add RPC events for blocking caused by the name resolver and the LB policy's picker Jun 29, 2023

Fix test

dc4e6b8

dfawley reviewed Jun 29, 2023

View reviewed changes

Fixed test and responded to Doug's comments

1361dcc

dfawley reviewed Jun 29, 2023

View reviewed changes

easwars reviewed Jun 29, 2023

View reviewed changes

zasweq added 2 commits June 30, 2023 16:24

Responded to review comments

e69d389

Remove resolver resolve event

5ec681a

dfawley assigned zasweq and unassigned dfawley Jul 5, 2023

Vet

ff3dda4

dfawley reviewed Jul 5, 2023

View reviewed changes

zasweq added 2 commits July 6, 2023 13:41

Save progress, tests work, need to cleanup

906ed7d

Cleanup

e6d27af

zasweq changed the title ~~stats: Add RPC events for blocking caused by the name resolver and the LB policy's picker~~ stats: Add RPC events for blocking caused by the LB policy's picker Jul 6, 2023

dfawley changed the title ~~stats: Add RPC events for blocking caused by the LB policy's picker~~ stats: Add RPC event for blocking caused by the LB policy's picker Jul 6, 2023

dfawley reviewed Jul 6, 2023

View reviewed changes

zasweq added 2 commits July 6, 2023 17:52

Responded to Doug's comments

00f02a5

Rename test

a5d9ad2

zasweq assigned dfawley and unassigned zasweq Jul 6, 2023

dfawley approved these changes Jul 6, 2023

View reviewed changes

dfawley requested changes Jul 7, 2023

View reviewed changes

dfawley reviewed Jul 7, 2023

View reviewed changes

Review comments

624eaf2

dfawley reviewed Jul 7, 2023

View reviewed changes

zasweq added 3 commits July 7, 2023 16:17

Deflake...hopefully

9fa6112

Deflake part 2 eleectric bugaloo

4685c89

Vet

7a796d9

zasweq assigned dfawley and unassigned dfawley Jul 7, 2023

easwars assigned zasweq and unassigned dfawley Jul 11, 2023

easwars modified the milestones: 1.57 Release, 1.58 Release Jul 14, 2023

Finally deflake

8e40bc1

zasweq assigned dfawley and unassigned zasweq Jul 18, 2023

Make comment better

e1a01c2

dfawley reviewed Jul 18, 2023

View reviewed changes

dfawley assigned zasweq and unassigned dfawley Jul 18, 2023

arvindbr8 assigned dfawley and unassigned zasweq Jul 18, 2023

Responded to Doug's comments

1daf196

dfawley approved these changes Jul 18, 2023

View reviewed changes

dfawley assigned zasweq and unassigned dfawley Jul 18, 2023

zasweq changed the title ~~stats: Add RPC event for blocking caused by the LB policy's picker~~ stats: Add RPC event for blocking for a picker update Jul 18, 2023

zasweq merged commit 7aab9c0 into grpc:master Jul 18, 2023
11 checks passed

zasweq mentioned this pull request Sep 6, 2023

trace grpc http requests via net/http/httptrace #6589

Closed

github-actions bot locked as resolved and limited conversation to collaborators Jan 15, 2024

		@@ -59,6 +59,27 @@ func (s *Begin) IsClient() bool { return s.Client }

		func (s *Begin) isRPCStats() {}

		// InitialResolverResult represents an event that the resolved finished

		// PickerUpdated represents an event that the picker finished picking if the
		// ClientConn blocks on picker picking while performing a RPC.

stats: Add RPC event for blocking for a picker update #6422

stats: Add RPC event for blocking for a picker update #6422

Conversation

zasweq commented Jun 29, 2023 • edited by dfawley

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

dfawley left a 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

dfawley left a 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

zasweq Jul 18, 2023 • edited

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

zasweq commented Jun 29, 2023 •

edited by dfawley

zasweq Jul 18, 2023 •

edited