X-Runtime header doesn't seem to be reliable

rubyonrails-core
1

As far as I understand, Rails uses a middleware by default that will send the total time spent on a request in the Rails side in the X-Runtime HTTP header.

But it doesn't seem to be reliable in the sense that when I perform a request against http://localhost:3000/ (development environment, tested with both Puma and Webrick), I get 10ms of latency when serving some CSS assets but 109ms of latency for the index page. When I look at the header for the same request, I get "X-Runtime: 0.034849".

Here's how it reports the timing in the server logs:

Completed 200 OK in 22ms (Views: 1.4ms | Sequel: 13.2ms)    Rendered search/_fields_finder.html.erb (0.0ms)    Rendered search/_left_pane.html.erb (0.7ms)    Rendered search/_index.html.erb (8.9ms)    Rendered transactions/_list.html.erb (0.0ms)    Rendered search/_saved_searches_dialogs.html.erb (0.2ms)    Rendered search/_saved.html.erb (0.5ms)    Rendered main/_change_log.html.erb (0.1ms)    Rendered main/_glossary.html.erb (0.0ms)    Rendered themes/default/_footer.html.erb (0.1ms)    Rendered main/index.html.erb within layouts/main (70.5ms)

This happens because I'm using "render stream: true" in that action, but I'd expect the latency to be reduced when looking at the Chrome reported timing, but it doesn't matter if I render with "stream: true" or not, the latency reported by Chrome is always about 100ms.

Am I missing something?

Thanks in advance, Rodrigo.

2

This functionality does not come from Rails, but rather Rack::Runtime (http://guides.rubyonrails.org/configuring.html#configuring-middleware) you can see the middleware here: https://github.com/rack/rack/blob/master/lib/rack/runtime.rb. It looks pretty simple, i’m not sure if it is streaming aware.

For different latencies regarding assets, i’m guessing that chrome is perhaps doing some caching? How much latency do you get when you hit that CSS from a new incognito window?

3

I don’t need an incognito window to force skipping any caching, I just check “Disable cache (while DevTools is open)”. I did that and I can see from the Network pane that the response status was 200, and it took 16ms of latency + 30ms of “Receiving” time for a JS asset. What I mean is that most probably the web server (Puma, Webrick) is not the cause for such a big latency… So maybe there’s something more happening that is not registered by that middleware and I’d like to know if there’s anyway I could understand what else it could be and if I’m able to optimize it… Just in case you’re curious, I tested it in an incognito window and the result is the same as disabling cache. I understand that and that’s exactly my intention. I want Chrome to download the assets while the page is loading but I see that it won’t download them until the page finishes loading, which makes sense since I get about 3ms of “Receiving” time. What I mean is that rendering with “stream: true” is not helping at all and it makes no difference if I use normal rendering (except for this bug I reported yesterday: ) Chrome reports me all timings separately: “Blocking”, “Sending”, “Waiting” and “Receiving”. The waiting part is taking 99% of the total time. Do you get different results? I have even included this in one of my partials: <% sleep 1 -%> Guess what: “Waiting: 1.1s” So, I guess the problem is that streaming doesn’t seem to be working actually. Now that I figured this out, I’ll try to reproduce in a separate application and if I can, I’ll report another bug for template streaming rendering. Thank you for helping, Richard. Cheers, Rodrigo.

4

I didn’t know you could turn off caching in chrome. I’ll have to take a better look into their dev tools. Once you figure this out, it could make a nice blog post on how to use front end + backend analytics to debug and speed up performance problems.

5

I've created this issue in GitHub:

https://github.com/rails/rails/issues/14117 Here's a sample application: GitHub - rosenfeld/rails-template-streaming-bug: Template streaming (render stream: true) does not work in latest Rails

And you can see it live on OpenShift here: http://railstemplatestreamingbug-rosenfeld.rhcloud.com/

It would be interesting to write such a post but I don't think my company would pay me for doing that and I don't really have any free time as the babysitter will leave the same time I leave my job and I'm left alone with my baby... Hard to convince my wife to take care of our 9 months old daughter and the house while freeing me to do other stuff, so I only ask for it in special events, like a Choro jam with some friends once in a week :wink:

Best, Rodrigo.

6

Completely wild guess, but the issue you’re seeing could be related to the fact that you’re running in development mode. I wouldn’t trust any benchmark unless the app was in production mode. One reason is the code reloading in development mode.

7

I wrote this in that mentioned issue on GitHub:

" I tried disabling ETag and ConditionalGet middlewares but couldn't get any luck either in development or production environments."

So, I don't think the development environment is the reason in this case.

I'd love to hear about more wild guesses though.