diff --git a/pkg/registry/generic/etcd/etcd.go b/pkg/registry/generic/etcd/etcd.go index 9ac647a04ea..5c2a70812c8 100644 --- a/pkg/registry/generic/etcd/etcd.go +++ b/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) } diff --git a/pkg/tools/etcd_helper.go b/pkg/tools/etcd_helper.go index 03df8e440c8..35351807a04 100644 --- a/pkg/tools/etcd_helper.go +++ b/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 diff --git a/pkg/util/trace.go b/pkg/util/trace.go new file mode 100644 index 00000000000..a6b92234596 --- /dev/null +++ b/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) +}