Why is the number for "response time" in my logs different than "time-to-first-byte"?
|
|
Problems can arise in performance work when you don't understand what a number means. That is, if you don't understand what the number is measuring or what it says about the system's state.
One common area of confusion and misconception is around the metric of "response time".
What makes response time confusing is that it actually contains many parts, and that it changes based on where we measure it. An application's response time will be different from each of these perspectives:
- The Rails application code
- The application server (e.g. Puma, Unicorn)
- The load balancer (e.g. the Heroku dyno mesh, NGINX)
- The client (e.g. the browser)
That's because each of these perspectives adds an additional layer onto the response time because each layer does something different.
I want to now address a question I received on Twitter from @sir__ko:
Hey @nateberkopec: Rails Server says "Completed 200 OK in 2ms" and TTFB results in ~13ms. Any clue where this difference might come from? Running a fresh/blank rails app on localhost. Best regards
These two "response time" numbers are being measured in two different places with two different perspectives: the first is being measured in the Rails application code itself, and the second is being measured at the client. So, the reason for the difference (~9 milliseconds) here is that there's lots of things that happen between the Rails application measuring how fast it created a response, like this:
time = Time.now
yield
duration = Time.now - time
... and the browser, which is measuring time between sending a network request and receiving a response.
What are those things? Let's go through them step-by-step.
1. Your Rails application has to create a valid response. We can think of a Rails application like a big function that takes a URL, a cookie, and some query parameters as input, and then produces HTML as output. This takes a certain amount of time. In the case of sir__ko's application, this took 2 milliseconds, as reported in the log.
2. Your application server has to accept a network connection, buffer the contents, and parse a valid HTTP request to pass to the Rails application. This takes time too. In fact, it can actually take a lot of time, especially when your Puma/Unicorn is under a lot of load, and all of its workers and threads are already busy with work.
3. The load balancer. Though fast, these steps are not free. Often they add a millisecond or three, just by virtue of passing a request around the internal network of your chosen cloud provider.
4. The client has to send a network request hurtling across the internet at the speed of light, which, while fast, still takes tens or even hundreds of milliseconds. The response time metric observed at the client includes: RAILS_TIME + PUMA_TIME + LOAD_BALANCER_TIME + NETWORK_TIME, while the Rails application logs only include RAILS_TIME.
Even when you're doing this on your local machine, you're still going to see steps 2 and 4. The local network interface, while cheap, is not free, and you'll probably see a few milliseconds added on just from CPU contention and timeslicing between your application code and the network stack.
I hope this clarified a bit about why response times are more complicated to interpret than you might think. If you'd like a real world example of when the exact definition of "repsonse time" ended up mattering quite a lot in a Rails application, take a look at Routergate, which was an incident with Heroku and Genius where Heroku and New Relic incorrectly reported time spent queueing for a free worker process. Whoopsy!
Until next week,
-Nate
|
|
|
|