Add very simple tracing mechanism for easier debugging of slow requests.

pkg/registry/generic/etcd/etcd.go

@@ -18,6 +18,7 @@ package etcd
 
 import (
 	"fmt"
+	"time"
 
 	"github.com/GoogleCloudPlatform/kubernetes/pkg/api"
 	kubeerr "github.com/GoogleCloudPlatform/kubernetes/pkg/api/errors"
@@ -28,6 +29,7 @@ import (
 	"github.com/GoogleCloudPlatform/kubernetes/pkg/registry/generic"
 	"github.com/GoogleCloudPlatform/kubernetes/pkg/runtime"
 	"github.com/GoogleCloudPlatform/kubernetes/pkg/tools"
+	"github.com/GoogleCloudPlatform/kubernetes/pkg/util"
 	"github.com/GoogleCloudPlatform/kubernetes/pkg/watch"
 
 	"github.com/golang/glog"
@@ -144,22 +146,29 @@ func (e *Etcd) List(ctx api.Context, label labels.Selector, field fields.Selecto
 
 // ListPredicate returns a list of all the items matching m.
 func (e *Etcd) ListPredicate(ctx api.Context, m generic.Matcher) (runtime.Object, error) {
+	trace := util.NewTrace("List")
+	defer trace.LogIfLong(time.Second)
 	list := e.NewListFunc()
 	if name, ok := m.MatchesSingle(); ok {
+		trace.Step("About to read single object")
 		key, err := e.KeyFunc(ctx, name)
 		if err != nil {
 			return nil, err
 		}
 		err = e.Helper.ExtractObjToList(key, list)
+		trace.Step("Object extracted")
 		if err != nil {
 			return nil, err
 		}
 	} else {
+		trace.Step("About to list directory")
 		err := e.Helper.ExtractToList(e.KeyRootFunc(ctx), list)
+		trace.Step("List extracted")
 		if err != nil {
 			return nil, err
 		}
 	}
+	defer trace.Step("List filtered")
 	return generic.FilterList(list, m, generic.DecoratorFunc(e.Decorator))
 }
 
@@ -192,6 +201,8 @@ func (e *Etcd) CreateWithName(ctx api.Context, name string, obj runtime.Object)
 
 // 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")
+	defer trace.LogIfLong(time.Second)
 	if err := rest.BeforeCreate(e.CreateStrategy, ctx, obj); err != nil {
 		return nil, err
 	}
@@ -210,12 +221,14 @@ func (e *Etcd) Create(ctx api.Context, obj runtime.Object) (runtime.Object, erro
 			return nil, err
 		}
 	}
+	trace.Step("About to create object")
 	out := e.NewFunc()
 	if err := e.Helper.CreateObj(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
@@ -255,6 +268,8 @@ func (e *Etcd) UpdateWithName(ctx api.Context, name string, obj runtime.Object)
 // 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")
+	defer trace.LogIfLong(time.Second)
 	name, err := e.ObjectNameFunc(obj)
 	if err != nil {
 		return nil, false, err
@@ -343,14 +358,18 @@ 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) {
+	trace := util.NewTrace("Get")
+	defer trace.LogIfLong(time.Second)
 	obj := e.NewFunc()
 	key, err := e.KeyFunc(ctx, name)
 	if err != nil {
 		return nil, err
 	}
+	trace.Step("About to read object")
 	if err := e.Helper.ExtractObj(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
@@ -361,12 +380,15 @@ func (e *Etcd) Get(ctx api.Context, name string) (runtime.Object, error) {
 
 // Delete removes the item from etcd.
 func (e *Etcd) Delete(ctx api.Context, name string, options *api.DeleteOptions) (runtime.Object, error) {
+	trace := util.NewTrace("Delete")
+	defer trace.LogIfLong(time.Second)
 	key, err := e.KeyFunc(ctx, name)
 	if err != nil {
 		return nil, err
 	}
 
 	obj := e.NewFunc()
+	trace.Step("About to read object")
 	if err := e.Helper.ExtractObj(key, obj, false); err != nil {
 		return nil, etcderr.InterpretDeleteError(err, e.EndpointName, name)
 	}
@@ -383,6 +405,7 @@ func (e *Etcd) Delete(ctx api.Context, name string, options *api.DeleteOptions)
 		return e.finalizeDelete(obj, false)
 	}
 	if graceful && *options.GracePeriodSeconds != 0 {
+		trace.Step("Graceful deletion")
 		out := e.NewFunc()
 		if err := e.Helper.SetObj(key, obj, out, uint64(*options.GracePeriodSeconds)); err != nil {
 			return nil, etcderr.InterpretUpdateError(err, e.EndpointName, name)
@@ -392,6 +415,7 @@ 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.Helper.DeleteObj(key, out); err != nil {
 		return nil, etcderr.InterpretDeleteError(err, e.EndpointName, name)
 	}

pkg/tools/etcd_helper.go

@@ -181,6 +181,8 @@ func (h *EtcdHelper) listEtcdNode(key string) ([]*etcd.Node, uint64, error) {
 
 // decodeNodeList walks the tree of each node in the list and decodes into the specified object
 func (h *EtcdHelper) decodeNodeList(nodes []*etcd.Node, slicePtr interface{}) error {
+	trace := util.NewTrace("decodeNodeList " + getTypeName(slicePtr))
+	defer trace.LogIfLong(500 * time.Millisecond)
 	v, err := conversion.EnforcePtr(slicePtr)
 	if err != nil || v.Kind() != reflect.Slice {
 		// This should not happen at runtime.
@@ -188,9 +190,11 @@ func (h *EtcdHelper) decodeNodeList(nodes []*etcd.Node, slicePtr interface{}) er
 	}
 	for _, node := range nodes {
 		if node.Dir {
+			trace.Step("Decoding dir " + node.Key + " START")
 			if err := h.decodeNodeList(node.Nodes, slicePtr); err != nil {
 				return err
 			}
+			trace.Step("Decoding dir " + node.Key + " END")
 			continue
 		}
 		if obj, found := h.getFromCache(node.ModifiedIndex); found {
@@ -210,6 +214,7 @@ func (h *EtcdHelper) decodeNodeList(nodes []*etcd.Node, slicePtr interface{}) er
 			}
 		}
 	}
+	trace.Step(fmt.Sprintf("Decoded %v nodes", len(nodes)))
 	return nil
 }
 
@@ -222,15 +227,19 @@ type etcdCache interface {
 }
 
 func (h *EtcdHelper) getFromCache(index uint64) (runtime.Object, bool) {
+	trace := util.NewTrace("getFromCache")
+	defer trace.LogIfLong(200 * time.Microsecond)
 	startTime := time.Now()
 	defer func() {
 		cacheGetLatency.Observe(float64(time.Since(startTime) / time.Microsecond))
 	}()
 	obj, found := h.cache.Get(index)
+	trace.Step("Raw get done")
 	if found {
 		// We should not return the object itself to avoid poluting the cache if someone
 		// modifies returned values.
 		objCopy, err := conversion.DeepCopy(obj)
+		trace.Step("Deep copied")
 		if err != nil {
 			glog.Errorf("Error during DeepCopy of cached object: %q", err)
 			return nil, false
@@ -261,20 +270,25 @@ func (h *EtcdHelper) addToCache(index uint64, obj runtime.Object) {
 // ExtractToList works on a *List api object (an object that satisfies the runtime.IsList
 // definition) and extracts a go object per etcd node into a slice with the resource version.
 func (h *EtcdHelper) ExtractToList(key string, listObj runtime.Object) error {
+	trace := util.NewTrace("ExtractToList " + getTypeName(listObj))
+	defer trace.LogIfLong(time.Second)
 	listPtr, err := runtime.GetItemsPtr(listObj)
 	if err != nil {
 		return err
 	}
 	key = h.PrefixEtcdKey(key)
 	startTime := time.Now()
+	trace.Step("About to list etcd node")
 	nodes, index, err := h.listEtcdNode(key)
 	recordEtcdRequestLatency("list", getTypeName(listPtr), startTime)
+	trace.Step("Etcd node listed")
 	if err != nil {
 		return err
 	}
 	if err := h.decodeNodeList(nodes, listPtr); err != nil {
 		return err
 	}
+	trace.Step("Node list decoded")
 	if h.Versioner != nil {
 		if err := h.Versioner.UpdateList(listObj, index); err != nil {
 			return err
@@ -286,14 +300,17 @@ func (h *EtcdHelper) ExtractToList(key string, listObj runtime.Object) error {
 // ExtractObjToList unmarshals json found at key and opaques it into a *List api object
 // (an object that satisfies the runtime.IsList definition).
 func (h *EtcdHelper) ExtractObjToList(key string, listObj runtime.Object) error {
+	trace := util.NewTrace("ExtractObjToList " + getTypeName(listObj))
 	listPtr, err := runtime.GetItemsPtr(listObj)
 	if err != nil {
 		return err
 	}
 	key = h.PrefixEtcdKey(key)
 	startTime := time.Now()
+	trace.Step("About to read etcd node")
 	response, err := h.Client.Get(key, false, false)
 	recordEtcdRequestLatency("get", getTypeName(listPtr), startTime)
+	trace.Step("Etcd node read")
 	if err != nil {
 		if IsEtcdNotFound(err) {
 			return nil
@@ -307,6 +324,7 @@ func (h *EtcdHelper) ExtractObjToList(key string, listObj runtime.Object) error
 	if err := h.decodeNodeList(nodes, listPtr); err != nil {
 		return err
 	}
+	trace.Step("Object decoded")
 	if h.Versioner != nil {
 		if err := h.Versioner.UpdateList(listObj, response.EtcdIndex); err != nil {
 			return err

pkg/util/trace.go

@@ -0,0 +1,68 @@
+/*
+Copyright 2015 The Kubernetes Authors All rights reserved.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package util
+
+import (
+	"bytes"
+	"fmt"
+	"time"
+
+	"github.com/golang/glog"
+)
+
+type traceStep struct {
+	stepTime time.Time
+	msg      string
+}
+
+type Trace struct {
+	name      string
+	startTime time.Time
+	steps     []*traceStep
+}
+
+func NewTrace(name string) *Trace {
+	return &Trace{name, time.Now(), make([]*traceStep, 0)}
+}
+
+func (t *Trace) Step(msg string) {
+	t.steps = append(t.steps, &traceStep{time.Now(), msg})
+}
+
+func (t *Trace) Log() {
+	endTime := time.Now()
+	var buffer bytes.Buffer
+
+	buffer.WriteString(fmt.Sprintf("Trace %q (started %v):\n", t.name, t.startTime))
+	lastStepTime := t.startTime
+	for _, step := range t.steps {
+		buffer.WriteString(fmt.Sprintf("[%v] [%v] %v\n", step.stepTime.Sub(t.startTime), step.stepTime.Sub(lastStepTime), step.msg))
+		lastStepTime = step.stepTime
+	}
+	buffer.WriteString(fmt.Sprintf("[%v] [%v] END\n", endTime.Sub(t.startTime), endTime.Sub(lastStepTime)))
+	glog.Info(buffer.String())
+}
+
+func (t *Trace) LogIfLong(threshold time.Duration) {
+	if time.Since(t.startTime) >= threshold {
+		t.Log()
+	}
+}
+
+func (t *Trace) TotalTime() time.Duration {
+	return time.Since(t.startTime)
+}