Merge pull request #578 from kubecost/niko/log

Threadsafe logging

pkg/log/counter.go

@@ -0,0 +1,31 @@
+package log
+
+import "sync"
+
+type counter struct {
+	mu   sync.RWMutex
+	seen map[string]int
+}
+
+func newCounter() *counter {
+	return &counter{seen: map[string]int{}}
+}
+
+func (ctr *counter) count(key string) int {
+	ctr.mu.RLock()
+	defer ctr.mu.RUnlock()
+	return ctr.seen[key]
+}
+
+func (ctr *counter) delete(key string) {
+	ctr.mu.Lock()
+	delete(ctr.seen, key)
+	ctr.mu.Unlock()
+}
+
+func (ctr *counter) increment(key string) int {
+	ctr.mu.Lock()
+	defer ctr.mu.Unlock()
+	ctr.seen[key]++
+	return ctr.seen[key]
+}

pkg/log/counter_test.go

@@ -0,0 +1,68 @@
+package log
+
+import (
+	"sync"
+	"testing"
+)
+
+func TestCounter_Ops(t *testing.T) {
+	ctr := newCounter()
+
+	var num int
+
+	// Should return 0 if never seen
+	num = ctr.count("something")
+	if num != 0 {
+		t.Fatalf("counter: count: expected %d; found %d", 0, num)
+	}
+
+	// Should return 1 if seen once
+	num = ctr.increment("something")
+	if num != 1 {
+		t.Fatalf("counter: count: expected %d; found %d", 1, num)
+	}
+
+	// Should still return 1 if seen only once
+	num = ctr.count("something")
+	if num != 1 {
+		t.Fatalf("counter: count: expected %d; found %d", 1, num)
+	}
+
+	// Should return 1 if seen once
+	for i := 2; i <= 234; i++ {
+		num = ctr.increment("something")
+		if num != i {
+			t.Fatalf("counter: count: expected %d; found %d", i, num)
+		}
+	}
+
+	ctr.delete("something")
+	num = ctr.count("something")
+	if num != 0 {
+		t.Fatalf("counter: count: expected %d; found %d", 0, num)
+	}
+}
+
+func TestCounter_Threadsafety(t *testing.T) {
+	var wg sync.WaitGroup
+
+	// Run 1000 goroutines, logging 10000 times each as fast as they can
+	for i := 1; i <= 1000; i++ {
+		wg.Add(1)
+		go func() {
+			for j := 1; j <= 10000; j++ {
+				DedupedInfof(10, "this log seen %d times", j)
+			}
+			wg.Done()
+		}()
+	}
+
+	wg.Wait()
+}
+
+func TestDeduping(t *testing.T) {
+	// Should log 10 times, then stop
+	for i := 1; i <= 234; i++ {
+		DedupedInfof(10, "this log seen %d times", i)
+	}
+}

pkg/log/log.go

@@ -7,25 +7,24 @@ import (
 	"k8s.io/klog"
 )
 
