Add the ability to store/retrieve incomplete/partial spans

[vprithvi]

Summary

Allow clients to export partial spans, to support two use cases:

• Flush a long running span before it is finished, in case the process crashes before finishing it
• Enrich existing span with information from other sources, e.g. to record log events not captured via tracing SDK

Details

For the first version of this feature, we shall assume the following

• clients can flush and report partial spans; but not span deltas
• duration is monotonically increasing
• the final span has the longest duration

For e.g., a client can do the following
time = 1s
Report Span[traceID=1, spanID=2, duration=10s, operationName="someOperation"]

time = 2s
Report Span[traceID=1, spanID=2, duration=20s, operationName="someOperation"]

time = 3s
Report Span[traceID=1, spanID=2, duration=40s, operationName="someOperation", tags=...]

To support this, the backend would need the ability to resolve merge conflicts on spans. For V1, this means simply selecting the longest span.

On Cassandra, the jaeger-collector uses the model spanhash, guaranteeing that all partial spans are stored:

jaeger/plugin/storage/cassandra/spanstore/dbmodel/converter.go

Line 45 in 412baf6

spanHash, _ := model.HashCode(span)

jaeger/model/span.go

Lines 63 to 66 in fcbd210

	func (s *Span) Hash(w io.Writer) (err error) {
	// gob is not the most efficient way, but it ensures we don't miss any fields.
	// See BenchmarkSpanHash in span_test.go
	enc := gob.NewEncoder(w)

On ElasticSearch, we use the index api, which performs upserts.

jaeger/plugin/storage/es/spanstore/writer.go

Lines 179 to 182 in e52ecff

	func (s *SpanWriter) writeSpan(indexName string, jsonSpan *jModel.Span) {
	elasticSpan := Span{Span: jsonSpan, StartTimeMillis: jsonSpan.StartTime / 1000} // Microseconds to milliseconds
	s.client.Index().Index(indexName).Type(spanType).BodyJson(&elasticSpan).Add()

To make matters more interesting, note that Jaeger supports storing Zipkin spans that share the same spanID for client and server spans. Jaeger adjusts these spanIDs during query time as seen here:

jaeger/model/adjuster/span_id_deduper.go

Lines 23 to 31 in 412baf6

	// SpanIDDeduper returns an adjuster that changes span ids for server
	// spans (i.e. spans with tag: span.kind == server) if there is another
	// client span that shares the same span ID. This is needed to deal with
	// Zipkin-style clients that reuse the same span ID for both client and server
	// side of an RPC call. Jaeger UI expects all spans to have unique IDs.
	//
	// This adjuster never returns any errors. Instead it records any issues
	// it encounters in Span.Warnings.
	func SpanIDDeduper() Adjuster {

Another point to note is that jaeger-collector makes no guarantee that spans are stored in the order that they are received.

Enhancements

1. Communicate that jaeger-query is serving incomplete spans to the user. One approach is to do something similar to Icon / demarcation for client spans with no responding server span jaeger-ui#132. We might have to enhance the Span model to store this information
2. Allow for jaeger-clients to report that the span it is sending is the final span. This allows us to remove the assumption about monotonically increasing duration.
3. Add support for span deltas, which might allow for clients to reduce state maintained. (Might be at odds with the previous point)
4. Enhance Span model to store the lineage of a span (whether it was generated from a Zipkin or Jaeger span), this allows for more robust merging behavior

For more context on use cases and prior discussion see jaegertracing/jaeger-client-java#231

Similar tickets:

• Incomplete span support #979
• Support receiving duplicate spans keeping only the latest #3790

[yurishkuro]

I am not sure why we need phase 1-2 approach and restrictions. Could we not just merge all spans into one? Rules would be:

• tags and lots are merged as sets
• operationName and flags are taken from span with largest duration
• start time is the earliest of all
• duration can be either the largest or calculated from the latest endTime(i)=startTime(i)+duration(i)

Enhance Span model to store the lineage of a span (whether it was generated from a Zipkin or Jaeger span), this allows for more robust merging behavior

I don't think lineage is really relevant. Zipkin style spans should be deduped using span.kind = client/server distinction.

[vprithvi]

I am not sure why we need phase 1-2 approach and restrictions.

We don't really, if we agree on the merge rules, it may be simpler to implement the rules in one go.

We might still need the restriction that the final span has the longest duration, (or some other method of denoting the last span sent by a client for a specific span id)

[de-robat]

By the proposal made in jaegertracing/jaeger-client-java#231 where you've already referenced this discussion, the last span would be either denoted by a specific flag such as beeing complete or by having a duration at all. I don't know if that's possible but all in between spans would probably still report 0 duration because while still being running the duration information is redundant after all or isn't it? At least that's what i've understood form that discussion.

[phal0r]

I was discussing with @black-adder about the approach described in jaegertracing/jaeger-client-java#231 and want to summarize our findings here so far:

One important requirement is not to change the cassandra schema in order to keep updates of jaeger simple. Therefore I want to split the enhancements necessary in "before persistence" and "after persistence".

To allow for easier distinction of partial and complete spans after persistence, I would suggest to change the assumptions to

• a partial span always has a duration of 0
• the final span always has a duration > 0

Before persistence

• Clients can optionally send an "incomplete" flag to indicate if this span is partial or not
• Clients should report a duration of 0 for partial spans and the correct duration for the final span
• Thrift SpanModel gets attribute "incomplete"
• DomainSpan gets the attributes "incomplete" and "type" (which can be 'jaeger' or 'zipkin')
• JsonSpan gets attribute "incomplete", but it will be populated only during incoming spans requests, not when reading from storage

The type attribute for the domain model is necessary to enable cassandra and es writers to distinguish between replacing partial jaeger spans logic and zipkin server and client have same spanId logic. The type will not be persisted.

The writer needs to distinguish between both aforementioned logics, cause UPSERTs will only work with a stable identifier (cassandra primary key and es document id). Current writer logic would not allow for this, because

• the es indexer will generate a random document id for every call
• the cassandra spanhash does not take into account, that a final span may have additional logs/tags/changes

In my approach we enhanced both writers as follows:

• es writer in writeSpan function

if jaegerSpanType == model.JaegerSpanType {
	_, err = s.client.Index().Index(indexName).Type(spanType).Id(string(jsonSpan.TraceID) + string(jsonSpan.SpanID)).BodyJson(&elasticSpan).Do(s.ctx)
} else {
	_, err = s.client.Index().Index(indexName).Type(spanType).BodyJson(&elasticSpan).Do(s.ctx)
}

The Id(stable identifier) call is necessary to allow for UPSERT, but we don't want to replace zipkin spans with the same spanId, because of client/server spans having the same spanId. Therefore the distinction.

• cassandra writer, enhancing DomainSpan.Hash function

//with supporting incomplete spans the hash needs to be unique for a combination
//of spanId and traceId, so the final representation of the same span
//will overwrite the incomplete version in cassandra
if s.Type == JaegerSpanType {
	return enc.Encode(JaegerSpanHash{s.TraceID, s.SpanID})
} else {
	return enc.Encode(s)
}

The primary key comprising of spanId, traceId and a hashed representation of the spans remains, we just switch to only hashing traceId and spanId for spans received from jaeger clients, thus having a stable identifier regardless of additonal logs/tags or whatsoever.

After persistence

Since we don't want to change the schema, we won't have any additional information if a span is partial or not. We could stick to the assumption, that a partial span always has a duration of 0 and a completed span always has a duration > 0.

-Jaeger-UI could distinguish and mark spans as partial, when duration is 0

• In this approach no changes would be necessary in the deduper, since partial spans will always be replaced with the next incoming incarnation of this particular span
• The clock adjuster (

  jaeger/model/adjuster/clockskew.go

  Line 148 in 412baf6

  func (a *clockSkewAdjuster) calculateSkew(child *node, parent *node) time.Duration {

  ) needs to check for spans with a duration of 0 in the following cases

1. parentSpan is partial and childSpan is complete
   -> parentDuration < childDuration, therefore no adjustment will be done with the current logic
2. parentSpan and childSpan are partial
   -> this would basically lead to a delta parentStartTime - childStartTime and therefore adjusting the child span to the same startTime the parent has
3. parentSpan is complete and childSpan is partial
   -> childSpan will be adjusted to parentDuration/2 if the childStartTime is before parentStartTime
   -> if childStartTime is between parentStartTime and parentEndTime no adjustments will be made

So we probably need to incorporate changes for 2. and 3.
-> for 2 we should just check that childStartTime is adjusted to be >= parentStartTime, checking for endTimes makes no sense, since they are not known at this point
-> for 3 we should check that childStartTime is between parentStartTime and parentEndTime, but what would we want to adjust it too? Maybe parentDuration/2 is already a good approach?

I can provide a Pull Request with the changes described here (except the ClockAdjuster), so you guys can get a more detailled impression of the changes, I just need to fix one last failing test and can reference it here then :)

[yurishkuro]

Why is it necessary to ensure upsert? I think a simpler solution is to merge spans on read.

[phal0r]

I took this approach, because only the last span is relevant (at least this is my assumption) and it is much friendlier for storage not to keep all intermediate representations. Do you think storage size is not an issue?

[yurishkuro]

Hasn't been in the cases we encountered. But in some cases it's not even an option, it's a requirement to save all partial spans. E.g. we have a system that executes long running (on the order of days) workflows, and it persists the intermediate state in the database. The start and finish events of a span may not even be in the same process.

[phal0r]

Ok, that makes sense. Would have been good to know that before :)

So with this approach, the question is, how to model a final span, right? In #728 @black-adder already suggested to use a flag. In my understanding adding a new finalFlag constant like (https://github.com/jaegertracing/jaeger/blob/master/model/span.go#L27)
would allow to detect final spans without altering the db schema of cassandra, because it's a uint32
https://github.com/jaegertracing/jaeger/blob/master/plugin/storage/cassandra/spanstore/dbmodel/model.go#L28
That removes the necessity for any other incomplete attribute and aligns quite well with the current data model (at least if i understood the purpose of flags correctly). The clients could easily implement setting the flag in their span.finish() methods.

With a isFinal flag my suggested approach with a duration of 0 to distinguish between final and partial spans wouldn't be necessary aswell.

[yurishkuro]

My concern with using the flags field is in changing its semantic meaning and scope. Right now we're using it merely to store the value of spanContext.flags, i.e. the thing that is propagated over the wire. @phal0r 's proposal would change it to also carry information that is only meaningful for the backend, and meaningless in the propagation format.

I don't have strong objections to using the duration field. It does have a few drawbacks:

1. it is theoretically possible, on system with low precision clocks (like milliseconds) for the duration to be 0 even on the finished span.
2. it's a poor man's substitution for a proper field in the Span model, mixing different concerns
3. it does not allow full ordering of the span fragments

The downsides of introducing a dedicated field on the Span is mostly the implementation churn where we need to add it to the data model, update DB schemas everywhere, etc, I think internally we went with the approach based on duration - @vprithvi can you confirm?