Add option for limiting the number of logs in a Span #39

RaduBerinde · 2016-09-26T20:16:15Z

The MaxLogsPerSpan option limits the number of logs in a Span. Oldest
events are dropped as necessary. The first log in the finished span indicates how
many were dropped.

The default limit is 100.

Fixes #38.

CC @tschottdorf @bensigelman

jmacd · 2016-09-26T21:01:14Z

span.go

+	if maxLogs := s.tracer.options.MaxLogsPerSpan; maxLogs > 0 && len(s.raw.Logs) == maxLogs {
+		// We have too many logs. Overwrite the earliest log (use Logs as a circular
+		// buffer).
+		s.raw.Logs[s.numDroppedLogs%maxLogs] = ld


I would like us to drop from the middle of the span log, not from the beginning. A log would read something like:
log 0
log 1
log 2
** dropped 5 events **
log 8
log 9
log 10
log 11

Since this is a significant change, we should plan to do it consistently across basictracer libraries. I'd like to get @bhs and @yurishkuro to comment.

Interesting. Would that be about half of max before the dropped ones, and half after?
It's easy enough to implement whichever policy on my end; I will wait until there is agreement. It might be easier to access the discussion post-mortem if it's in #38 instead of here.

to make this efficient, how about treating the 2nd half of the array as a circular buffer?

Yes, that's what we would do (if folks agree on that policy).

yurishkuro · 2016-09-26T21:25:52Z

span.go

+		// dropped event.
+	}
+
+	// The MaxLogsPerSpan limit does not apply to BulkLogData.


The purpose of limiting is to cap memory usage. If the caller is supplying a huge BulkLogData, they are already storing that in memory. That said, I don't feel strongly - we can make those go through the normal limiting logic just as well.

fair enough - can you add this to the comments?

Sure, will do.

yurishkuro · 2016-09-26T21:26:56Z

tracer.go

@@ -87,7 +94,8 @@ type Options struct {
 // returned object with a Tracer.
 func DefaultOptions() Options {
 	return Options{
-		ShouldSample: func(traceID uint64) bool { return traceID%64 == 0 },
+		ShouldSample:   func(traceID uint64) bool { return traceID%64 == 0 },
+		MaxLogsPerSpan: 100,


@RaduBerinde you changed your mind about default being infinite?

Yes, as per the discussion in #38

yurishkuro · 2016-09-26T21:27:34Z

span.go

+		}
+		// Replace the oldest event. This means we are effectively dropping one more
+		// event.
+		s.raw.Logs[0].Event = fmt.Sprintf("** dropped %d events **", s.numDroppedLogs+1)


perhaps this makes more sense as a tag than a log

jmacd · 2016-09-26T21:34:28Z

@yurishkuro If it's a tag, then we don't know where the dropped logs span
begins and ends.
ᐧ

On Mon, Sep 26, 2016 at 2:27 PM, Yuri Shkuro notifications@github.com
wrote:

@yurishkuro commented on this pull request.

In span.go
#39 (review)
:
  // buffer in place, moving the first pos elements to the back. This
// algorithm is described in:
//  http://www.cplusplus.com/reference/algorithm/rotate
for first, middle, next := 0, pos, pos; first != middle; {
    s.raw.Logs[first], s.raw.Logs[next] = s.raw.Logs[next], s.raw.Logs[first]
    first++
    next++
    if next == len(s.raw.Logs) {
        next = middle
    } else if first == middle {
        middle = next
    }
}
// Replace the oldest event. This means we are effectively dropping one more
// event.
s.raw.Logs[0].Event = fmt.Sprintf("*\* dropped %d events **", s.numDroppedLogs+1)
perhaps this makes more sense as a tag than a log

—
You are receiving this because you were assigned.
Reply to this email directly, view it on GitHub
#39 (review),
or mute the thread
https://github.com/notifications/unsubscribe-auth/ADdiiRwl9YyR7uTxKIEzB9KpHeTIX6JVks5quDjGgaJpZM4KG8nA
.

RaduBerinde · 2016-09-26T21:40:29Z

Also, in some cases tags might not be visible everywhere where logs are. A prime example is NetTraceIntegrator which ignores tags (though that should be fixed IMO).

yurishkuro · 2016-09-26T21:47:38Z

then we don't know where the dropped logs span begins and ends.

hm, if your limit is 10 and you dropped 50 logs, how exactly do you know where the dropped ones begin? My reasoning is that the number of dropped logs is an attribute of the whole span, attaching a timestamp to that information (via log) does not have a lot of meaning.

RaduBerinde · 2016-09-26T21:51:20Z

I think what was meant was that the message makes it obvious which logs were dropped in relation to the ones which were not dropped. In the current change, the ** dropped ** message comes first so it's clear the older logs were dropped. In the proposal above, it comes in the middle; we definitely need some kind of "separator" between the oldest and the newest logs in that case.

jmacd · 2016-09-26T22:07:33Z

I was thinking that a limit serves two purposes:
(1) limit memory
(2) limit bandwidth
From the service's point of view (and network egress costs) it's useful to have a limit, and I would probably wish for it to be applied to bulk log data as well. Though I suppose if you're using bulk logs, you can limit it yourself.

As for the timestamp, my proposal was that by inserting a log record at the point were logs are dropped, at least the user can see two complete subsections of the log, the beginning up until the drop point, and the drop point to the end. I.e., there are two pieces of information, how many were dropped and which time range was dropped.

RaduBerinde · 2016-09-26T22:25:04Z

Sure, I will apply the limit to the bulk data as well.

Also, is the default limit of 100 ok? (I don't feel strongly about any particular value, I would just avoid setting it too small given that it will change the behavior of current users)

bhs · 2016-09-26T23:39:08Z

span.go

+		}
+		// Replace the oldest event. This means we are effectively dropping one more
+		// event.
+		s.raw.Logs[0].Event = fmt.Sprintf("** dropped %d events **", s.numDroppedLogs+1)


FYI, you have unlucky timing... this is not going to compile at master since the OpenTracing KV logging thing just landed today.

Thankfully, this is a good case for KV logging :)

RaduBerinde · 2016-09-27T00:33:31Z

Are there any objections to @jmacd's proposal to drop the events in the "middle"? If not, I will work on that.

bhs · 2016-09-27T00:39:07Z

@RaduBerinde I think @jmacd's "middle-out" (har har har) proposal is the optimal thing if you can spare the time. We did something similar with Dapper's version of this change and it worked well.

RaduBerinde · 2016-09-27T02:10:37Z

Updated to "middle-out" :)

