Added tracing for long running requests. #69756

cheftako · 2018-10-13T00:41:43Z

What this PR does / why we need it:
Adds tracing for use apiserver requests (get etc) where etcd is not the cause of the long running
requests.

Which issue(s) this PR fixes (optional, in fixes #<issue number>(, fixes #<issue_number>, ...) format, will close the issue(s) when PR gets merged):
Fixes #69748

Special notes for your reviewer:

Release note:

NONE

neolit123 · 2018-10-13T14:45:31Z

do we need a release note?
/kind feature

cheftako · 2018-10-15T05:20:35Z

@neolit123 Historically trace PRs such as #44667 have not needed release notes. This change should only be adding logging to help debug long running requests. Is there a particular part of the change you feel we need to warn customers about?

neolit123 · 2018-10-15T09:01:14Z

@cheftako ok, sounds good.

cheftako · 2018-10-15T19:51:03Z

/test pull-kubernetes-integration

fedebongio · 2018-10-15T20:12:44Z

/assign @wojtek-t

wojtek-t · 2018-10-16T08:25:55Z

staging/src/k8s.io/apiserver/pkg/endpoints/handlers/delete.go

 		transformResponseObject(ctx, scope, req, w, status, result)
 	}
 }

 // DeleteCollection returns a function that will handle a collection deletion
 func DeleteCollection(r rest.CollectionDeleter, checkBody bool, scope RequestScope, admit admission.Interface) http.HandlerFunc {
 	return func(w http.ResponseWriter, req *http.Request) {
+		trace := utiltrace.New("Delete " + req.URL.Path)
+		defer trace.LogIfLong(1000 * time.Millisecond)


For consistency with all other requests *create/update", maybe 500ms (we use 500ms there)?

Quick question. On the other collection operations we do 500ms but we start them later in the operation. https://github.com/kubernetes/apiserver/blob/master/pkg/endpoints/handlers/get.go#L260 for example skips any watch latency.
I can certainly change to 500ms but I am wondering if that may trigger to often on collection requests which are expected to take longer.

Yes - get is special, so let's ignore it.

But for both create:
https://github.com/kubernetes/apiserver/blob/master/pkg/endpoints/handlers/create.go#L47
and update:
https://github.com/kubernetes/apiserver/blob/master/pkg/endpoints/handlers/update.go#L49

we start at exactly the same place and use 500ms.

So I think we should be consistent.

wojtek-t · 2018-10-16T08:30:00Z

staging/src/k8s.io/apiserver/pkg/endpoints/handlers/response.go

 	mediaType, _, err := negotiation.NegotiateOutputMediaType(req, scope.Serializer, &scope)
 	if err != nil {
 		status := responsewriters.ErrorToAPIStatus(err)
+		trace.Step("Writing raw JSON response")


I think this one won't provide much value - negotiation is really fast.

Granted but I suspect that some of the time the problem is actually writing the response to the requester. As such I would like a tight bracket around the "responsewriters.WriteRawJSON(int(status.Code), status, w)" call.

Yes - writing response is many times dominating factor - I completely agree that.

I completely wasn't clear what I wanted to say - sorry for that.
My point was that - the time between "negotiating output media type" and this step should be negligible.

So given that your point is completely correct, I think what I wanted to say is to:

leave this one (to see whether we spent time here)

but remove the "negotiating output media type" step (since different between this one and that should be negligible).

Does it make sense now?

wojtek-t · 2018-10-16T08:33:20Z

staging/src/k8s.io/apiserver/pkg/endpoints/handlers/response.go

 			_, info, err := negotiation.NegotiateOutputMediaType(req, metainternalversion.Codecs, &scope)
 			if err != nil {
 				scope.err(err, w, req)
 				return
 			}
 			encoder := metainternalversion.Codecs.EncoderForVersion(info.Serializer, metav1beta1.SchemeGroupVersion)
+			trace.Step(fmt.Sprintf("Serializing response as type %s", info.MediaType))


I'm 99,9% sure that all the time will spent after this.

So TBH, I would skip the previous steps (as tracing itself has some overhead) and leave just this one...

Again trying to get a tight bracket around the "responsewriters.SerializeObject(info.MediaType, encoder, w, req, statusCode, partial)" call.

Same point here (sorry for being completely unclear on that).

I completely agree that this Step has value.
I just suggest removing those previous two ones (that should be negligible):

trace.Step("Getting object kind, setting GVK")

trace.Step("Renegotiating internal version")

wojtek-t · 2018-10-16T08:34:11Z

staging/src/k8s.io/apiserver/pkg/endpoints/handlers/response.go

@@ -95,12 +102,14 @@ func transformResponseObject(ctx context.Context, scope RequestScope, req *http.
 			}

 			// renegotiate under the internal version
+			trace.Step("Renegotiating internal version")


Same with this one.

Happy to drop this one.

I think this is now inline with the previous comments - so please drop this and the one mentioned below.

wojtek-t · 2018-10-16T08:35:23Z

staging/src/k8s.io/apiserver/pkg/endpoints/handlers/response.go

@@ -150,25 +162,30 @@ func transformResponseObject(ctx context.Context, scope RequestScope, req *http.
 			}

 			// renegotiate under the internal version
+			trace.Step("Renegotiating internal version")


Same with this one.

wojtek-t · 2018-10-16T08:35:30Z

staging/src/k8s.io/apiserver/pkg/endpoints/handlers/response.go

 			responsewriters.SerializeObject(info.MediaType, encoder, w, req, statusCode, table)
 			return

 		default:
 			// this block should only be hit if scope AllowsConversion is incorrect
+			trace.Step("Renegotiating internal version")


logicalhan · 2018-10-16T18:17:45Z

/lgtm

k8s-ci-robot · 2018-10-16T18:17:53Z

@logicalhan: changing LGTM is restricted to assignees, and only kubernetes/kubernetes repo collaborators may be assigned issues.

In response to this:

/lgtm

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

wojtek-t

Sorry for being extremely unclear with what I meant - I hope now it's more clear what i wanted to write.

wojtek-t · 2018-10-17T07:57:18Z

staging/src/k8s.io/apiserver/pkg/endpoints/handlers/delete.go

 		transformResponseObject(ctx, scope, req, w, status, result)
 	}
 }

 // DeleteCollection returns a function that will handle a collection deletion
 func DeleteCollection(r rest.CollectionDeleter, checkBody bool, scope RequestScope, admit admission.Interface) http.HandlerFunc {
 	return func(w http.ResponseWriter, req *http.Request) {
+		trace := utiltrace.New("Delete " + req.URL.Path)
+		defer trace.LogIfLong(1000 * time.Millisecond)


Yes - get is special, so let's ignore it.

But for both create:
https://github.com/kubernetes/apiserver/blob/master/pkg/endpoints/handlers/create.go#L47
and update:
https://github.com/kubernetes/apiserver/blob/master/pkg/endpoints/handlers/update.go#L49

we start at exactly the same place and use 500ms.

So I think we should be consistent.

wojtek-t · 2018-10-17T08:00:01Z

staging/src/k8s.io/apiserver/pkg/endpoints/handlers/response.go

 	mediaType, _, err := negotiation.NegotiateOutputMediaType(req, scope.Serializer, &scope)
 	if err != nil {
 		status := responsewriters.ErrorToAPIStatus(err)
+		trace.Step("Writing raw JSON response")


Yes - writing response is many times dominating factor - I completely agree that.

I completely wasn't clear what I wanted to say - sorry for that.
My point was that - the time between "negotiating output media type" and this step should be negligible.

So given that your point is completely correct, I think what I wanted to say is to:

leave this one (to see whether we spent time here)

but remove the "negotiating output media type" step (since different between this one and that should be negligible).

Does it make sense now?

wojtek-t · 2018-10-17T08:01:12Z

staging/src/k8s.io/apiserver/pkg/endpoints/handlers/response.go

 			_, info, err := negotiation.NegotiateOutputMediaType(req, metainternalversion.Codecs, &scope)
 			if err != nil {
 				scope.err(err, w, req)
 				return
 			}
 			encoder := metainternalversion.Codecs.EncoderForVersion(info.Serializer, metav1beta1.SchemeGroupVersion)
+			trace.Step(fmt.Sprintf("Serializing response as type %s", info.MediaType))


Same point here (sorry for being completely unclear on that).

I completely agree that this Step has value.
I just suggest removing those previous two ones (that should be negligible):

trace.Step("Getting object kind, setting GVK")

trace.Step("Renegotiating internal version")

wojtek-t · 2018-10-17T08:02:05Z

staging/src/k8s.io/apiserver/pkg/endpoints/handlers/response.go

@@ -95,12 +102,14 @@ func transformResponseObject(ctx context.Context, scope RequestScope, req *http.
 			}

 			// renegotiate under the internal version
+			trace.Step("Renegotiating internal version")


I think this is now inline with the previous comments - so please drop this and the one mentioned below.

Added tracing for use cases where etcd is not the cause of long running requests. Fixed spelling. Factored in Wojtek-t feedback.

wojtek-t · 2018-10-29T07:50:24Z

/lgtm
/approve

k8s-ci-robot · 2018-10-29T07:50:32Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: cheftako, 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 added release-note-none Denotes a PR that doesn't merit a release note. size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Oct 13, 2018

k8s-ci-robot requested review from hzxuzhonghu and smarterclayton October 13, 2018 00:41

k8s-ci-robot added kind/feature Categorizes issue or PR as related to a new feature. and removed needs-kind Indicates a PR lacks a `kind/foo` label and requires one. labels Oct 13, 2018

cheftako force-pushed the trace branch from d2a7a97 to f4a3482 Compare October 15, 2018 17:35

k8s-ci-robot assigned wojtek-t Oct 15, 2018

wojtek-t reviewed Oct 16, 2018

View reviewed changes

wojtek-t reviewed Oct 17, 2018

View reviewed changes

Added tracing for long running requests.

99ebe87

Added tracing for use cases where etcd is not the cause of long running requests. Fixed spelling. Factored in Wojtek-t feedback.

cheftako force-pushed the trace branch from f4a3482 to 99ebe87 Compare October 29, 2018 07:38

k8s-ci-robot added size/S Denotes a PR that changes 10-29 lines, ignoring generated files. and removed size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Oct 29, 2018

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

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

k8s-ci-robot merged commit 833dcc2 into kubernetes:master Oct 29, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Added tracing for long running requests. #69756

Added tracing for long running requests. #69756

cheftako commented Oct 13, 2018

neolit123 commented Oct 13, 2018

cheftako commented Oct 15, 2018

neolit123 commented Oct 15, 2018

cheftako commented Oct 15, 2018

fedebongio commented Oct 15, 2018

wojtek-t Oct 16, 2018

cheftako Oct 16, 2018

wojtek-t Oct 17, 2018

wojtek-t Oct 16, 2018

cheftako Oct 16, 2018

wojtek-t Oct 17, 2018

cheftako Oct 29, 2018

wojtek-t Oct 16, 2018

cheftako Oct 16, 2018

wojtek-t Oct 17, 2018

cheftako Oct 29, 2018

wojtek-t Oct 16, 2018

cheftako Oct 16, 2018

wojtek-t Oct 17, 2018

cheftako Oct 29, 2018

wojtek-t Oct 16, 2018

cheftako Oct 16, 2018

wojtek-t Oct 16, 2018

cheftako Oct 16, 2018

logicalhan commented Oct 16, 2018

k8s-ci-robot commented Oct 16, 2018

wojtek-t left a comment

wojtek-t Oct 17, 2018

wojtek-t Oct 17, 2018

wojtek-t Oct 17, 2018

wojtek-t Oct 17, 2018

wojtek-t commented Oct 29, 2018

k8s-ci-robot commented Oct 29, 2018

Added tracing for long running requests. #69756

Added tracing for long running requests. #69756

Conversation

cheftako commented Oct 13, 2018

neolit123 commented Oct 13, 2018

cheftako commented Oct 15, 2018

neolit123 commented Oct 15, 2018

cheftako commented Oct 15, 2018

fedebongio commented Oct 15, 2018

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

logicalhan commented Oct 16, 2018

k8s-ci-robot commented Oct 16, 2018

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

wojtek-t commented Oct 29, 2018

k8s-ci-robot commented Oct 29, 2018