Zipkin: Can we help uncover or explain span reporting lag?

[adriancole]

from @dan-tr

@dan-tr Sep 28 23:09
Is timestamp_millis created based on the timestamp field or is created based on the current time when the record is inserted into ES? I'm looking for away to discern if there is any lag time between the message being put on the Kafka queue (client-side) and the record being stored in ES (server-side).

We should add the description to the README here, but no. this timestamp isn't used for lag, it is based on the best timestamp.
https://github.com/openzipkin/zipkin/tree/master/zipkin-storage/elasticsearch

timestamp + duration would be the time a span was recorded and eligible to be sent. In https://github.com/openzipkin/zipkin-reporter-java, and other libraries, there would be up to a second before the span goes on the wire.

We could look at our local endpoint vs one of the endpoints in the span and try to determine roughly the lag, based on limitations of clock skew guessing. If we did, we'd likely record that as a stat vs put it into the span... unless we created a "fake span" which we then recorded against zipkin-server.

Another option would be to accept traces originated by reporters. Ex start a trace when the span was sent. In kafka, we'd have to hijack the message key, which isn't a problem in zipkin topics. https://github.com/openzipkin/brave/pull/212

Thoughts?

[dan-tr]

Actually, I think all I am really looking for is when did the record get inserted into Elasticsearch. If Zipkin does only inserts, then I am looking for the record creation timestamp. If it does inserts and updates, then I am looking for the last update timestamp.

So I don't think any calculation needs to be done. Zipkin just needs to store the current time on each insert/update.

In production this timestamp can be valuable when something goes wrong and you want to know the last time Zipkin wrote anything to ES.

Does that make sense?

[adriancole]

we could add this, but it will be the third timestamp field, which makes me
reluctant.

Would metrics be reasonable way to track the last write attempt?

https://github.com/openzipkin/zipkin/tree/master/zipkin-server#collector

[adriancole]

ps @openzipkin/elasticsearch this topic is a pretty opsy one. anyone doing something similar and have opinions?

ex. timestamp(_millis) is a semantic field for the span. If someone wanted to know the created_at, well elasticsearch doesn't do that. The question here, is should we? if so, how can we label such a field so that it isn't confused with the timestamp reported by the apps?

[dan-tr]

I agree this is pretty opsy. I think logstash does this by adding an @ sign to the front of the field. Maybe Zipkin could use the same convention.

[yurishkuro]

In similar situations (ingesting from a queue-like pipeline) we simply emit a metric as timer("ingestion.latency", time.Now() - span.startTime). Wouldn't this be sufficient for this use case, rather than storing it in ES?

[shakuzen]

+1 for metrics over adding a meta field to the data model.

[dan-tr]

Where is the metric emitted to? And how does it correlate that to the record written to Elasticsearch? Seems like we would need to emit the ingest latency along with the span id.

[adriancole]

I think the key thing here is that Dan is looking for a per-message
accounting of latency vs an aggregate one (ex via metrics). This is the
first time such a request has come up (ex hasn't happened on any other
storage system). That may be because spans are lossy and so not guaranteed.
Maybe people aren't looking at spans one-at-a-time knowing that. I can
certainly understand that when troubleshooting or setting up the system for
the first time, something like this could be handy!

To answer the question, the server's /metrics endpoint is json and there's
also a prometheus metrics endpoint exposed. Regardless of monitoring system
used, these metrics would need to be collected to be useful in any way.

[adriancole]

I think that we should add (and define) latency metrics as an initial step, since this would be useful regardless of the storage backend. Will keep this issue open about the forensic investigation on a span-by-span basis.

ps opened this to help showcase metrics in use https://github.com/openzipkin/docker-zipkin/issues/121

[dan-tr]

Maybe the insert timestamp could be an optional field turned on either through an environment variable or maybe the Elasticsearch template (not sure about that).

Because we are using async messaging (via Kafka) there is always the possibility of a message backlog. Knowing the insert date would be very help in deducing how far behind the server is in processing the backlog.

[adriancole]

