Return dynamic RetryAfter header from APF #117547

wojtek-t · 2023-04-24T08:42:27Z

NONE

/kind feature
/sig api-machinery
/priority important-longterm

wojtek-t · 2023-04-24T08:44:02Z

@MikeSpreitzer @tkashem @deads2k - FYI

cici37 · 2023-04-25T20:12:35Z

/triage accepted

cici37 · 2023-04-25T20:12:42Z

/cc @deads2k

MikeSpreitzer · 2023-05-01T18:58:03Z

/cc @MikeSpreitzer

MikeSpreitzer

Why Fibonacci numbers?

Why not an exponential slow-down and linear speeed-up, as in TCP window sizes?

MikeSpreitzer · 2023-05-02T03:14:13Z

staging/src/k8s.io/apiserver/pkg/server/filters/priority-and-fairness.go

+		workEstimator:           workEstimator,
+		droppedRequests:         utilflowcontrol.NewDroppedRequestsTracker(),
+	}
+	return http.HandlerFunc(priorityAndFairnessHandler.Handle)


Instead we could just return priorityAndFairnessHandler if its method were named ServeHTTP rather than Handle, right?

True - but that wouldn't change much here..

It would make no change at all that matters to the rest of the code, just a simplification here.

MikeSpreitzer · 2023-05-02T03:32:38Z

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker.go

+	}
+}
+
+// recomputeRetryAfter is checking if retryAfter shouldn't be adjusted.


This sentence and the others that refer to "retryAfter" are confusing to the reader at this point, who does not see a variable or field named "retryAfter". I suggest adding a comment on droppedRequestsStats.currentRetryAfterStep explaining that retryAfter = retryAfterSteps[droppedRequestsStats.currentRetryAfterStep].

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker.go

MikeSpreitzer · 2023-05-02T03:35:32Z

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker.go

+	history []unixStat
+
+	currentRetryAfterStep int
+	retryAfterUpdateUnix  int64


Suggested change

retryAfterUpdateUnix int64

// retryAfterUpdateUnix is the time when currentRetryAfterStep was last updated, in seconds since Unix epoch.

retryAfterUpdateUnix int64

MikeSpreitzer · 2023-05-02T03:37:20Z

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker.go

