track latency incurred in various layers of apiserver #107910

tkashem · 2022-02-01T23:19:33Z

What type of PR is this?

/kind feature

What this PR does / why we need it:

track latency incurred in various components within the apiserver, for example, storage layer, transformation of response object, http.ResponseWriter.Write and admission webhooks
and annotate the latency in audit event

{
  "kind": "Event",
  "apiVersion": "audit.k8s.io/v1",
  "level": "Metadata",
  "stage": "ResponseComplete",
  
  "requestReceivedTimestamp": "2022-03-24T21:38:52.741392Z",
  "stageTimestamp": "2022-03-24T21:38:52.743090Z",
  "annotations": {
    "apiserver.latency.k8s.io/etcd": "1.138415ms",
    "apiserver.latency.k8s.io/response-write": "415ns",
    "apiserver.latency.k8s.io/serialize-response-object": "28.677µs",
    "apiserver.latency.k8s.io/total": "1.698553ms",
    "apiserver.latency.k8s.io/transform-response-object": "1.41µs",
}

Which issue(s) this PR fixes:

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 · 2022-02-02T20:08:35Z

/assign @deads2k @wojtek-t @dgrisonnet

tkashem · 2022-02-02T20:09:54Z

@wojtek-t Is it possible to decorate from the watch cache layer and down?

fedebongio · 2022-02-03T17:36:44Z

/triage accepted

tkashem · 2022-02-03T18:51:31Z

/retest

tkashem · 2022-03-24T22:08:26Z

staging/src/k8s.io/apiserver/pkg/storage/etcd3/latency_tracker.go

+// NewETCDLatencyTracker returns an implementation of
+// clientv3.KV that times the calls from the specified
+// 'delegate' KV instance in order to track latency incurred.
+func NewETCDLatencyTracker(delegate clientv3.KV) clientv3.KV {


instead of tapping into storage.Interface, I am now tapping into etcd3 client KV so we can measure latency from etcd3 round trips only

deads2k · 2022-03-25T13:54:24Z

staging/src/k8s.io/apiserver/pkg/storage/etcd3/latency_tracker.go

+}
+
+type clientV3TxnTracker struct {
+	ctx context.Context


blech. Exists in the etcd client though, so I think we're stuck.

deads2k · 2022-03-25T13:55:37Z

/lgtm

deads2k · 2022-03-25T13:55:42Z

/approve

k8s-ci-robot · 2022-03-25T13:56:20Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: deads2k, tkashem

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~~ [deads2k]

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

tkashem · 2022-03-25T15:05:29Z

Test started today at 9:59 AM failed after 46m30s.
133/133 Tests Passed!

a timeout in some other layer, may be in collection of artifatcs?

/test pull-kubernetes-integration

aojea · 2022-03-25T15:18:19Z

a timeout in some other layer, may be in collection of artifatcs?

I think this PR is doing something to the etcd client that is making it fail

/hold

https://storage.googleapis.com/kubernetes-jenkins/pr-logs/pull/107910/pull-kubernetes-integration/1507356118538522624/build-log.txt

aojea · 2022-03-25T15:51:52Z

a timeout in some other layer, may be in collection of artifatcs?

I think this PR is doing something to the etcd client that is making it fail

/hold

https://storage.googleapis.com/kubernetes-jenkins/pr-logs/pull/107910/pull-kubernetes-integration/1507356118538522624/build-log.txt

now it went through, let me give it another shot to see if that was unrelated to this PR, I will unhold

Sorry for holding it but this job is very sensible to things that impact apiserver resource usage, I just wanted to be completely sure 😄

/test pull-kubernetes-integration

logicalhan · 2022-03-25T15:57:57Z

staging/src/k8s.io/apiserver/pkg/endpoints/request/webhook_duration.go

+
+	annotations := map[string]string{}
+	if latency := tracker.TransformTracker.GetLatency(); latency != 0 {
+		annotations["apiserver.latency.k8s.io/transform-response-object"] = latency.String()


sorry for the late nit: can we use consts for these strings and use those when we retrieve values? I see spots in the PR where we assume that the key is there if the annotations map is returned but a small bug in the key could cause a NPE.

@logicalhan we don't retrieve by key name where the annotations are returned. it added "apiserver.latency.k8s.io/total" key to the annotations map if it wan non-empty, but I changed it a bit so that the annotations map returned is not mutated (that seems a better pattern)
With this i don't see any need to use const since these key names are are not referred to anywhere else.

// record the total latency for this request, for convenience. - layerLatencies["apiserver.latency.k8s.io/total"] = latency.String() + audit.LogAnnotation(ev, "apiserver.latency.k8s.io/total", latency.String()) for k, v := range layerLatencies { audit.LogAnnotation(ev, k, v) }

but if you think having these key names in one place is more readable, I can make this change :)

nah it's fine then, thanks!
/lgtm

@logicalhan the keys have been moved to consts now, ptal

aojea · 2022-03-25T16:24:40Z

@tkashem but you have a new comment #107910 (comment)

you are free to unhold, the job has started to be unstable since a few hours , so is not because of this PR
Thanks

tkashem · 2022-03-25T16:32:37Z

i did a force push, this is the only change.

        // record the total latency for this request, for convenience.
-       layerLatencies["apiserver.latency.k8s.io/total"] = latency.String()
+       audit.LogAnnotation(ev, "apiserver.latency.k8s.io/total", latency.String())
        for k, v := range layerLatencies {
                audit.LogAnnotation(ev, k, v)
        }

aojea · 2022-03-25T16:50:46Z

/hold cancel

logicalhan

/lgtm

k8s-ci-robot requested review from lavalamp and smarterclayton February 1, 2022 23:21

tkashem force-pushed the latency-breakdown branch 3 times, most recently from d5cd2b2 to 740bb81 Compare February 2, 2022 19:43

tkashem changed the title ~~[WIP] track latency~~ track latency incurred in various layers of apiserver Feb 2, 2022

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 Feb 2, 2022

k8s-ci-robot assigned deads2k, dgrisonnet and wojtek-t Feb 2, 2022

tkashem force-pushed the latency-breakdown branch 2 times, most recently from bc6611c to 7eb7f54 Compare February 3, 2022 17:34

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 Feb 3, 2022

tkashem commented Mar 24, 2022

View reviewed changes

tkashem force-pushed the latency-breakdown branch from 2db240a to 9a12077 Compare March 25, 2022 12:10

deads2k reviewed Mar 25, 2022

View reviewed changes

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Mar 25, 2022

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Mar 25, 2022

k8s-ci-robot added the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Mar 25, 2022

logicalhan reviewed Mar 25, 2022

View reviewed changes

tkashem force-pushed the latency-breakdown branch from 9a12077 to 7583bfa Compare March 25, 2022 16:32

k8s-ci-robot removed the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Mar 25, 2022

k8s-ci-robot assigned logicalhan Mar 25, 2022

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Mar 25, 2022

tkashem added 2 commits March 25, 2022 12:45

add latency tracker for storage and transform

eca9085

track latency for http.ResponseWriter.Write

1d1a44c

k8s-ci-robot removed the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Mar 25, 2022

tkashem force-pushed the latency-breakdown branch from 7583bfa to 1d1a44c Compare March 25, 2022 16:51

k8s-ci-robot removed the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Mar 25, 2022

logicalhan reviewed Mar 25, 2022

View reviewed changes

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Mar 25, 2022

k8s-ci-robot merged commit 84bd51c into kubernetes:master Mar 25, 2022

k8s-ci-robot added this to the v1.24 milestone Mar 25, 2022

dgrisonnet mentioned this pull request Mar 31, 2022

Add verb, resource, subresource to apiserver_flowcontrol_request_execution_seconds #109110

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

track latency incurred in various layers of apiserver #107910

track latency incurred in various layers of apiserver #107910

tkashem commented Feb 1, 2022 •

edited

tkashem commented Feb 2, 2022

tkashem commented Feb 2, 2022 •

edited

fedebongio commented Feb 3, 2022

tkashem commented Feb 3, 2022

tkashem Mar 24, 2022

deads2k Mar 25, 2022

deads2k commented Mar 25, 2022

deads2k commented Mar 25, 2022

k8s-ci-robot commented Mar 25, 2022

tkashem commented Mar 25, 2022 •

edited

aojea commented Mar 25, 2022

aojea commented Mar 25, 2022

logicalhan Mar 25, 2022

tkashem Mar 25, 2022 •

edited

tkashem Mar 25, 2022 •

edited

logicalhan Mar 25, 2022

tkashem Mar 25, 2022

logicalhan Mar 25, 2022

aojea commented Mar 25, 2022

tkashem commented Mar 25, 2022 •

edited

aojea commented Mar 25, 2022

logicalhan left a comment

track latency incurred in various layers of apiserver #107910

track latency incurred in various layers of apiserver #107910

Conversation

tkashem commented Feb 1, 2022 • 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 Feb 2, 2022

tkashem commented Feb 2, 2022 • edited

fedebongio commented Feb 3, 2022

tkashem commented Feb 3, 2022

tkashem Mar 24, 2022

Choose a reason for hiding this comment

deads2k Mar 25, 2022

Choose a reason for hiding this comment

deads2k commented Mar 25, 2022

deads2k commented Mar 25, 2022

k8s-ci-robot commented Mar 25, 2022

tkashem commented Mar 25, 2022 • edited

aojea commented Mar 25, 2022

aojea commented Mar 25, 2022

logicalhan Mar 25, 2022

Choose a reason for hiding this comment

tkashem Mar 25, 2022 • edited

Choose a reason for hiding this comment

tkashem Mar 25, 2022 • edited

Choose a reason for hiding this comment

logicalhan Mar 25, 2022

Choose a reason for hiding this comment

tkashem Mar 25, 2022

Choose a reason for hiding this comment

logicalhan Mar 25, 2022

Choose a reason for hiding this comment

aojea commented Mar 25, 2022

tkashem commented Mar 25, 2022 • edited

aojea commented Mar 25, 2022

logicalhan left a comment

Choose a reason for hiding this comment

tkashem commented Feb 1, 2022 •

edited

tkashem commented Feb 2, 2022 •

edited

tkashem commented Mar 25, 2022 •

edited

tkashem Mar 25, 2022 •

edited

tkashem Mar 25, 2022 •

edited

tkashem commented Mar 25, 2022 •

edited