Merge pull request #42178 from derekwaynecarr/decode-node-list-spam

Automatic merge from submit-queue (batch tested with PRs 41597, 42185, 42075, 42178, 41705)

stop spamming logs on restart of api server

**What this PR does / why we need it**:
This PR reduces an excessive amount of log spam on startup of any API server with larger amounts of content.  We have experienced server restart times ~5 minutes that is a consequence of us tracing each directory in etcd during our initial decoding.  This spams the journald process, and results in much of those messages getting rate limited and dropped, and making actual problems much harder to debug.  This stops us logging discrete keys in favor of just knowing that an operation was slow for the particular object type (which is enough information!)

this PR also makes it so we know what trace operation was ended in our log messages!

sample log now:

```
Trace "decodeNodeList *[]api.PolicyBinding" (started 2017-02-20 22:20:33.98771112 +0000 UTC)
Decoded 10718 nodes
decodeNodeList *[]api.PolicyBinding [500ms] END
```
This commit is contained in:
Kubernetes Submit Queue 2017-03-01 00:36:09 -08:00 committed by GitHub
commit 499f089230
2 changed files with 4 additions and 3 deletions

View File

@ -380,11 +380,12 @@ func (h *etcdHelper) decodeNodeList(nodes []*etcd.Node, filter storage.FilterFun
}
for _, node := range nodes {
if node.Dir {
trace.Step("Decoding dir " + node.Key + " START")
// IMPORTANT: do not log each key as a discrete step in the trace log
// as it produces an immense amount of log spam when there is a large
// amount of content in the list.
if err := h.decodeNodeList(node.Nodes, filter, slicePtr); err != nil {
return err
}
trace.Step("Decoding dir " + node.Key + " END")
continue
}
if obj, found := h.getFromCache(node.ModifiedIndex, filter); found {

View File

@ -57,7 +57,7 @@ func (t *Trace) Log() {
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)))
buffer.WriteString(fmt.Sprintf("%q [%v] [%v] END\n", t.name, endTime.Sub(t.startTime), endTime.Sub(lastStepTime)))
glog.Info(buffer.String())
}