Statsd - Tracking timing across the stack

Question

I'm using statsd (the django-statsd library to be exact) to track timing metrics on my application. Issues arise when I need to test something across multiple levels of the stack. A prime example: an object is created, a post_save method is called from that object, a celery task is then triggered from there, which subsequently triggers another celery task that calls out to twilio to send a text message to a user, which finally hits up an endpoint on my server letting me know that the text was successfully sent.

I'd love to track the overall time of this without having to resort to manually piecing together the timing of each function (which, anyway, loses the latency time between the calls). I'd also like to avoid writing "start times" to a database to refer to at the end of the call-stack trip, as the database lookup time for a start time would also distort my metrics. However, a call to some sort of cache might be low latency enough to be negligible. But that requires a little more infrastructure than I was hoping to need at this prototype stage.

Any ideas on the best approach for this?

Answer 1

I'd also like to avoid writing "start times" to a database to refer to at the end of the call-stack trip, as the database lookup time for a start time would also distort my metrics. However, a call to some sort of cache might be low latency enough to be negligible.

Statsd is the right thing for this as it defaults to UDP, making it a fire-and-forget mechanism with little overhead. Also, since UDP is asynchronous, the function throwing the packet does not wait for ACK and promptly moves on.

Any ideas on the best approach for this?

And you can profile latency too, though it will require a little going out of the way. If you want no extra variables to be passed from function to function to module, then you'd have to 'process' the raw data according to the semantics of your control-flow.

a(){
    statsd(a.begin_time)    
    ...
    statsd(a.end_time)
}
.........................
.......LATENCY SEA.......
.........................

b(){
    statsd(b.begin_time)
    ...
    statsd(b.end_time)
}

.........................
.......LATENCY SEA.......
.........................

c(){
    statsd(c.begin_time)
    ...
    statsd(c.end_time)
}

Because 'B comes after A' in the control flow-

latency(a,b) = b.begin_time - a.end_time