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?

On Feb 1, 2011, at 5:57 PM, Joe M. wrote:

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

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 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

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.