logging spans via kafka or HTTP appear to be done in one big batch, synchronously

[trtg]

after instrumenting the POST handler in some production code, we noticed that the service receiving the response from that POST handler was timing out. I dug in with wireshark and noticed that at the end of our POST handler a ton of traffic is being emitted to kafka and then finally the desired HTTP response is sent to the client. If I completely remove the zipkin_span() call, the network traffic to zipkin goes away of course and > 100ms of latency is removed from the response. Jaeger instrumentation has no such issues, so I may just switch to that, but it would be nice to know what is going on? Am I missing some configuration setting that keeps my app from being tied up with kafka traffic ? It's important to note here that this issue happens regardless of transport_handler. If I use the http_transport implementation shown in the README, instead of a ton of synchronous kafka traffic at the end of my POST handler I just end up with a bunch of synchronous POSTS to the zipkin API.

[kaisen]

This seems like it's due to the recent PR #52 that added batched sending. The default batch size is set to 100 which in retrospect may be too large. There is an override param available for zipkin_span() called max_span_batch_size. Does setting this to 5 or something fix your issue?

[codefromthecrypt]

synchronous seems to be the more concerning issue here

[trtg]

@kaisen I'm running a version of py_zipkin prior to PR #52 i havent pulled in updates in a bit. So in the version I have max_span_batch_size is not yet a parameter. Are you saying that prior to the parameter existing, it just defaulted to 100? I don't really understand how py_zipkin emits its spans. Jaeger seems to be making use of a tornado event loop to do this asynchronously. I am able to leave jaeger instrumentation on with no apparent overhead in terms of latency.

[kaisen]

@trtg ah ok, if you're version isn't the latest, then spans are sent individually, so max_span_batch_size is both unavailable and irrelevant.

py_zipkin emits logs via the given transport_handler function (see https://github.com/Yelp/py_zipkin/blob/v0.8.3/py_zipkin/logging_helper.py#L334 for versions prior to the current v0.9.0). We don't provide anything out of the box so you would have to implement your own async transport_handler.

[codefromthecrypt]

We don't provide anything out of the box so you would have to implement your own async transport_handler.

would it make sense to change the example transport_handler to use tornado? Is it a lot of code? (ik this would be a separate issue, but maybe prevent this problem for those copy/pasting)

[bplotnick]

@trtg I'm not sure what your application is doing, but I suggest looking at something like flask-zipkin or pyramid-zipkin. Both of these defer the logging until after the response is returned by using middleware, which is a much simpler than using an event loop IMO.

@adriancole I think it's reasonable to have an example of async sending. I'll ticket this up and we can write something simple, maybe using asyncio or something.

I do still think that doing synchronous sending outside of the critical path is a better strategy considering that the alternatives are that you are either going to be using 1) threads/processes which have synchronization cost or 2) an event loop, which is concurrent, but not parallel.

The downsides being that 1) the spans will be delayed until the end of the request context, which may not be ideal for long running requests and 2) you have to store all of the spans in memory, which may not be ideal for a context with a large number of spans.

[codefromthecrypt]

The downsides being that 1) the spans will be delayed until the end of the request context, which may not be ideal for long running requests

FWIW most folks delay reporting until a request completes by default, flushing after a timeout (often 30s).

2) you have to store all of the spans in memory, which may not be ideal for a context with a large number of spans.

A memory budget seems a reasonable way out. That or keep tags (binary annotations) to a minimum which makes size/span roughly constant (as most do in zipkin), and inform users that when they add large tags it increases the memory overhead and undoes this assumption

[trtg]

@bplotnick my application is very high volume, i.e. thousands of requests per second with somewhat tight real-time deadlines. Since this additional latency is present even when sampling percentage is zero, I'm currently exploring swapping in jaeger (assuming it doesn't have the same issues with clock skew I ran into with zipkin- it works fine in docker so far). I'll take a look at flask-zipkin and pyramid-zipkin but it would be nice if the sending of spans happened outside the critical path, as you said.

I do wonder about the memory issue you noted. It obviously would not be good if the boxes emitting spans hit OOM issues because the collector was unreachable. I'm rather curious how jaeger avoids this issue(assuming it does) given that its architecture requires an agent running on every box and forgoes a queue like kafka.

[bplotnick]

@trtg py_zipkin certainly takes a less opinionated approach than jaeger, but i do encourage you to pick the right tool for the job, even if that isn't py_zipkin. We also love pull requests 😄

I'll say that we actually have a similar system as what you describe in place at Yelp by using scribe for our transport. This runs a leaf process on each box that allows you to write quickly locally (but still outside of the critical path).

For the memory usage concern, we also leave that up to the user. If our users start adding too many binary annotations or emitting too many spans in a given process, it is up to them to either reduce this amount or use a different transport handler. In my experience, however, the applications that tend to do this are already memory bloated already, such that the additional py_zipkin overhead is still negligible :P