ddtrace/tracer: update log msg to accurately count dropped traces (#2845

)

ddtrace/tracer/spancontext_test.go

@@ -148,6 +148,25 @@ func TestSpanTracePushOne(t *testing.T) {
 	assert.Equal(0, len(trace.spans), "no more spans in the trace")
 }
 
+// Tests to confirm that when the payload queue is full, chunks are dropped
+// and the associated trace is counted as dropped.
+func TestTraceFinishChunk(t *testing.T) {
+	assert := assert.New(t)
+	tracer := newUnstartedTracer()
+	defer tracer.statsd.Close()
+
+	root := newSpan("name", "service", "resource", 0, 0, 0)
+	trace := root.context.trace
+
+	for i := 0; i < payloadQueueSize+1; i++ {
+		trace.mu.Lock()
+		c := chunk{spans: make([]*span, 1)}
+		trace.finishChunk(tracer, &c)
+		trace.mu.Unlock()
+	}
+	assert.Equal(uint32(1), tracer.totalTracesDropped)
+}
+
 func TestPartialFlush(t *testing.T) {
 	t.Setenv("DD_TRACE_PARTIAL_FLUSH_ENABLED", "true")
 	t.Setenv("DD_TRACE_PARTIAL_FLUSH_MIN_SPANS", "2")

ddtrace/tracer/tracer.go

@@ -81,6 +81,11 @@ type tracer struct {
 	// finished, and dropped
 	spansStarted, spansFinished, tracesDropped uint32
 
+	// Keeps track of the total number of traces dropped for accurate logging.
+	totalTracesDropped uint32
+
+	logDroppedTraces *time.Ticker
+
 	// Records the number of dropped P0 traces and spans.
 	droppedP0Traces, droppedP0Spans uint32
 
@@ -276,6 +281,7 @@ func newUnstartedTracer(opts ...StartOption) *tracer {
 		rulesSampling:    rulesSampler,
 		prioritySampling: sampler,
 		pid:              os.Getpid(),
+		logDroppedTraces: time.NewTicker(1 * time.Second),
 		stats:            newConcentrator(c, defaultStatsBucketSize),
 		obfuscator: obfuscate.NewObfuscator(obfuscate.Config{
 			SQL: obfuscate.SQLConfig{
@@ -451,7 +457,15 @@ func (t *tracer) pushChunk(trace *chunk) {
 	select {
 	case t.out <- trace:
 	default:
-		log.Error("payload queue full, dropping %d traces", len(trace.spans))
+		log.Debug("payload queue full, trace dropped %d spans", len(trace.spans))
+		atomic.AddUint32(&t.totalTracesDropped, 1)
+	}
+	select {
+	case <-t.logDroppedTraces.C:
+		if t := atomic.SwapUint32(&t.totalTracesDropped, 0); t > 0 {
+			log.Error("%d traces dropped through payload queue", t)
+		}
+	default:
 	}
 }