Ultra slow view rendering on first load after no requests for a few hours with Phusion Passenger

[Chris Mayan]

Hi there,

I'm having some very slow responses on view rendering of the first load of a site after no requests have been made to the server say after 6 or so hours.

I've included some prod logs, and the Passenger configuration files (please see below) to show the 22 second delay.

Quick background: 

a) the site redirects http requests to https. 

b) the first request is to the root of the site, which responds in a slow 2.4 seconds before redirecting to the https version of the page, 

c) it redirects, and the redirected view takes almost 22seconds to render.

d) subsequent hits to the site (even from another browser on a different network connection that has never visited the site before) now only takes on average 64ms!

Is this some sort of Passenger configuration problem? I've read and reread the Passenger configuration manual and I have set  options to stop it from idling down any of the spawns and / or rails environment that may cause the slow lag after no requests for some time.

I've also utilised PassengerPreStart, and used MinInstances.

But none of this seems to cure this problem at all.

The server is also not using any swap. Here is the output from "free":

                       total       used       free     shared    buffers     cached

Mem:       1023384     881020     142364          0      61940     188796

  -/+ buffers/cache:     630284     393100

Swap:       905208               0     905208

Is there some Passenger/Apache configuration that I am missing?

Is there some OS thing that is affecting the performance? (Server is virtual machine - is the VM starved of cpu/disk resources perhaps?)

Have any of you experienced anything like this and/or know a way to resolve it?

Thanks and appreciate any help or suggestions 

Cheers

Chris

Prod Logs:

----------------

Processing SiteController#index (for x.x.x.x at 2011-12-20 09:42:01) [GET]

  Parameters: {"action"=>"index", "controller"=>"site"}

Redirected to https://domainname.com/

Filter chain halted as [:ensure_proper_protocol] rendered_or_redirected.

Completed in 2471ms (DB: 1) | 302 Found [http://domainname.com/]

Processing SiteController#index (for x.x.x.x at 2011-12-20 09:42:06) [GET]

  Parameters: {"action"=>"index", "controller"=>"site"}

Rendering template within layouts/general_layout

Rendering site/index

Completed in 22577ms (View: 21815, DB: 96) | 200 OK [https://domainname.com/]

Processing SiteController#index (for x.x.x.x at 2011-12-20 09:43:03) [GET]

  Parameters: {"action"=>"index", "controller"=>"site"}

Rendering template within layouts/general_layout

Rendering site/index

Completed in 64ms (View: 56, DB: 25) | 200 OK [https://domainname.com/]

Passenger.conf:

-------------------------

<IfModule mod_passenger.c>

  PassengerRoot /var/lib/gems/1.8/gems/passenger-3.0.9

  PassengerRuby /usr/bin/ruby1.8

  PassengerUseGlobalQueue On

  PassengerSpawnMethod smart

  PassengerFriendlyErrorPages Off

  PassengerMinInstances 5

  PassengerPoolIdleTime 0

  PassengerHighPerformance on

  PassengerLogLevel 0

  RailsFrameworkSpawnerIdleTime 0

  RailsAppSpawnerIdleTime 0

</IfModule>

In the individual site config I have:

--------------------------------------------------

PassengerPreStart https://domainname.com

[Simon Russell]

Can you see the passenger worker processes running on the box (after
the six hour period)? And are you doing any page/fragment/anything
caching in the Rails app?

> --
> You received this message because you are subscribed to the Google Groups
> "Ruby or Rails Oceania" group.
> To post to this group, send email to rails-...@googlegroups.com.
> To unsubscribe from this group, send email to
> rails-oceani...@googlegroups.com.
> For more options, visit this group at
> http://groups.google.com/group/rails-oceania?hl=en.

[Chris Mayan]

Hi Simon,

The passenger worker processes are and have been running since a few days ago (quick "ps" shows they have all been alive at least 3 days).

Production.rb has:

-----------------------------

config.cache_classes = true

config.action_controller.consider_all_requests_local = false

config.action_controller.perform_caching             = true

config.action_view.cache_template_loading            = true 

Apart from that no "caches_page" or "caches_action" directives are used in any controllers 

or anywhere else in the rails app etc..

Cheers

Chris

[Simon Russell]

When you actually do the request that takes ages, it's definitely not
spawning any new workers, or killing old ones?

Is it basically a simple app? Just DB + Rails?

You were suspicious of the fact that it's in a VM -- what
virtualisation thing are you using?

[Chris Mayan]

Hi Simon,

I believe it is not spawning any new workers or killing old ones, as the same number of workers are there, and their process ids haven't changed, and their start date time was from 3 days ago.

It's a large application (when you type in ./script/console that takes a long time to load), but in theory it is just a DB+ Rails + several DelayedJob workers on the side.

This problem is happening on my go-to-stage server (host is running VMWare Server 2). I'm fairly sure it happens on the VMWare ESX server as well in production.

I'm thinking about the rails caching thing you asked me before and that seems quite possible that rails is caching template rendering but for some reason is expiring it after 6 hours or so... is there some internal expiration config in rails that specifies this?

(i.e. the caching is internal to rails and nothing to do with Passenger).

Some other background - the app on first instance of Rails will actually create singleton "resources" and load them to memory per rails instance - not sure if this is what I am seeing as causing the lag as well.

Cheers

Chris

[Simon Russell]

Looking at how long it takes to redirect to https, I suppose it's
probably not a caching thing. I sort of don't really know what it
could be; it seems like it's doing an unusually large amount of work
on app startup (if script/console takes ages to start); I guess adding
some logging on the expensive startup actions might shed some light on
what's going on. Maybe those singleton objects aren't as singleton as
they're designed to be.

If you can get it to happen locally, then a profiler might also help.

[Chris Mayan]

Hi,

Thanks for help - I'll review everything piece by piece and see if I can get a resolution on this.

In the meantime, if you or any one else has any ideas or suggestions what it could be, I'd be delighted to hear it.

With respect to getting it happening locally - the problem is I have never been able to get it to behave like this locally - only when it is remotely deployed on a production or staging server.

And it's a cow to test because for the next few hours everything is sub 200ms responses... 

I'm thinking that the caching thing might be an issue because the delay is the same amount of delay that I face if I don't use the PassengerPreload thing... maybe the Passenger instances are unloading and/or rails is unloading after sometime... 

Cheers

Chris

[Simon Russell]

Well, there's always cron + curl until you find the source of the problem :)