apf: print watch initialization latency in httplog #105403

tkashem · 2021-10-01T14:27:51Z

What type of PR is this?

/kind bug

What this PR does / why we need it:

show watch initialization latency in httplog for watch requests

Which issue(s) this PR fixes:

Special notes for your reviewer:

Does this PR introduce a user-facing change?

NONE

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:

tkashem · 2021-10-01T14:28:28Z

/assign @wojtek-t @MikeSpreitzer

tkashem · 2021-10-01T14:33:09Z

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

+	if requestInfo, ok := apirequest.RequestInfoFrom(ctx); ok {
+		watch = strconv.FormatBool(requestInfo.Verb == "watch")
+	}
+	apiserverRequestExecutionSeconds.WithContext(ctx).WithLabelValues(priorityLevel, flowSchema, watch).Observe(executionTime.Seconds())


we could include the verb in the metric, but that would increase the cardinality. I think for this metric we probably don't care beyond whether it's a watch.

There are other long-running requests, but they currently do not contribute to this metric --- right? Perhaps we should future-proof by calling this label "long-running"?

You mean as a label in the metric? Yeah - that sgtm.

@tkashem - also - might be useful to split the metrics PR from the logs PR (the metrics will have release note, as suggest above, etc.).

if we want to future-proof it (assuming that at some point apf may account for long-running requests), then i would suggest renaming the label to type with values {'regular'|'watch'|'non-watch-long-running'} (for lack of better terms on my part) so we can differentiate between watch and non-watch long running requests.

I like it - let's change the label name to "type" and for now use:

"regular" [I'm not a fan of this name - but I don't have better alternative]

"watch"

If at some point we start supporting other calls, we can introduce new values.

I split the metrics into a separate PR - #105517 with release notes

wojtek-t · 2021-10-01T14:41:18Z

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

@@ -270,7 +272,7 @@ var (
 			Buckets:        requestDurationSecondsBuckets,
 			StabilityLevel: compbasemetrics.ALPHA,
 		},
-		[]string{priorityLevel, flowSchema},
+		[]string{priorityLevel, flowSchema, "watch"},


@logicalhan - I'm assuming we can still modify alpha-stability metrics?

This should be fine, but we should add a release note about it.

wojtek-t · 2021-10-01T14:42:13Z

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

