Better traces for api calls.

pkg/apiserver/resthandler.go

@@ -115,6 +115,9 @@ func getResourceHandler(scope RequestScope, getter getterFunc) restful.RouteFunc
 func GetResource(r rest.Getter, scope RequestScope) restful.RouteFunction {
 	return getResourceHandler(scope,
 		func(ctx api.Context, name string, req *restful.Request) (runtime.Object, error) {
+			// For performance tracking purposes.
+			trace := util.NewTrace("Get " + req.Request.URL.Path)
+			defer trace.LogIfLong(250 * time.Millisecond)
 			return r.Get(ctx, name)
 		})
 }
@@ -322,6 +325,10 @@ func ListResource(r rest.Lister, rw rest.Watcher, scope RequestScope, forceWatch
 
 func createHandler(r rest.NamedCreater, scope RequestScope, typer runtime.ObjectTyper, admit admission.Interface, includeName bool) restful.RouteFunction {
 	return func(req *restful.Request, res *restful.Response) {
+		// For performance tracking purposes.
+		trace := util.NewTrace("Create " + req.Request.URL.Path)
+		defer trace.LogIfLong(250 * time.Millisecond)
+
 		w := res.ResponseWriter
 
 		// TODO: we either want to remove timeout or document it (if we document, move timeout out of this function and declare it in api_installer)
@@ -351,12 +358,14 @@ func createHandler(r rest.NamedCreater, scope RequestScope, typer runtime.Object
 		}
 
 		obj := r.New()
+		trace.Step("About to convert to expected version")
 		// TODO this cleans up with proper typing
 		if err := scope.Codec.DecodeIntoWithSpecifiedVersionKind(body, obj, scope.Kind); err != nil {
 			err = transformDecodeError(typer, err, obj, body)
 			errorJSON(err, scope.Codec, w)
 			return
 		}
+		trace.Step("Conversion done")
 
 		if admit != nil && admit.Handles(admission.Create) {
 			userInfo, _ := api.UserFrom(ctx)
@@ -368,6 +377,7 @@ func createHandler(r rest.NamedCreater, scope RequestScope, typer runtime.Object
 			}
 		}
 
+		trace.Step("About to store object in database")
 		result, err := finishRequest(timeout, func() (runtime.Object, error) {
 			out, err := r.Create(ctx, name, obj)
 			if status, ok := out.(*unversioned.Status); ok && err == nil && status.Code == 0 {
@@ -379,11 +389,13 @@ func createHandler(r rest.NamedCreater, scope RequestScope, typer runtime.Object
 			errorJSON(err, scope.Codec, w)
 			return
 		}
+		trace.Step("Object stored in database")
 
 		if err := setSelfLink(result, req, scope.Namer); err != nil {
 			errorJSON(err, scope.Codec, w)
 			return
 		}
+		trace.Step("Self-link added")
 
 		write(http.StatusCreated, scope.Kind.GroupVersion(), scope.Codec, result, w, req.Request)
 	}
@@ -565,6 +577,10 @@ func patchResource(ctx api.Context, timeout time.Duration, versionedObj runtime.
 // UpdateResource returns a function that will handle a resource update
 func UpdateResource(r rest.Updater, scope RequestScope, typer runtime.ObjectTyper, admit admission.Interface) restful.RouteFunction {
 	return func(req *restful.Request, res *restful.Response) {
+		// For performance tracking purposes.
+		trace := util.NewTrace("Update " + req.Request.URL.Path)
+		defer trace.LogIfLong(250 * time.Millisecond)
+
 		w := res.ResponseWriter
 
 		// TODO: we either want to remove timeout or document it (if we document, move timeout out of this function and declare it in api_installer)
@@ -585,11 +601,13 @@ func UpdateResource(r rest.Updater, scope RequestScope, typer runtime.ObjectType
 		}
 
 		obj := r.New()
+		trace.Step("About to convert to expected version")
 		if err := scope.Codec.DecodeIntoWithSpecifiedVersionKind(body, obj, scope.Kind); err != nil {
 			err = transformDecodeError(typer, err, obj, body)
 			errorJSON(err, scope.Codec, w)
 			return
 		}
+		trace.Step("Conversion done")
 
 		if err := checkName(obj, name, namespace, scope.Namer); err != nil {
 			errorJSON(err, scope.Codec, w)
@@ -606,6 +624,7 @@ func UpdateResource(r rest.Updater, scope RequestScope, typer runtime.ObjectType
 			}
 		}
 
+		trace.Step("About to store object in database")
 		wasCreated := false
 		result, err := finishRequest(timeout, func() (runtime.Object, error) {
 			obj, created, err := r.Update(ctx, obj)
@@ -616,11 +635,13 @@ func UpdateResource(r rest.Updater, scope RequestScope, typer runtime.ObjectType
 			errorJSON(err, scope.Codec, w)
 			return
 		}
+		trace.Step("Object stored in database")
 
 		if err := setSelfLink(result, req, scope.Namer); err != nil {
 			errorJSON(err, scope.Codec, w)
 			return
 		}
+		trace.Step("Self-link added")
 
 		status := http.StatusOK
 		if wasCreated {
@@ -633,6 +654,10 @@ func UpdateResource(r rest.Updater, scope RequestScope, typer runtime.ObjectType
 // DeleteResource returns a function that will handle a resource deletion
 func DeleteResource(r rest.GracefulDeleter, checkBody bool, scope RequestScope, admit admission.Interface) restful.RouteFunction {
 	return func(req *restful.Request, res *restful.Response) {
+		// For performance tracking purposes.
+		trace := util.NewTrace("Delete " + req.Request.URL.Path)
+		defer trace.LogIfLong(250 * time.Millisecond)
+
 		w := res.ResponseWriter
 
 		// TODO: we either want to remove timeout or document it (if we document, move timeout out of this function and declare it in api_installer)
@@ -671,6 +696,7 @@ func DeleteResource(r rest.GracefulDeleter, checkBody bool, scope RequestScope,
 			}
 		}
 
+		trace.Step("About do delete object from database")
 		result, err := finishRequest(timeout, func() (runtime.Object, error) {
 			return r.Delete(ctx, name, options)
 		})
@@ -678,6 +704,7 @@ func DeleteResource(r rest.GracefulDeleter, checkBody bool, scope RequestScope,
 			errorJSON(err, scope.Codec, w)
 			return
 		}
+		trace.Step("Object deleted from database")
 
 		// if the rest.Deleter returns a nil object, fill out a status. Callers may return a valid
 		// object with the response.

pkg/registry/generic/etcd/etcd.go

@@ -18,8 +18,6 @@ package etcd
 
 import (
 	"fmt"
-	"reflect"
-	"time"
 
 	"k8s.io/kubernetes/pkg/api"
 	kubeerr "k8s.io/kubernetes/pkg/api/errors"
@@ -32,7 +30,6 @@ import (
 	"k8s.io/kubernetes/pkg/registry/generic"
 	"k8s.io/kubernetes/pkg/runtime"
 	"k8s.io/kubernetes/pkg/storage"
-	"k8s.io/kubernetes/pkg/util"
 	"k8s.io/kubernetes/pkg/watch"
 
 	"github.com/golang/glog"
@@ -198,8 +195,6 @@ func (e *Etcd) ListPredicate(ctx api.Context, m generic.Matcher, options *unvers
 
 // Create inserts a new item according to the unique key from the object.
 func (e *Etcd) Create(ctx api.Context, obj runtime.Object) (runtime.Object, error) {
-	trace := util.NewTrace("Create " + reflect.TypeOf(obj).String())
-	defer trace.LogIfLong(time.Second)
 	if err := rest.BeforeCreate(e.CreateStrategy, ctx, obj); err != nil {
 		return nil, err
 	}
@@ -215,14 +210,12 @@ func (e *Etcd) Create(ctx api.Context, obj runtime.Object) (runtime.Object, erro
 	if err != nil {
 		return nil, err
 	}
-	trace.Step("About to create object")
 	out := e.NewFunc()
 	if err := e.Storage.Create(ctx, key, obj, out, ttl); err != nil {
 		err = etcderr.InterpretCreateError(err, e.EndpointName, name)
 		err = rest.CheckGeneratedNameError(e.CreateStrategy, err, obj)
 		return nil, err
 	}
-	trace.Step("Object created")
 	if e.AfterCreate != nil {
 		if err := e.AfterCreate(out); err != nil {
 			return nil, err
@@ -240,8 +233,6 @@ func (e *Etcd) Create(ctx api.Context, obj runtime.Object) (runtime.Object, erro
 // or an error. If the registry allows create-on-update, the create flow will be executed.
 // A bool is returned along with the object and any errors, to indicate object creation.
 func (e *Etcd) Update(ctx api.Context, obj runtime.Object) (runtime.Object, bool, error) {
-	trace := util.NewTrace("Update " + reflect.TypeOf(obj).String())
-	defer trace.LogIfLong(time.Second)
 	name, err := e.ObjectNameFunc(obj)
 	if err != nil {
 		return nil, false, err
@@ -344,17 +335,13 @@ func (e *Etcd) Update(ctx api.Context, obj runtime.Object) (runtime.Object, bool
 // Get retrieves the item from etcd.
 func (e *Etcd) Get(ctx api.Context, name string) (runtime.Object, error) {
 	obj := e.NewFunc()
-	trace := util.NewTrace("Get " + reflect.TypeOf(obj).String())
-	defer trace.LogIfLong(time.Second)
 	key, err := e.KeyFunc(ctx, name)
 	if err != nil {
 		return nil, err
 	}
-	trace.Step("About to read object")
 	if err := e.Storage.Get(ctx, key, obj, false); err != nil {
 		return nil, etcderr.InterpretGetError(err, e.EndpointName, name)
 	}
-	trace.Step("Object read")
 	if e.Decorator != nil {
 		if err := e.Decorator(obj); err != nil {
 			return nil, err
@@ -376,9 +363,6 @@ func (e *Etcd) Delete(ctx api.Context, name string, options *api.DeleteOptions)
 	}
 
 	obj := e.NewFunc()
-	trace := util.NewTrace("Delete " + reflect.TypeOf(obj).String())
-	defer trace.LogIfLong(time.Second)
-	trace.Step("About to read object")
 	if err := e.Storage.Get(ctx, key, obj, false); err != nil {
 		return nil, etcderr.InterpretDeleteError(err, e.EndpointName, name)
 	}
@@ -395,7 +379,6 @@ func (e *Etcd) Delete(ctx api.Context, name string, options *api.DeleteOptions)
 		return e.finalizeDelete(obj, false)
 	}
 	if graceful {
-		trace.Step("Graceful deletion")
 		out := e.NewFunc()
 		lastGraceful := int64(0)
 		err := e.Storage.GuaranteedUpdate(
@@ -433,7 +416,6 @@ func (e *Etcd) Delete(ctx api.Context, name string, options *api.DeleteOptions)
 
 	// delete immediately, or no graceful deletion supported
 	out := e.NewFunc()
-	trace.Step("About to delete object")
 	if err := e.Storage.Delete(ctx, key, out); err != nil {
 		return nil, etcderr.InterpretDeleteError(err, e.EndpointName, name)
 	}