Added tracing for long running requests.

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

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

@@ -167,6 +167,7 @@ func createHandler(r rest.NamedCreater, scope RequestScope, admit admission.Inte
 			status.Code = int32(code)
 		}
 
+		scope.Trace = trace
 		transformResponseObject(ctx, scope, req, w, code, result)
 	}
 }

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

@@ -175,6 +175,7 @@ func DeleteResource(r rest.GracefulDeleter, allowsOptions bool, scope RequestSco
 			}
 		}
 
+		scope.Trace = trace
 		transformResponseObject(ctx, scope, req, w, status, result)
 	}
 }
@@ -182,6 +183,9 @@ func DeleteResource(r rest.GracefulDeleter, allowsOptions bool, scope RequestSco
 // 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(500 * time.Millisecond)
+
 		if isDryRun(req.URL) && !utilfeature.DefaultFeatureGate.Enabled(features.DryRun) {
 			scope.err(errors.NewBadRequest("the dryRun alpha feature is disabled"), w, req)
 			return
@@ -310,6 +314,7 @@ func DeleteCollection(r rest.CollectionDeleter, checkBody bool, scope RequestSco
 			}
 		}
 
+		scope.Trace = trace
 		transformResponseObject(ctx, scope, req, w, http.StatusOK, result)
 	}
 }

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

@@ -74,7 +74,9 @@ func getResourceHandler(scope RequestScope, getter getterFunc) http.HandlerFunc
 		}
 
 		trace.Step("About to write a response")
+		scope.Trace = trace
 		transformResponseObject(ctx, scope, req, w, http.StatusOK, result)
+		trace.Step("Transformed response object")
 	}
 }
 
@@ -279,6 +281,7 @@ func ListResource(r rest.Lister, rw rest.Watcher, scope RequestScope, forceWatch
 			}
 		}
 
+		scope.Trace = trace
 		transformResponseObject(ctx, scope, req, w, http.StatusOK, result)
 		trace.Step(fmt.Sprintf("Writing http response done (%d items)", numberOfItems))
 	}

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

@@ -201,6 +201,7 @@ func PatchResource(r rest.Patcher, scope RequestScope, admit admission.Interface
 		}
 		trace.Step("Self-link added")
 
+		scope.Trace = trace
 		transformResponseObject(ctx, scope, req, w, http.StatusOK, result)
 	}
 }

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

@@ -35,9 +35,11 @@ import (
 // Will write the complete response object.
 func transformResponseObject(ctx context.Context, scope RequestScope, req *http.Request, w http.ResponseWriter, statusCode int, result runtime.Object) {
 	// TODO: fetch the media type much earlier in request processing and pass it into this method.
+	trace := scope.Trace
 	mediaType, _, err := negotiation.NegotiateOutputMediaType(req, scope.Serializer, &scope)
 	if err != nil {
 		status := responsewriters.ErrorToAPIStatus(err)
+		trace.Step("Writing raw JSON response")
 		responsewriters.WriteRawJSON(int(status.Code), status, w)
 		return
 	}
@@ -68,6 +70,7 @@ func transformResponseObject(ctx context.Context, scope RequestScope, req *http.
 				return
 			}
 			encoder := metainternalversion.Codecs.EncoderForVersion(info.Serializer, metav1beta1.SchemeGroupVersion)
+			trace.Step(fmt.Sprintf("Serializing response as type %s", info.MediaType))
 			responsewriters.SerializeObject(info.MediaType, encoder, w, req, statusCode, partial)
 			return
 
@@ -79,6 +82,7 @@ func transformResponseObject(ctx context.Context, scope RequestScope, req *http.
 				return
 			}
 			list := &metav1beta1.PartialObjectMetadataList{}
+			trace.Step("Processing list items")
 			err := meta.EachListItem(result, func(obj runtime.Object) error {
 				m, err := meta.Accessor(obj)
 				if err != nil {
@@ -101,6 +105,7 @@ func transformResponseObject(ctx context.Context, scope RequestScope, req *http.
 				return
 			}
 			encoder := metainternalversion.Codecs.EncoderForVersion(info.Serializer, metav1beta1.SchemeGroupVersion)
+			trace.Step(fmt.Sprintf("Serializing response as type %s", info.MediaType))
 			responsewriters.SerializeObject(info.MediaType, encoder, w, req, statusCode, list)
 			return
 
@@ -109,17 +114,20 @@ func transformResponseObject(ctx context.Context, scope RequestScope, req *http.
 			// TODO: skip if this is a status response (delete without body)?
 
 			opts := &metav1beta1.TableOptions{}
+			trace.Step("Decoding parameters")
 			if err := metav1beta1.ParameterCodec.DecodeParameters(req.URL.Query(), metav1beta1.SchemeGroupVersion, opts); err != nil {
 				scope.err(err, w, req)
 				return
 			}
 
+			trace.Step("Converting to table")
 			table, err := scope.TableConvertor.ConvertToTable(ctx, result, opts)
 			if err != nil {
 				scope.err(err, w, req)
 				return
 			}
 
+			trace.Step("Processing rows")
 			for i := range table.Rows {
 				item := &table.Rows[i]
 				switch opts.IncludeObject {
@@ -156,6 +164,7 @@ func transformResponseObject(ctx context.Context, scope RequestScope, req *http.
 				return
 			}
 			encoder := metainternalversion.Codecs.EncoderForVersion(info.Serializer, metav1beta1.SchemeGroupVersion)
+			trace.Step(fmt.Sprintf("Serializing response as type %s", info.MediaType))
 			responsewriters.SerializeObject(info.MediaType, encoder, w, req, statusCode, table)
 			return
 
@@ -164,11 +173,13 @@ func transformResponseObject(ctx context.Context, scope RequestScope, req *http.
 			accepted, _ := negotiation.MediaTypesForSerializer(metainternalversion.Codecs)
 			err := negotiation.NewNotAcceptableError(accepted)
 			status := responsewriters.ErrorToAPIStatus(err)
+			trace.Step("Writing raw JSON response")
 			responsewriters.WriteRawJSON(int(status.Code), status, w)
 			return
 		}
 	}
 
+	trace.Step("Writing response")
 	responsewriters.WriteObject(statusCode, scope.Kind.GroupVersion(), scope.Serializer, result, w, req)
 }
 

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

@@ -40,6 +40,7 @@ import (
 	"k8s.io/apiserver/pkg/endpoints/metrics"
 	"k8s.io/apiserver/pkg/endpoints/request"
 	"k8s.io/apiserver/pkg/registry/rest"
+	utiltrace "k8s.io/apiserver/pkg/util/trace"
 	openapiproto "k8s.io/kube-openapi/pkg/util/proto"
 )
 
@@ -56,6 +57,7 @@ type RequestScope struct {
 	Typer           runtime.ObjectTyper
 	UnsafeConvertor runtime.ObjectConvertor
 	Authorizer      authorizer.Authorizer
+	Trace           *utiltrace.Trace
 
 	TableConvertor rest.TableConvertor
 	OpenAPISchema  openapiproto.Schema

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

@@ -190,6 +190,7 @@ func UpdateResource(r rest.Updater, scope RequestScope, admit admission.Interfac
 			status = http.StatusCreated
 		}
 
+		scope.Trace = trace
 		transformResponseObject(ctx, scope, req, w, status, result)
 	}
 }