1/*
2Copyright 2015 The Kubernetes Authors.
3
4Licensed under the Apache License, Version 2.0 (the "License");
5you may not use this file except in compliance with the License.
6You may obtain a copy of the License at
7
8    http://www.apache.org/licenses/LICENSE-2.0
9
10Unless required by applicable law or agreed to in writing, software
11distributed under the License is distributed on an "AS IS" BASIS,
12WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13See the License for the specific language governing permissions and
14limitations under the License.
15*/
16
17package trace
18
19import (
20	"bytes"
21	"fmt"
22	"math/rand"
23	"time"
24
25	"k8s.io/klog"
26)
27
28// Field is a key value pair that provides additional details about the trace.
29type Field struct {
30	Key   string
31	Value interface{}
32}
33
34func (f Field) format() string {
35	return fmt.Sprintf("%s:%v", f.Key, f.Value)
36}
37
38func writeFields(b *bytes.Buffer, l []Field) {
39	for i, f := range l {
40		b.WriteString(f.format())
41		if i < len(l)-1 {
42			b.WriteString(",")
43		}
44	}
45}
46
47type traceStep struct {
48	stepTime time.Time
49	msg      string
50	fields   []Field
51}
52
53// Trace keeps track of a set of "steps" and allows us to log a specific
54// step if it took longer than its share of the total allowed time
55type Trace struct {
56	name      string
57	fields    []Field
58	startTime time.Time
59	steps     []traceStep
60}
61
62// New creates a Trace with the specified name. The name identifies the operation to be traced. The
63// Fields add key value pairs to provide additional details about the trace, such as operation inputs.
64func New(name string, fields ...Field) *Trace {
65	return &Trace{name: name, startTime: time.Now(), fields: fields}
66}
67
68// Step adds a new step with a specific message. Call this at the end of an execution step to record
69// how long it took. The Fields add key value pairs to provide additional details about the trace
70// step.
71func (t *Trace) Step(msg string, fields ...Field) {
72	if t.steps == nil {
73		// traces almost always have less than 6 steps, do this to avoid more than a single allocation
74		t.steps = make([]traceStep, 0, 6)
75	}
76	t.steps = append(t.steps, traceStep{stepTime: time.Now(), msg: msg, fields: fields})
77}
78
79// Log is used to dump all the steps in the Trace
80func (t *Trace) Log() {
81	// an explicit logging request should dump all the steps out at the higher level
82	t.logWithStepThreshold(0)
83}
84
85func (t *Trace) logWithStepThreshold(stepThreshold time.Duration) {
86	var buffer bytes.Buffer
87	tracenum := rand.Int31()
88	endTime := time.Now()
89
90	totalTime := endTime.Sub(t.startTime)
91	buffer.WriteString(fmt.Sprintf("Trace[%d]: %q ", tracenum, t.name))
92	if len(t.fields) > 0 {
93		writeFields(&buffer, t.fields)
94		buffer.WriteString(" ")
95	}
96	buffer.WriteString(fmt.Sprintf("(started: %v) (total time: %v):\n", t.startTime, totalTime))
97	lastStepTime := t.startTime
98	for _, step := range t.steps {
99		stepDuration := step.stepTime.Sub(lastStepTime)
100		if stepThreshold == 0 || stepDuration > stepThreshold || klog.V(4) {
101			buffer.WriteString(fmt.Sprintf("Trace[%d]: [%v] [%v] ", tracenum, step.stepTime.Sub(t.startTime), stepDuration))
102			buffer.WriteString(step.msg)
103			if len(step.fields) > 0 {
104				buffer.WriteString(" ")
105				writeFields(&buffer, step.fields)
106			}
107			buffer.WriteString("\n")
108		}
109		lastStepTime = step.stepTime
110	}
111	stepDuration := endTime.Sub(lastStepTime)
112	if stepThreshold == 0 || stepDuration > stepThreshold || klog.V(4) {
113		buffer.WriteString(fmt.Sprintf("Trace[%d]: [%v] [%v] END\n", tracenum, endTime.Sub(t.startTime), stepDuration))
114	}
115
116	klog.Info(buffer.String())
117}
118
119// LogIfLong is used to dump steps that took longer than its share
120func (t *Trace) LogIfLong(threshold time.Duration) {
121	if time.Since(t.startTime) >= threshold {
122		// if any step took more than it's share of the total allowed time, it deserves a higher log level
123		stepThreshold := threshold / time.Duration(len(t.steps)+1)
124		t.logWithStepThreshold(stepThreshold)
125	}
126}
127
128// TotalTime can be used to figure out how long it took since the Trace was created
129func (t *Trace) TotalTime() time.Duration {
130	return time.Since(t.startTime)
131}
132