Since this is not supported in other storage layers, and others don't seem
interested. I'm hesitant about adding an if statement, environment variable
and another hack.

I also don't like how close the variable name is to the other two
timestamps. It really feels like tech debt.

Since this is for manual troubleshooting, what about encoding the stored
timestamp into the id of the document? This is done with cassandra iirc and
wouldn't clutter the json with another similar field. We would assign an id
that encodes the timestamp instead of having elasticsearch generate one.
Would that work for you?

[adriancole]

here's a concrete counter-offer :)

since we don't change spans after writing them to ES, we can use a timestamp convention for the document ids.

Ex. something like $epochmillis-$traceId.$spanId. The trace and span id would help ensure against collision. It is unlikely a span will be reported twice in the same millisecond.

So, if I wrote the same span successively (for client and server), it would look like the following rows:
"1475335327601-0000000000000001.0000000000000003"
"1475335439449-0000000000000001.0000000000000003"

This would be a longer id than the normal ones in ES, and not good for any automated analysis, could be helpful to answer your question about when the span was stored without defining another field. Is this worth doing?

[dan-tr]

Hum... To me that feels like we would be overloading a data field for two different purposes (for timestamping and identification).

I think for now I would prefer to just let this issue "percolate" for a while and see anyone else asks for it.

No point making a change like this just for me :smiley:

[adriancole]

Hum... To me that feels like we would be overloading a data field for two
different purposes (for timestamping and identification).

indeed that's what it would be :)

I think for now I would prefer to just let this issue "percolate" for a
while and see anyone else asks for it.

No point making a change like this just for me 😃

yeah usually issues like this end up with multiple requestors, thanks for
deferring until then

[mansu]

+1 for this feature. I was looking through my spans today and was wondering what time they were ingested. I used a crude '/zipkin-/_stats' end point to see when the index was last written to but having a timestamp field on the ingested span would make this process a lot easier.

I think the best way approach here is to add an @timestamp field to every span that is ingested. The value of the @timestamp field would be the time the span is written to ES. This is a standard practice for other logs ingested by logstash, so it is not odd thing to do in ES land. Since this change is localized to the ES module, it shouldn't impact other storage engines or the interface.

[adriancole]

Thanks, suman. Can someone cite the practice with a link? busy-work I know,
but I'm fine with doing this, just want to borrow this rationale in code
comments.

[adriancole]

I did some digging and I don't like using @timestamp.

Firstly, seems logstash format it in iso8601 which is unnecessary overhead and distraction (to add a formatter to our code). https://github.com/elastic/logstash/blob/master/logstash-core-event/lib/logstash/timestamp.rb

Next iso8601 doesn't help you compare lag using other timestamps which are in epoch millis (and also epoch micros), just makes busy work to convert one or the other.

Finally, it is a special field for logstash. I've seen some references suggesting even that it is internal. It seems they have changed formatting before. I don't like the idea of misleading people into thinking this is logstash interop and then that accidentally breaking.

My thought is that if we are to do this, be specific in a way where we can inform people what to do with this. Ex. collector_timestamp (because we don't have a component named ingestor), and make it epoch millis as that's the least overhead and burden for those who will never read this.

WDYT?

[mansu]

@adriancole I looked at the code earlier and had the same feeling. I was looking for a better idea but can't think of one. I like your suggestion. However, I would prefer the name of the field to be collector_timestamp_millis

[dan-tr]

I like the field name collector_timestamp_millis as well.

[adriancole]

here's the fix https://github.com/openzipkin/zipkin/pull/1328

[adriancole]

In testing the new ES 5 support, I found that our hypothesis, which is that the new ingest node functionality can address this.. well it is supported.

The following stuff works like a champ and requires no zipkin change except to punch a hole to specify a pipeline id

PUT _ingest/pipeline/my-pipeline-id
{
  "description" : "add collector_timestamp_millis",
  "processors" : [
    {
      "set" : {
        "field": "collector_timestamp_millis",
        "value": "{{_ingest.timestamp}}"
      }
    }
  ]
}