Encode Duration is tracked twice for the Threshold Tracing

From forums:https://forums.couchbase.com/t/encode-duration-is-tracked-twice-for-the-threshold-tracing/35362

QUICK SUMMARY

When logging slow operations Couchbase v3 exposes the duration of the encoding the operation in microseconds, it’s called encode_duration_us. I noticed that it has the larger value than expected. Investigating the code seems like a request span for the operation is Disposed twice which means that it adds this tag request_encoding_duration to the underlying activity object two times and to the parent activity 3 times.

DETAILS

Let’s consider an example with a get request. Get operation tracing is represented as a outer request span object. Then in the OperationBase.SendAsync method when encoding of the operation happens this outer span creates a child span for the encoding operation.

{{Task SendAsync(...)

{ ... using var encodingSpan = Span.EncodingSpan(); // encoding logic encodingSpan.Dispose(); // Dispose 1// send operation logic// Dispose 2}

}}
Every time the Dispose method is called on the span object, RequestSpan.End method is called which sets to the underlying activity this tag request_encoding_duration and then it moves all its tags to the parent activity:

{{void End() {
... case InnerRequestSpans.EncodingSpan.Name:

{ var durationStr = SetEndTimeAndDuration(); SetAttribute(ThresholdTags.EncodeDuration, durationStr); ... }

... if (parentSpan != null)

{ foreach (var activityTag in _activity.Tags) \{ parentSpan.SetAttribute(activityTag.Key, activityTag.Value!); }

}
}}}
So this means that when we call Dispose twice, we call End twice and we add that tag two times to the encoding activity object and three times (1 tag on first call + 2 tags on second call) to the parent activity object.

Then the ThresholdListener collects the total encoding value as a sum of these tags which 1) have two duplicated values and 2) one tag contains encoding + send time

Currently, from the client perspective this can be fixed by providing custom RequestTracer and RequestSpan classes to the SDK (thankfully it allows doing this).