-var seen = make(map[string]int)
+// TODO for deduped functions, if timeLogged > logTypeLimit, should we log once
+// every... 100 (?) times so we don't lose track entirely?
+
+// concurrency-safe counter
+var ctr = newCounter()
 
 func Errorf(format string, a ...interface{}) {
 	klog.Errorf(fmt.Sprintf("[Error] %s", format), a...)
 }
 
 func DedupedErrorf(logTypeLimit int, format string, a ...interface{}) {
-	timesLogged, ok := seen[format]
-	if !ok {
-		seen[format] = 1
+	timesLogged := ctr.increment(format)
+
+	if timesLogged < logTypeLimit {
+		Errorf(format, a...)
 	} else if timesLogged == logTypeLimit {
-		seen[format]++
-		f := fmt.Sprintf("[Error] %s", format)
-		klog.Errorf("%s seen %d times, suppressing future logs", f, logTypeLimit)
-	} else if timesLogged > logTypeLimit {
-		seen[format]++
-	} else {
-		seen[format]++
-		klog.Errorf(fmt.Sprintf("[Error] %s", format), a...)
+		Errorf(format, a...)
+		Infof("%s logged %d times: suppressing future logs", format, logTypeLimit)
 	}
 }
 
@@ -34,18 +33,13 @@ func Warningf(format string, a ...interface{}) {
 }
 
 func DedupedWarningf(logTypeLimit int, format string, a ...interface{}) {
-	timesLogged, ok := seen[format]
-	if !ok {
-		seen[format] = 1
+	timesLogged := ctr.increment(format)
+
+	if timesLogged < logTypeLimit {
+		Warningf(format, a...)
 	} else if timesLogged == logTypeLimit {
-		seen[format]++
-		f := fmt.Sprintf("[Warning] %s", format)
-		klog.Errorf("%s seen %d times, suppressing future logs", f, logTypeLimit)
-	} else if timesLogged > logTypeLimit {
-		seen[format]++
-	} else {
-		seen[format]++
-		klog.V(2).Infof(fmt.Sprintf("[Warning] %s", format), a...)
+		Warningf(format, a...)
+		Infof("%s logged %d times: suppressing future logs", format, logTypeLimit)
 	}
 }
 
@@ -54,18 +48,13 @@ func Infof(format string, a ...interface{}) {
 }
 
 func DedupedInfof(logTypeLimit int, format string, a ...interface{}) {
-	timesLogged, ok := seen[format]
-	if !ok {
-		seen[format] = 1
+	timesLogged := ctr.increment(format)
+
+	if timesLogged < logTypeLimit {
+		Infof(format, a...)
 	} else if timesLogged == logTypeLimit {
-		seen[format]++
-		f := fmt.Sprintf("[Info] %s", format)
-		klog.Errorf("%s seen %d times, suppressing future logs", f, logTypeLimit)
-	} else if timesLogged > logTypeLimit {
-		seen[format]++
-	} else {
-		seen[format]++
-		klog.V(3).Infof(fmt.Sprintf("[Info] %s", format), a...)
+		Infof(format, a...)
+		Infof("%s logged %d times: suppressing future logs", format, logTypeLimit)
 	}
 }
 
@@ -88,63 +77,3 @@ func ProfileWithThreshold(start time.Time, threshold time.Duration, name string)
 		Profilef("%s: %s", elapsed, name)
 	}
 }
-
-type Profiler struct {
-	profiles map[string]time.Duration
-	starts   map[string]time.Time
-}
-
-func NewProfiler() *Profiler {
-	return &Profiler{
-		profiles: map[string]time.Duration{},
-		starts:   map[string]time.Time{},
-	}
-}
-
-func (p *Profiler) Start(name string) {
-	if p == nil {
-		return
-	}
-	p.starts[name] = time.Now()
-}
-
-func (p *Profiler) Stop(name string) time.Duration {
-	if p == nil {
-		return 0
-	}
-	if start, ok := p.starts[name]; ok {
-		elapsed := time.Since(start)
-		p.profiles[name] += elapsed
-		return elapsed
-	}
-	return 0
-}
-
-func (p *Profiler) Log(name string) {
-	if p == nil {
-		return
-	}
-	Profilef("%s: %s", p.profiles[name], name)
-}
-
-func (p *Profiler) LogAll() {
-	if p == nil {
-		return
-	}
-
-	// Print profiles, largest to smallest. (Inefficienct, but shouldn't matter.)
-	print := map[string]time.Duration{}
-	for name, value := range p.profiles {
-		print[name] = value
-	}
-	for len(print) > 0 {
-		largest := ""
-		for name := range print {
-			if print[name] > print[largest] {
-				largest = name
-			}
-		}
-		Profilef("%s: %s", print[largest], largest)
-		delete(print, largest)
-	}
-}

pkg/log/profiler.go

@@ -0,0 +1,63 @@
+package log
+
+import "time"
+
+type Profiler struct {
+	profiles map[string]time.Duration
+	starts   map[string]time.Time
+}
+
+func NewProfiler() *Profiler {
+	return &Profiler{
+		profiles: map[string]time.Duration{},
+		starts:   map[string]time.Time{},
+	}
+}
+
+func (p *Profiler) Start(name string) {
+	if p == nil {
+		return
+	}
+	p.starts[name] = time.Now()
+}
+
+func (p *Profiler) Stop(name string) time.Duration {
+	if p == nil {
+		return 0
+	}
+	if start, ok := p.starts[name]; ok {
+		elapsed := time.Since(start)
+		p.profiles[name] += elapsed
+		return elapsed
+	}
+	return 0
+}
+
+func (p *Profiler) Log(name string) {
+	if p == nil {
+		return
+	}
+	Profilef("%s: %s", p.profiles[name], name)
+}
+
+func (p *Profiler) LogAll() {
+	if p == nil {
+		return
+	}
+
+	// Print profiles, largest to smallest. (Inefficienct, but shouldn't matter.)
+	print := map[string]time.Duration{}
+	for name, value := range p.profiles {
+		print[name] = value
+	}
+	for len(print) > 0 {
+		largest := ""
+		for name := range print {
+			if print[name] > print[largest] {
+				largest = name
+			}
+		}
+		Profilef("%s: %s", print[largest], largest)
+		delete(print, largest)
+	}
+}