Matthias Andreas Benkard | 832a54e | 2019-01-29 09:27:38 +0100 | [diff] [blame] | 1 | /* |
| 2 | Copyright 2015 The Kubernetes Authors. |
| 3 | |
| 4 | Licensed under the Apache License, Version 2.0 (the "License"); |
| 5 | you may not use this file except in compliance with the License. |
| 6 | You may obtain a copy of the License at |
| 7 | |
| 8 | http://www.apache.org/licenses/LICENSE-2.0 |
| 9 | |
| 10 | Unless required by applicable law or agreed to in writing, software |
| 11 | distributed under the License is distributed on an "AS IS" BASIS, |
| 12 | WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| 13 | See the License for the specific language governing permissions and |
| 14 | limitations under the License. |
| 15 | */ |
| 16 | |
| 17 | package trace |
| 18 | |
| 19 | import ( |
| 20 | "bytes" |
| 21 | "fmt" |
| 22 | "math/rand" |
| 23 | "time" |
| 24 | |
| 25 | "github.com/golang/glog" |
| 26 | ) |
| 27 | |
| 28 | type traceStep struct { |
| 29 | stepTime time.Time |
| 30 | msg string |
| 31 | } |
| 32 | |
| 33 | type Trace struct { |
| 34 | name string |
| 35 | startTime time.Time |
| 36 | steps []traceStep |
| 37 | } |
| 38 | |
| 39 | func New(name string) *Trace { |
| 40 | return &Trace{name, time.Now(), nil} |
| 41 | } |
| 42 | |
| 43 | func (t *Trace) Step(msg string) { |
| 44 | if t.steps == nil { |
| 45 | // traces almost always have less than 6 steps, do this to avoid more than a single allocation |
| 46 | t.steps = make([]traceStep, 0, 6) |
| 47 | } |
| 48 | t.steps = append(t.steps, traceStep{time.Now(), msg}) |
| 49 | } |
| 50 | |
| 51 | func (t *Trace) Log() { |
| 52 | // an explicit logging request should dump all the steps out at the higher level |
| 53 | t.logWithStepThreshold(0) |
| 54 | } |
| 55 | |
| 56 | func (t *Trace) logWithStepThreshold(stepThreshold time.Duration) { |
| 57 | var buffer bytes.Buffer |
| 58 | tracenum := rand.Int31() |
| 59 | endTime := time.Now() |
| 60 | |
| 61 | totalTime := endTime.Sub(t.startTime) |
| 62 | buffer.WriteString(fmt.Sprintf("Trace[%d]: %q (started: %v) (total time: %v):\n", tracenum, t.name, t.startTime, totalTime)) |
| 63 | lastStepTime := t.startTime |
| 64 | for _, step := range t.steps { |
| 65 | stepDuration := step.stepTime.Sub(lastStepTime) |
| 66 | if stepThreshold == 0 || stepDuration > stepThreshold || glog.V(4) { |
| 67 | buffer.WriteString(fmt.Sprintf("Trace[%d]: [%v] [%v] %v\n", tracenum, step.stepTime.Sub(t.startTime), stepDuration, step.msg)) |
| 68 | } |
| 69 | lastStepTime = step.stepTime |
| 70 | } |
| 71 | stepDuration := endTime.Sub(lastStepTime) |
| 72 | if stepThreshold == 0 || stepDuration > stepThreshold || glog.V(4) { |
| 73 | buffer.WriteString(fmt.Sprintf("Trace[%d]: [%v] [%v] END\n", tracenum, endTime.Sub(t.startTime), stepDuration)) |
| 74 | } |
| 75 | |
| 76 | glog.Info(buffer.String()) |
| 77 | } |
| 78 | |
| 79 | func (t *Trace) LogIfLong(threshold time.Duration) { |
| 80 | if time.Since(t.startTime) >= threshold { |
| 81 | // if any step took more than it's share of the total allowed time, it deserves a higher log level |
| 82 | stepThreshold := threshold / time.Duration(len(t.steps)+1) |
| 83 | t.logWithStepThreshold(stepThreshold) |
| 84 | } |
| 85 | } |
| 86 | |
| 87 | func (t *Trace) TotalTime() time.Duration { |
| 88 | return time.Since(t.startTime) |
| 89 | } |