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?