@@ -176,6 +177,15 @@ func WithPriorityAndFairness(
 			}()

 			execute := func() {
+				startedAt := time.Now()
+				defer func() {
+					// TODO: Once PR#104557 merges, we can remove the 'klog.V(3).Enabled()' check.


Hmm - I'm not sure it will ever merge, because of : #104557 (comment)

now, it's not static - the filter is always enabled and i am checking runtime for each request if log level 3 is enabled, only then the httplog construct is initialized.

once #104920 merges I will ask David to remove the hold.

Yes, I think leaving the V(3).Enabled() check here permanently is fine.

With #104557 merged - let's address this now.

MikeSpreitzer · 2021-10-01T18:50:57Z

(1) I am starting to get concerned about how much debug information we are putting in the httplog line. Perhaps only do this at a higher -v level (perhaps 4)?

(2) I also wonder if we would prefer to get this information as a metric (a histogram of latencies) rather than in log messages.

tkashem · 2021-10-01T19:28:32Z

(1) I am starting to get concerned about how much debug information we are putting in the httplog line. Perhaps only do this at a higher -v level (perhaps 4)?

it would be nice to have it at all log levels where httplog is enabled, this is the only place where watch initialization latency is recorded in log. (We found an issue with apf watch accounting with aggregated types - please see #105409)

(2) I also wonder if we would prefer to get this information as a metric (a histogram of latencies) rather than in log messages.

well apiserver_flowcontrol_request_execution_seconds records watch initialization latency, but it is currently indistinguishable from latency of regular requests, this PR adds a new label named watch, it is set to true if it is from watch initialization.

tkashem · 2021-10-01T21:13:44Z

/test pull-kubernetes-e2e-gce-ubuntu-containerd

MikeSpreitzer

If nobody else complains about this, it is good enough for me.
Thanks.
/LGTM

fedebongio · 2021-10-05T20:08:21Z

/triage accepted

tkashem · 2021-10-06T15:33:57Z

oops, bad rebase, fixing it

tkashem · 2021-10-06T16:05:08Z

it's ready for another pass

wojtek-t · 2021-10-06T19:20:37Z

/lgtm
/approve

k8s-ci-robot · 2021-10-06T19:21:19Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: MikeSpreitzer, tkashem, 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

tkashem · 2021-10-06T22:36:08Z

/test pull-kubernetes-unit

MikeSpreitzer · 2021-10-06T23:09:13Z

/retest

tkashem changed the title ~~apf: print watch init latency in httplog~~ apf: print watch initialization latency in httplog Oct 1, 2021

k8s-ci-robot requested review from lavalamp and sttts October 1, 2021 14:28

k8s-ci-robot assigned MikeSpreitzer and wojtek-t Oct 1, 2021

tkashem commented Oct 1, 2021

View reviewed changes

wojtek-t reviewed Oct 1, 2021

View reviewed changes

MikeSpreitzer approved these changes Oct 4, 2021

View reviewed changes

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Oct 4, 2021

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 Oct 5, 2021

tkashem force-pushed the add-watch-init-latency branch from c9cabc8 to a18e1c5 Compare October 6, 2021 15:32

k8s-ci-robot removed the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Oct 6, 2021

k8s-ci-robot added the sig/auth Categorizes an issue or PR as relevant to SIG Auth. label Oct 6, 2021

apf: print watch init latency in httplog

9b21e11

tkashem force-pushed the add-watch-init-latency branch from a18e1c5 to 9b21e11 Compare October 6, 2021 15:37

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Oct 6, 2021

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Oct 6, 2021

k8s-ci-robot merged commit 5c3a789 into kubernetes:master Oct 7, 2021

k8s-ci-robot added this to the v1.23 milestone Oct 7, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

apf: print watch initialization latency in httplog #105403

apf: print watch initialization latency in httplog #105403

tkashem commented Oct 1, 2021 •

edited

tkashem commented Oct 1, 2021

tkashem Oct 1, 2021

MikeSpreitzer Oct 1, 2021

wojtek-t Oct 4, 2021

tkashem Oct 4, 2021 •

edited

wojtek-t Oct 5, 2021

tkashem Oct 6, 2021

wojtek-t Oct 1, 2021

logicalhan Oct 1, 2021

wojtek-t Oct 1, 2021

tkashem Oct 1, 2021

MikeSpreitzer Oct 1, 2021

wojtek-t Oct 6, 2021

MikeSpreitzer commented Oct 1, 2021 •

edited

tkashem commented Oct 1, 2021 •

edited

tkashem commented Oct 1, 2021

MikeSpreitzer left a comment

fedebongio commented Oct 5, 2021

tkashem commented Oct 6, 2021 •

edited

tkashem commented Oct 6, 2021

wojtek-t commented Oct 6, 2021

k8s-ci-robot commented Oct 6, 2021

tkashem commented Oct 6, 2021

MikeSpreitzer commented Oct 6, 2021

apf: print watch initialization latency in httplog #105403

apf: print watch initialization latency in httplog #105403

Conversation

tkashem commented Oct 1, 2021 • edited

What type of PR is this?

What this PR does / why we need it:

Which issue(s) this PR fixes:

Special notes for your reviewer:

Does this PR introduce a user-facing change?

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:

tkashem commented Oct 1, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tkashem Oct 4, 2021 • 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

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 commented Oct 1, 2021 • edited

tkashem commented Oct 1, 2021 • edited

tkashem commented Oct 1, 2021

MikeSpreitzer left a comment

Choose a reason for hiding this comment

fedebongio commented Oct 5, 2021

tkashem commented Oct 6, 2021 • edited

tkashem commented Oct 6, 2021

wojtek-t commented Oct 6, 2021

k8s-ci-robot commented Oct 6, 2021

tkashem commented Oct 6, 2021

MikeSpreitzer commented Oct 6, 2021

tkashem commented Oct 1, 2021 •

edited

tkashem Oct 4, 2021 •

edited

MikeSpreitzer commented Oct 1, 2021 •

edited

tkashem commented Oct 1, 2021 •

edited

tkashem commented Oct 6, 2021 •

edited