trace: on klog.V(4) only log all nested traced inside trace above threshold
diff --git a/trace/trace.go b/trace/trace.go
index e7f56d8..7ae4167 100644
--- a/trace/trace.go
+++ b/trace/trace.go
@@ -26,6 +26,10 @@
"k8s.io/klog/v2"
)
+var klogV = func(lvl klog.Level) bool {
+ return klog.V(lvl).Enabled()
+}
+
// Field is a key value pair that provides additional details about the trace.
type Field struct {
Key string
@@ -80,7 +84,7 @@
func (s traceStep) writeItem(b *bytes.Buffer, formatter string, startTime time.Time, stepThreshold *time.Duration) {
stepDuration := s.stepTime.Sub(startTime)
- if stepThreshold == nil || *stepThreshold == 0 || stepDuration >= *stepThreshold {
+ if stepThreshold == nil || *stepThreshold == 0 || stepDuration >= *stepThreshold || klogV(4) {
b.WriteString(fmt.Sprintf("%s---", formatter))
writeTraceItemSummary(b, s.msg, stepDuration, s.stepTime, s.fields)
}
@@ -106,7 +110,7 @@
}
func (t *Trace) writeItem(b *bytes.Buffer, formatter string, startTime time.Time, stepThreshold *time.Duration) {
- if t.durationIsWithinThreshold() {
+ if t.durationIsWithinThreshold() || klogV(4) {
b.WriteString(fmt.Sprintf("%v[", formatter))
writeTraceItemSummary(b, t.name, t.TotalTime(), t.startTime, t.fields)
if st := t.calculateStepThreshold(); st != nil {
@@ -168,13 +172,13 @@
// LogIfLong only logs the trace if the duration of the trace exceeds the threshold.
// Only steps that took longer than their share or the given threshold are logged.
-// If klog is at verbosity level 4 or higher, the trace and its steps are logged regardless of threshold.
-// If the Trace is nested it is not immediately logged. Instead, it is logged when the trace it is nested within
-// is logged.
+// If klog is at verbosity level 4 or higher and the trace took longer than the threshold,
+// all substeps and subtraces are logged. Otherwise, only those which took longer than
+// their own threshold.
+// If the Trace is nested it is not immediately logged. Instead, it is logged when the trace it
+// is nested within is logged.
func (t *Trace) LogIfLong(threshold time.Duration) {
- if !klog.V(4).Enabled() { // don't set threshold if verbosity is level 4 of higher
- t.threshold = &threshold
- }
+ t.threshold = &threshold
t.Log()
}
diff --git a/trace/trace_test.go b/trace/trace_test.go
index e98b70f..a5e1b13 100644
--- a/trace/trace_test.go
+++ b/trace/trace_test.go
@@ -385,6 +385,7 @@
expectedMsgs []string
unexpectedMsg []string
trace *Trace
+ verbosity klog.Level
}{
{
name: "Log nested trace when it surpasses threshold",
@@ -501,6 +502,32 @@
},
},
},
+ {
+ name: "Log all nested traces that surpass threshold and their children if klog verbosity is >= 4",
+ expectedMsgs: []string{"inner1", "inner2"},
+ unexpectedMsg: []string{"msg"},
+ verbosity: 4,
+ trace: &Trace{
+ name: "msg",
+ startTime: currentTime.Add(10),
+ traceItems: []traceItem{
+ &Trace{
+ name: "inner1",
+ threshold: &five,
+ startTime: currentTime.Add(-10 * time.Millisecond),
+ endTime: ¤tTime,
+ traceItems: []traceItem{
+ &Trace{
+ name: "inner2",
+ threshold: &twoHundred,
+ startTime: currentTime.Add(-10 * time.Millisecond),
+ endTime: ¤tTime,
+ },
+ },
+ },
+ },
+ },
+ },
}
for _, tt := range tests {
@@ -508,6 +535,16 @@
var buf bytes.Buffer
klog.SetOutput(&buf)
+ if tt.verbosity > 0 {
+ orig := klogV
+ klogV = func(l klog.Level) bool {
+ return l <= tt.verbosity
+ }
+ defer func() {
+ klogV = orig
+ }()
+ }
+
tt.trace.LogIfLong(twoHundred)
for _, msg := range tt.expectedMsgs {