Rails - Feb 2011 - 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?

-- 
You received this message because you are subscribed to the Google Groups
"Ruby on Rails: Talk" group.
To post to this group, send email to
rubyonrails-talk-/JYPxA39Uh5TLH3MbocFF+G/Ez6ZCGd0@public.gmane.org
To unsubscribe from this group, send email to
rubyonrails-talk+unsubscribe-/JYPxA39Uh5TLH3MbocFF+G/Ez6ZCGd0@public.gmane.org
For more options, visit this group at
http://groups.google.com/group/rubyonrails-talk?hl=en.

On Feb 1, 2011, at 5:57 PM, Joe Martin 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

-- 
You received this message because you are subscribed to the Google Groups
"Ruby on Rails: Talk" group.
To post to this group, send email to
rubyonrails-talk-/JYPxA39Uh5TLH3MbocFF+G/Ez6ZCGd0@public.gmane.org
To unsubscribe from this group, send email to
rubyonrails-talk+unsubscribe-/JYPxA39Uh5TLH3MbocFF+G/Ez6ZCGd0@public.gmane.org
For more options, visit this group at
http://groups.google.com/group/rubyonrails-talk?hl=en.

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

On Feb 2, 8:30 am, Walter Lee Davis
<wa...-HQgmohHLjDZWk0Htik3J/w@public.gmane.org>
wrote:
>
> 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
-- 
You received this message because you are subscribed to the Google Groups
"Ruby on Rails: Talk" group.
To post to this group, send email to
rubyonrails-talk-/JYPxA39Uh5TLH3MbocFF+G/Ez6ZCGd0@public.gmane.org
To unsubscribe from this group, send email to
rubyonrails-talk+unsubscribe@googlegroups.com.
For more options, visit this group at
http://groups.google.com/group/rubyonrails-talk?hl=en.

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

-- 
You received this message because you are subscribed to the Google Groups
"Ruby on Rails: Talk" group.
To post to this group, send email to
rubyonrails-talk-/JYPxA39Uh5TLH3MbocFF+G/Ez6ZCGd0@public.gmane.org
To unsubscribe from this group, send email to
rubyonrails-talk+unsubscribe-/JYPxA39Uh5TLH3MbocFF+G/Ez6ZCGd0@public.gmane.org
For more options, visit this group at
http://groups.google.com/group/rubyonrails-talk?hl=en.

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.

-- 
You received this message because you are subscribed to the Google Groups
"Ruby on Rails: Talk" group.
To post to this group, send email to
rubyonrails-talk-/JYPxA39Uh5TLH3MbocFF+G/Ez6ZCGd0@public.gmane.org
To unsubscribe from this group, send email to
rubyonrails-talk+unsubscribe@googlegroups.com.
For more options, visit this group at
http://groups.google.com/group/rubyonrails-talk?hl=en.