Delay Loading Rails Views

Hi All,

I'm having trouble with a Rails app and I can't figure out what / where the problem is.

From the logging and testing I've done, it looks like there is a consistent 3 second delay between the time that Rails finishes rendering the view and the time that the browser actually receives the data. That delay doesn't show up on my laptop, running in Production mode, but it does show up on my server, running in Production mode. Both machines are running Ruby 1.8.7 and both are running Rails 3.0.3.

I ran the test as pure as I could. I SSHed into the server and loaded the page through curl and timed the load. I also loaded directly from Rails itself, not going through the Apache proxy. I think that eliminates both the network and Apache as sources of the delay. I think the delay is somewhere in Rails itself.

Here's my logs. First, the commands and date/time stamps from the prompt.

[litho:~/apps/timetrack/current/log] jmartin$ date ; curl -b "cookie:val" http://127.0.0.1:10100/activity/list >/dev/null ; date ;curl -b "cookie:val" http://127.0.0.1:10100/activity/list >/dev/ null ; date

Tuesday, February 1, 2011 2:28:38 PM GMT   % Total % Received % Xferd Average Speed Time Time Time Current                                  Dload Upload Total Spent Left Speed 100 4709 0 4709 0 0 1328 0 --:--:-- 0:00:03 --:--:-- 1328 Tuesday, February 1, 2011 2:28:42 PM GMT

Tuesday, February 1, 2011 2:28:42 PM GMT   % Total % Received % Xferd Average Speed Time Time Time Current                                  Dload Upload Total Spent Left Speed 100 4709 0 4709 0 0 1352 0 --:--:-- 0:00:03 --:--:-- 1352 Tuesday, February 1, 2011 2:28:45 PM GMT

Next, here are the entries from the Rails production.log file.

Started GET "/activity/list" for 127.0.0.1 at Tue Feb 01 14:28:38 +0000 2011   Processing by ActivityController#list as */* before filter Exist fragment? views/127.0.0.1:10100/activity/list (0.1ms) Write fragment views/127.0.0.1:10100/activity/list (0.1ms) Rendered activity/_recent.html.erb (7.4ms) Rendered activity/_switch.html.erb (2.4ms) Rendered activity/list.html.erb within layouts/application (14.1ms) Completed 200 OK in 19ms (Views: 14.5ms | ActiveRecord: 108.9ms)

Started GET "/activity/list" for 127.0.0.1 at Tue Feb 01 14:28:42 +0000 2011   Processing by ActivityController#list as */* before filter Exist fragment? views/127.0.0.1:10100/activity/list (0.1ms) Read fragment views/127.0.0.1:10100/activity/list (0.1ms) Rendered activity/_recent.html.erb (1.3ms) Rendered activity/_switch.html.erb (2.4ms) Rendered activity/list.html.erb within layouts/application (7.7ms) Completed 200 OK in 12ms (Views: 8.3ms | ActiveRecord: 106.9ms)

It looks like the Rails app receives the request as soon as curl sends it. It process it in 12 or 19 milliseconds and then curl doesn't get the response for another 3 full seconds.

What could possibly be causing the delay between the time that the view is Completed and logged and the time that curl receives the HTML data?

This kind of consistent delay sounds a lot like a DNS issue to me. Some machine in the transaction (maybe the server, maybe the machine that cURL is running on) is trying to look up its own name and failing, and having to wait through the DNS timeout. That's the direction I would start looking personally.

Walter

I thought of that, but I don't see where it could be getting into the mix. I'm running cURL directly on the application server and I'm connecting to the application via 127.0.0.1 — no DNS there. The database.yml is pointing to the database on 127.0.0.1 — no DNS there either. I'm not using memcached or anything else fancy that might need a DNS lookup.

I've checked all of the files in config/ and I don't see any host name entries. Is there anywhere else I should look for host name configuration?

Is there any way I can trace exactly what's happening after the "Completed 200 OK in 12ms" log entry, to see what's hanging?

~Joe

3 seconds is also very close to the time a server will wait for a second request, when keep-alive is on. I don't know why it would be triggered here as surely curl did not set that option on the connection.

Firewall config could also affect this.

--Michael

I found the problem, although I'm still baffled as to why it was occurring at all.

My session (using active_record_store) was storing the User object of the logged in user. Any page that access that object experienced the 3 second delay. Any page that didn't access that object loaded almost instantly. I re-jiggered the application to just store the user id and User.find the object whenever it was needed. Voila — no more delays.

Problem solved but I don't know why it was a problem.