One thing I'm not sure is how to "format" the "dropped logs" log record (see span.go:214).

bhs

NOTE: I didn't even try to review the possible off-by-one cases here. Aside from that caveat, the intent (and the default of 100) LGTM.

bhs · 2016-09-27T04:48:53Z

span.go

+		numNew := len(s.raw.Logs) - numOld
+		rotateLogBuffer(s.raw.Logs[numOld:], s.numDroppedLogs%numNew)
+
+		// Replace the log in the middle (the earliest "new" log) with information


terminology nit: can you do s/earliest/oldest/? It's an awkward term, but the only one that's unambiguous IMO. My brain things "early" means "new", though of course in this case they're opposite.

bhs · 2016-09-27T04:51:10Z

span.go

+			// Keep the timestamp of the last dropped event.
+			Timestamp: s.raw.Logs[numOld].Timestamp,
+			Fields: []log.Field{
+				otlog.String("event", "** dropped events **"),


my two cents:

[]log.Field{ otlog.String("event", "dropped Span logs"), otlog.Int("dropped_log_count", s.numDroppedLogs+1), otlog.String("component", "basictracer"), },

The "component" thing is just an idea... I think it'll make the error easier to track down for an unsuspecting tracing system user, though.

PS: what's the +1 for here? (I just copied it from you)

Adding component. +1 is explained by the comment above - we are overwriting an event, hence dropping one more.

Moving the +1 right next to the comment.

RaduBerinde · 2016-09-27T10:34:04Z

I see that Lightstep only shows the value of the event field. Should I include the number of dropped logs in the "event" string (at least for now)?

bhs · 2016-09-27T16:31:27Z

@RaduBerinde no, that is a lightstep limitation and it should be fixed on that side.

bhs · 2016-09-27T16:32:13Z

This LGTM... I'd like to wait for @yurishkuro and @jmacd to give a 👍 before merging, though.

yurishkuro · 2016-09-28T16:01:27Z

span.go

@@ -7,6 +7,7 @@ import (
 	opentracing "github.com/opentracing/opentracing-go"
 	"github.com/opentracing/opentracing-go/ext"
 	"github.com/opentracing/opentracing-go/log"
+	otlog "github.com/opentracing/opentracing-go/log"


this is the same as above

Oops, fixed.

yurishkuro · 2016-09-28T16:23:28Z

testutil_test.go

@@ -5,6 +5,7 @@ import (
 	"reflect"
 	"testing"

+	"github.com/cockroachdb/cockroach/util/caller"


I'd rather we didn't pull a new dependency purely for a nicer error message that never happens in practice.

Ah, definitely, didn't mean to do that. goimports is enabling my habits :)

Switched to runtime.Caller()

bhs · 2016-09-28T20:59:45Z

@RaduBerinde you'll need to rebase this one...

RaduBerinde · 2016-09-28T23:20:03Z

Updated. Thanks for the reviews!

bhs · 2016-09-29T00:06:21Z

LGTM. I'll give others until tomorrow to raise any other concerns before merging (esp @jmacd since @yurishkuro already approved the change). Thanks again!

The MaxLogsPerSpan option limits the number of logs in a Span. Events are dropped as necessary; a log in the finished span indicates how many were dropped. The default limit is 100. Fixes opentracing#38.

We added log limits to basictracer in opentracing/basictracer-go#39 This change sets better options for our tracers: - drop all logs for spans which we are not recording (those that go net/trace) - increase the default value of the new maxLogsPerSpan setting to 1000 Fixes cockroachdb#9529.

RaduBerinde force-pushed the logevent-limit branch from f95bbea to e4ed431 Compare September 26, 2016 20:16

RaduBerinde mentioned this pull request Sep 26, 2016

tracing: Transaction retries can consume unbounded memory cockroachdb/cockroach#9529

Closed

RaduBerinde force-pushed the logevent-limit branch from e4ed431 to ec9d41e Compare September 26, 2016 20:22

jmacd self-assigned this Sep 26, 2016

jmacd reviewed Sep 26, 2016

View reviewed changes

yurishkuro reviewed Sep 26, 2016

View reviewed changes

bhs reviewed Sep 26, 2016

View reviewed changes

RaduBerinde force-pushed the logevent-limit branch from ec9d41e to d0b305a Compare September 27, 2016 02:07

RaduBerinde force-pushed the logevent-limit branch from d0b305a to a0803ea Compare September 27, 2016 02:17

bhs reviewed Sep 27, 2016

View reviewed changes

RaduBerinde force-pushed the logevent-limit branch 2 times, most recently from fcd1b20 to a67d8c1 Compare September 27, 2016 10:33

yurishkuro mentioned this pull request Sep 27, 2016

Support a limit on the number of logs jaegertracing/jaeger-client-go#46

Closed

yurishkuro reviewed Sep 28, 2016

View reviewed changes

RaduBerinde force-pushed the logevent-limit branch from a67d8c1 to 492a88e Compare September 28, 2016 16:08

yurishkuro reviewed Sep 28, 2016

View reviewed changes

yurishkuro approved these changes Sep 28, 2016

View reviewed changes

RaduBerinde force-pushed the logevent-limit branch from 492a88e to 78912f6 Compare September 28, 2016 16:52

Add option for limiting the number of logs in a Span

723bb40

The MaxLogsPerSpan option limits the number of logs in a Span. Events are dropped as necessary; a log in the finished span indicates how many were dropped. The default limit is 100. Fixes opentracing#38.

RaduBerinde force-pushed the logevent-limit branch from 79ee6db to 723bb40 Compare September 29, 2016 02:40

RaduBerinde mentioned this pull request Sep 29, 2016

Add MaxLogsPerSpan option lightstep/lightstep-tracer-go#47

Merged

bhs merged commit 1b32af2 into opentracing:master Sep 29, 2016

RaduBerinde mentioned this pull request Sep 30, 2016

tracing: better basictracer options cockroachdb/cockroach#9641

Merged

Add option for limiting the number of logs in a Span #39

Add option for limiting the number of logs in a Span #39

Conversation

RaduBerinde commented Sep 26, 2016 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jmacd commented Sep 26, 2016

@yurishkuro commented on this pull request.

RaduBerinde commented Sep 26, 2016

yurishkuro commented Sep 26, 2016

RaduBerinde commented Sep 26, 2016

jmacd commented Sep 26, 2016

RaduBerinde commented Sep 26, 2016

Choose a reason for hiding this comment

RaduBerinde commented Sep 27, 2016

bhs commented Sep 27, 2016

RaduBerinde commented Sep 27, 2016

bhs left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

RaduBerinde commented Sep 27, 2016

bhs commented Sep 27, 2016

bhs commented Sep 27, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

yurishkuro Sep 28, 2016 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bhs commented Sep 28, 2016

RaduBerinde commented Sep 28, 2016

bhs commented Sep 29, 2016

RaduBerinde commented Sep 26, 2016 •

edited

Loading

yurishkuro Sep 28, 2016 •

edited

Loading