+//   requests.
+func (s *droppedRequestsStats) recomputeRetryAfter(unixTime int64) {
+	retryAfter := retryAfterSteps[s.currentRetryAfterStep]
+


This could be written less redundantly.
First, early out if enough time since retryAfterUpdateUnix has not passed.
Otherwise compute the doppedRequests sum, then compare with the high and low threshholds.

MikeSpreitzer · 2023-05-02T03:39:47Z

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker.go

+	// maxHistory represents what is the maximum history of dropped
+	// requests stored per priority level.


Suggested change

// maxHistory represents what is the maximum history of dropped

// requests stored per priority level.

// maxHistory is the age threshhold, in seconds, for discarding dropped requests history for a given priority level.

MikeSpreitzer · 2023-05-02T03:40:24Z

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker.go

+const (
+	// maxHistory represents what is the maximum history of dropped
+	// requests stored per priority level.
+	maxHistory = 30


Why keep stuff 29 seconds old when the logic never looks at anything older than 13 seconds?

MikeSpreitzer · 2023-05-02T03:50:08Z

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker.go

+// for the purpose of adjusting RetryAfter header for newly dropped
+// requests to avoid system overload.
+type droppedRequestsTracker struct {
+	clock clock.Clock


You don't need a whole Clock here, a PassiveClock or func() time.Time will do.

wojtek-t · 2023-05-08T11:52:30Z

@MikeSpreitzer - I added tests, PTAL

MikeSpreitzer · 2023-05-08T15:24:01Z

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker.go

+	for _, h := range s.history {
+		if unixTime-h.unixTime < retryAfter {


If this slice were traversed in the reverse order then there could be an early out as soon as the time threshold has been passed.

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker_test.go

MikeSpreitzer · 2023-05-08T15:33:24Z

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker_test.go

+	steps := []struct {
+		secondsElapsed  int
+		droppedRequests int
+		retryAfter      int64


Suggested change

retryAfter int64

// Expected value after the _first_ call to RecordDroppedRequest

retryAfter int64

wojtek-t

Comments applied - PTAL

wojtek-t · 2023-05-08T15:35:14Z

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker.go

+	for _, h := range s.history {
+		if unixTime-h.unixTime < retryAfter {


wojtek-t · 2023-05-08T15:35:21Z

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker_test.go

+	steps := []struct {
+		secondsElapsed  int
+		droppedRequests int
+		retryAfter      int64


staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker_test.go

MikeSpreitzer · 2023-05-08T15:40:03Z

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker.go

+		return
+	}
+
+	if droppedRequests < retryAfter {


According to the comment currently at lines 121--126, this condition needs && unixTime-s.retryAfterUpdateUnix >= retryAfter

I consciously decided not to rate-limit decreases (they will kind-of self-rate-limit after bumps anyway).
Fixed the comment.

So that means that both slow-down and speed-up happen at the same rate (amortized over adjacent time), the slow-downs are just more jumpy. The net result is that retryAfter goes up and goes down at one second per second (but the up changes are clumped).

Well - it depends on what exactly is happening. Note that the treshold for increasing retryAfter is much higher (3retryAfter) than for decreasing it (1retryAfter), so while going down can potentially be smoother, it generally will take more time.

That factor of 3 is the threshold for making a change, but the change is a factor of 2. So, apart from the fact that the increases are batched, both the ramp up and the ramp down goes --- at a maximum --- at the same amortized rate: 1 second per second.

MikeSpreitzer · 2023-05-08T15:50:19Z

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker.go

+	// However, given that we didn't report anything for the current second,
+	// we recompute it based on statistics from the previous one.
+	s.updateRetryAfterIfNeededLocked(unixTime - 1)


Even so, subtracting one here is confusing. Consider an example.

Suppose a drop happens at T=5.1 seconds, and the previous drop was at 4.something. This code will now trigger.

updateRetryAfterIfNeededLocked gets called with 4.

If it makes an update, it sets s.retryAfterUpdateUnix to 4.

I think it makes perfect sense to call updateRetryAfterIfNeededLocked(5) in that case. That is saying to think about what happened up to T=5.0, which is what you mean. More precisely, the logic would be working with half-open intervals: [retryAfterUpdateUnix.0, retryAfterUpdateUnix.0+retryAfter).

MikeSpreitzer · 2023-05-08T16:44:32Z

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker_test.go

+	// The following table represents the list over time of:
+	// - seconds elapsed (as computed since the initial time)
+	// - requests that will be recorded as dropped in a current second


I find the current design of the test cases to be harder to think about than I think is necessary. The usual design of a test case is that it says "do this then expect that" (for some this and that). The current design does not follow that pattern. I would find it easier to think about these test cases if the secondsElapsed and droppedRequests prescribed dropping at a steady rate (secondsElapsed/droppedRequests between drops, with no drop at the start and a drop at the end); that would make a coherent "do this" part and it would precede the "expect that" part. (Of course the actual test cases would need some editing to work with this definition.)

I don't think that steady-rate is really needed (it will uneccessary complicate the test).

But I think the rest of this comment makes sense (i.e. redoing it to be more like "do this, expect that". Will try to fix that tomorrow.

I fixed the test to actually verify RetryAfter after dropping all requests. This makes it more intuitive and doesn't change much.

PTAL

aojea · 2023-05-09T06:25:04Z

IIUIC this will have an interesting interaction with the "internal requests" we have in client-go , since the timeout of a request accounts for the whole original request #117313, now the retry times will increase so most probable will "retry less"

wojtek-t · 2023-05-09T09:34:24Z

IIUIC this will have an interesting interaction with the "internal requests" we have in client-go , since the timeout of a request accounts for the whole original request #117313, now the retry times will increase so most probable will "retry less"

This is true, but if you're explicitly requesting a client-side timeout for the request, that's actually desired. I don't perceive it as a problem, but rather as a natural consequence.

wojtek-t

@MikeSpreitzer - PTAL

wojtek-t · 2023-05-09T09:41:19Z

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker_test.go

+	// The following table represents the list over time of:
+	// - seconds elapsed (as computed since the initial time)
+	// - requests that will be recorded as dropped in a current second


I fixed the test to actually verify RetryAfter after dropping all requests. This makes it more intuitive and doesn't change much.

PTAL

MikeSpreitzer · 2023-05-15T18:14:25Z

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker.go

+	retryAfter := s.retryAfter.Load()
+
+	droppedRequests := int64(0)
+	if len(s.history) > 0 {


This conditionality is not needed because len(s.history) - 1 would evaluate to the int -1 the excluded case, right?

MikeSpreitzer · 2023-05-15T18:16:33Z

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker.go

+	s.history = append(s.history, unixStat{unixTime: unixTime, requests: count})
+
+	startIndex := 0
+	for ; startIndex < len(s.history) && unixTime-s.history[startIndex].unixTime > maxRetryAfter; startIndex++ {


Entries whose age equals or exceeds 2 * s.retryAfter are also never going to be needed.

MikeSpreitzer · 2023-05-15T18:20:00Z

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker_test.go

+		}
+		fakeClock.Step(time.Duration(secondsToAdvance) * time.Second)
+
+		// Record only first dropped request and recompute retryAfter.


This comment is out of date

MikeSpreitzer

/lgtm

This is an improvement. More can be done in follow-on.

k8s-ci-robot · 2023-05-15T18:21:51Z

LGTM label has been added.

Git tree hash: 039423f5b5deaef2ebe2d83e9da0fd531d5a479e

k8s-ci-robot · 2023-05-15T18:22:31Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: MikeSpreitzer, wojtek-t

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~staging/src/k8s.io/apiserver/OWNERS~~ [wojtek-t]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

k8s-ci-robot requested review from sttts and yue9944882 April 24, 2023 08:51

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Apr 24, 2023

k8s-ci-robot added triage/accepted Indicates an issue or PR is ready to be actively worked on. and removed needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. labels Apr 25, 2023

k8s-ci-robot requested a review from deads2k April 25, 2023 20:12

k8s-ci-robot requested a review from MikeSpreitzer May 1, 2023 18:58

MikeSpreitzer reviewed May 2, 2023

View reviewed changes

dims removed the do-not-merge/needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. label May 3, 2023

wojtek-t mentioned this pull request May 4, 2023

Better mechanism to decide Retry-After header #117734

Closed

MikeSpreitzer mentioned this pull request May 5, 2023

Implement watch limit in APF #117777

Open

wojtek-t force-pushed the apf_dynamic_retry_after branch 2 times, most recently from 467e24e to 60661ae Compare May 5, 2023 09:18

k8s-ci-robot removed the lgtm "Looks good to me", indicates that a PR is ready to be merged. label May 8, 2023

k8s-ci-robot requested a review from MikeSpreitzer May 8, 2023 11:51

wojtek-t changed the title ~~[WIP] Return dynamic RetryAfter header from APF~~ Return dynamic RetryAfter header from APF May 8, 2023

k8s-ci-robot removed the do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. label May 8, 2023

MikeSpreitzer reviewed May 8, 2023

View reviewed changes

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/dropped_requests_tracker_test.go Show resolved Hide resolved

MikeSpreitzer reviewed May 8, 2023

View reviewed changes

wojtek-t force-pushed the apf_dynamic_retry_after branch from 85b1762 to 3c49019 Compare May 8, 2023 15:35

wojtek-t commented May 8, 2023

View reviewed changes

MikeSpreitzer reviewed May 8, 2023

View reviewed changes

wojtek-t force-pushed the apf_dynamic_retry_after branch from 3c49019 to 9bd60c7 Compare May 8, 2023 18:58

APF: Dynamically compute retry-after based on history

23ac0fd

wojtek-t commented May 9, 2023

View reviewed changes

wojtek-t force-pushed the apf_dynamic_retry_after branch from 9bd60c7 to 23ac0fd Compare May 9, 2023 09:42

MikeSpreitzer reviewed May 15, 2023

View reviewed changes

MikeSpreitzer approved these changes May 15, 2023

View reviewed changes

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label May 15, 2023

k8s-ci-robot merged commit 2a4bf45 into kubernetes:master May 15, 2023
11 of 12 checks passed

k8s-ci-robot added this to the v1.28 milestone May 15, 2023

wojtek-t mentioned this pull request May 26, 2023

Follow up from dynamic retryAfter #118282

Merged

tkashem mentioned this pull request Oct 5, 2023

apf queue wait time for a request exceeds the hard-coded 15s threshold #119799

Closed

	retryAfterUpdateUnix int64
	// retryAfterUpdateUnix is the time when currentRetryAfterStep was last updated, in seconds since Unix epoch.
	retryAfterUpdateUnix int64

		// maxHistory represents what is the maximum history of dropped
		// requests stored per priority level.

	// maxHistory represents what is the maximum history of dropped
	// requests stored per priority level.
	// maxHistory is the age threshhold, in seconds, for discarding dropped requests history for a given priority level.

		for _, h := range s.history {
		if unixTime-h.unixTime < retryAfter {

	retryAfter int64
	// Expected value after the _first_ call to RecordDroppedRequest
	retryAfter int64

Return dynamic RetryAfter header from APF #117547

Return dynamic RetryAfter header from APF #117547

Conversation

wojtek-t commented Apr 24, 2023

wojtek-t commented Apr 24, 2023

cici37 commented Apr 25, 2023

cici37 commented Apr 25, 2023

MikeSpreitzer commented May 1, 2023

MikeSpreitzer 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

wojtek-t commented May 8, 2023

MikeSpreitzer May 8, 2023 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

MikeSpreitzer May 8, 2023 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

wojtek-t 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

MikeSpreitzer May 8, 2023 • edited

Choose a reason for hiding this comment

MikeSpreitzer May 8, 2023 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

aojea commented May 9, 2023

wojtek-t commented May 9, 2023

wojtek-t 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

MikeSpreitzer left a comment

Choose a reason for hiding this comment

k8s-ci-robot commented May 15, 2023

k8s-ci-robot commented May 15, 2023

MikeSpreitzer May 8, 2023 •

edited

MikeSpreitzer May 8, 2023 •

edited

MikeSpreitzer May 8, 2023 •

edited

MikeSpreitzer May 8, 2023 •

edited