tracing: Rate limit logs from zipkin collector library

This involves some slightly awkward refactoring of the log.EveryN code
into a different package because the tracing package can't use the log
package.

Resolves the massive log spam I saw when my tpc-c 50k cluster in cockroachdb#30284
caused my jaeger node to OOM, making for a lot of complaints from the
zipkin library about its backlog being too long.

Release note: None

pkg/util/every_n.go

@@ -0,0 +1,54 @@
+// Copyright 2017 The Cockroach Authors.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or
+// implied. See the License for the specific language governing
+// permissions and limitations under the License.
+
+package util
+
+import (
+	"time"
+
+	"github.com/cockroachdb/cockroach/pkg/util/syncutil"
+)
+
+// EveryN provides a way to rate limit spammy events. It tracks how recently a
+// given event has occurred so that it can determine whether it's worth
+// handling again.
+//
+// NOTE: If you specifically care about log messages, you should use the
+// version of this in the log package, as it integrates with the verbosity
+// flags.
+type EveryN struct {
+	// N is the minimum duration of time between log messages.
+	N time.Duration
+
+	syncutil.Mutex
+	lastProcessed time.Time
+}
+
+// Every is a convenience constructor for an EveryN object that allows a log
+// message every n duration.
+func Every(n time.Duration) EveryN {
+	return EveryN{N: n}
+}
+
+// ShouldProcess returns whether it's been more than N time since the last event.
+func (e *EveryN) ShouldProcess(now time.Time) bool {
+	var shouldProcess bool
+	e.Lock()
+	if now.Sub(e.lastProcessed) >= e.N {
+		shouldProcess = true
+		e.lastProcessed = now
+	}
+	e.Unlock()
+	return shouldProcess
+}

pkg/util/log/every_n_test.go → pkg/util/every_n_test.go

@@ -12,7 +12,7 @@
 // implied. See the License for the specific language governing
 // permissions and limitations under the License.
 
-package log
+package util
 
 import (
 	"testing"
@@ -41,8 +41,8 @@ func TestEveryN(t *testing.T) {
 		{11 * time.Minute, true},
 	}
 	for _, tc := range testCases {
-		if a, e := en.shouldLog(start.Add(tc.t)), tc.expected; a != e {
-			t.Errorf("ShouldLog(%v) got %v, want %v", tc.t, a, e)
+		if a, e := en.ShouldProcess(start.Add(tc.t)), tc.expected; a != e {
+			t.Errorf("ShouldProcess(%v) got %v, want %v", tc.t, a, e)
 		}
 	}
 }

pkg/util/log/every_n.go

@@ -17,25 +17,21 @@ package log
 import (
 	"time"
 
-	"github.com/cockroachdb/cockroach/pkg/util/syncutil"
+	"github.com/cockroachdb/cockroach/pkg/util"
 	"github.com/cockroachdb/cockroach/pkg/util/timeutil"
 )
 
 // EveryN provides a way to rate limit spammy log messages. It tracks how
 // recently a given log message has been emitted so that it can determine
 // whether it's worth logging again.
 type EveryN struct {
-	// N is the minimum duration of time between log messages.
-	N time.Duration
-
-	syncutil.Mutex
-	lastLog time.Time
+	util.EveryN
 }
 
 // Every is a convenience constructor for an EveryN object that allows a log
 // message every n duration.
 func Every(n time.Duration) EveryN {
-	return EveryN{N: n}
+	return EveryN{EveryN: util.Every(n)}
 }
 
 // ShouldLog returns whether it's been more than N time since the last event.
@@ -48,12 +44,5 @@ func (e *EveryN) shouldLog(now time.Time) bool {
 		// Always log when high verbosity is desired.
 		return true
 	}
-	var shouldLog bool
-	e.Lock()
-	if now.Sub(e.lastLog) >= e.N {
-		shouldLog = true
-		e.lastLog = now
-	}
-	e.Unlock()
-	return shouldLog
+	return e.ShouldProcess(now)
 }

pkg/util/tracing/shadow.go

@@ -24,7 +24,10 @@ import (
 	"context"
 	"fmt"
 	"os"
+	"time"
 
+	"github.com/cockroachdb/cockroach/pkg/util"
+	"github.com/cockroachdb/cockroach/pkg/util/timeutil"
 	lightstep "github.com/lightstep/lightstep-tracer-go"
 	opentracing "github.com/opentracing/opentracing-go"
 	zipkin "github.com/openzipkin/zipkin-go-opentracing"
@@ -110,15 +113,19 @@ func createLightStepTracer(token string) (shadowTracerManager, opentracing.Trace
 	})
 }
 
+var zipkinLogEveryN = util.Every(5 * time.Second)
+
 func createZipkinTracer(collectorAddr string) (shadowTracerManager, opentracing.Tracer) {
 	// Create our HTTP collector.
 	collector, err := zipkin.NewHTTPCollector(
 		fmt.Sprintf("http://%s/api/v1/spans", collectorAddr),
 		zipkin.HTTPLogger(zipkin.LoggerFunc(func(keyvals ...interface{}) error {
-			// These logs are from the collector (e.g. errors sending data, dropped
-			// traces). We can't use `log` from this package so print them to stderr.
-			toPrint := append([]interface{}{"Zipkin collector"}, keyvals...)
-			fmt.Fprintln(os.Stderr, toPrint)
+			if zipkinLogEveryN.ShouldProcess(timeutil.Now()) {
+				// These logs are from the collector (e.g. errors sending data, dropped
+				// traces). We can't use `log` from this package so print them to stderr.
+				toPrint := append([]interface{}{"Zipkin collector"}, keyvals...)
+				fmt.Fprintln(os.Stderr, toPrint)
+			}
 			return nil
 		})),
 	)