Heroku | how to read router logs

Question

So my typical router log on the Cedar platform looks might look like

2012-03-22T18:26:34+00:00 heroku[router]: GET [my_url] dyno=web.9 queue=0 wait=0ms service=228ms status=302 bytes=212
2012-03-22T18:26:36+00:00 heroku[router]: GET [my_url] dyno=web.7 queue=0 wait=0ms service=23ms status=200 bytes=360
2012-03-22T18:26:45+00:00 heroku[router]: GET [my_url] dyno=web.30 queue=0 wait=0ms service=348ms status=201 bytes=1

I want to confirm my understanding of the terms queue, wait and service

My initial thoughts where that:

• queue: The name of the queue if using background_job or resque
• wait: how long is the request waiting in the router (Request Queueing in New Relic)
• service: how long it actually takes your application to handle the request (not including queing time)

But my wait in my logs is always 0ms. Even if I have significant backlog.

Are my definitions wrong?

Calumnious

You say your wait is always 0ms, if the queue is also 0, how do you know you have a backlog outside of this? – Generalize

So for example, take serving my crossdomain.xml -- a static file, that on low loads response within 10ms. At high loads it can be 6000ms+ all the way up to the 30s timeout. I would expect most of that time to be on queue and wait. – Calumnious

Also, when I add more dynos, the service time goes down, and vice-versa – Calumnious

Answer 1

• Queue: The number of requests waiting to be processed by a dyno.
• Wait: The length of time this request sat in the queue before being processed.
• Service: The processing time of the request.

Your total response time will be wait + service.

Generalize

Can you explain a bit more what "service" means? Does it mean, the time it took to run through whatever scripts before sending a response or is it some internal timer that doesn't have anything to do with the code one wrote? – Petie

"the time it took to run through whatever scripts before sending a response" - This. – Generalize

As a caveat, the "service" time seems to take into account network time. This is most likely similar to how "time-taken" in IIS logs works. microsoft.com/technet/prodtechnol/WindowsServer2003/Library/IIS/… I base this off a comparison of some long running items (~20+ sec) according to "service", and comparing with the breakdown given by new relic's "real user monitoring" which indicates nearly 100% of that time is "network" time. – Bohs

I can confirm the above - and if you're using Heroku's SSL Endpoint you seem to take a big hit. I see great figures in New Relic for my app, but the logs and Blitz.io both agree that performance collapses at about 50 requests per second per dyno. – Latanya

I do not see queue information in Heroku Logs.. do you I need to enable it in some way? Or have they removed this.. – Demonology

They may have removed this as they changed the stats after Hipmunk called them out for publishing misleading stats. Have a look at some of Heroku's recent blog posts. – Generalize

How did you get these definitions? Can someone provide a URL to some docs? I see devcenter.heroku.com/articles/logging and it isn't precise with definitions. – Nathanson