I'm developing a rails application. After pushing the git on Heroku without trouble, the app show an error "request time out" inside the webbrowser.
If i'm re-trying 1 minute after, the app display the page very quikly on the webbrowser.
CONFIGURATION
Find below my configuration
Rails 5.1.2
psql (PostgreSQL) 9.6.1
The main info inside the gem file:
ruby '2.2.6'
gem 'rails', '~> 5.1.1'
gem 'pg', '~> 0.18'
gem 'puma', '~> 3.7'
Heroku
Standard-2X dynos, Shared, 1 GB RAM
Heroku Postgres :: Brown
Memcached Cloud :free
Papertrail :free
STANDARD PLAN
LOG
The log of the first very long request ( notice that I restart the server before the test to reproduce the problem that append every morning at the first request)
Aug 25 03:28:15 myapplication app/web.1: => Booting Puma
Aug 25 03:28:15 myapplication app/web.1: => Rails 5.1.2 application starting in production on http://0.0.0.0:41080
Aug 25 03:28:15 myapplication app/web.1: => Run `rails server -h` for more startup options
Aug 25 03:28:15 myapplication app/web.1: [4] Puma starting in cluster mode...
Aug 25 03:28:15 myapplication app/web.1: [4] * Version 3.9.1 (ruby 2.2.6-p396), codename: Private Caller
Aug 25 03:28:15 myapplication app/web.1: [4] * Min threads: 5, max threads: 5
Aug 25 03:28:15 myapplication app/web.1: [4] * Environment: production
Aug 25 03:28:15 myapplication app/web.1: [4] * Process workers: 2
Aug 25 03:28:15 myapplication app/web.1: [4] * Preloading application
Aug 25 03:28:15 myapplication app/web.1: [4] * Listening on tcp://0.0.0.0:41080
Aug 25 03:28:15 myapplication app/web.1: [4] Use Ctrl-C to stop
Aug 25 03:28:15 myapplication app/web.1: [4] - Worker 0 (pid: 6) booted, phase: 0
Aug 25 03:28:15 myapplication app/web.1: [4] - Worker 1 (pid: 19) booted, phase: 0
Aug 25 03:28:15 myapplication heroku/web.1: State changed from starting to up
Aug 25 03:28:37 myapplication app/heroku-postgres: source=HEROKU_POSTGRESQL_BROWN sample#current_transaction=2339 sample#db_size=25066008bytes sample#tables=21 sample#active-connections=2 sample#waiting-connections=0 sample#index-cache-hit-rate=0.99931 sample#table-cache-hit-rate=0.996 sample#load-avg-1m=0 sample#load-avg-5m=0 sample#load-avg-15m=0 sample#read-iops=0 sample#write-iops=0.057733 sample#memory-total=4044984kB sample#memory-free=1550168kB sample#memory-cached=1945532kB sample#memory-postgres=16880kB
Aug 25 03:30:38 myapplication app/heroku-postgres: source=HEROKU_POSTGRESQL_BROWN sample#current_transaction=2339 sample#db_size=25066008bytes sample#tables=21 sample#active-connections=2 sample#waiting-connections=0 sample#index-cache-hit-rate=0.99931 sample#table-cache-hit-rate=0.996 sample#load-avg-1m=0 sample#load-avg-5m=0 sample#load-avg-15m=0 sample#read-iops=0 sample#write-iops=0.029687 sample#memory-total=4044984kB sample#memory-free=1550000kB sample#memory-cached=1945544kB sample#memory-postgres=16880kB
Aug 25 03:31:39 myapplication app/heroku-postgres: source=HEROKU_POSTGRESQL_BROWN sample#current_transaction=2339 sample#db_size=25066008bytes sample#tables=21 sample#active-connections=2 sample#waiting-connections=0 sample#index-cache-hit-rate=0.99931 sample#table-cache-hit-rate=0.996 sample#load-avg-1m=0 sample#load-avg-5m=0 sample#load-avg-15m=0 sample#read-iops=0 sample#write-iops=0.029687 sample#memory-total=4044984kB sample#memory-free=1549940kB sample#memory-cached=1945564kB sample#memory-postgres=16880kB
Aug 25 03:32:38 myapplication app/heroku-postgres: source=HEROKU_POSTGRESQL_BROWN sample#current_transaction=2339 sample#db_size=25066008bytes sample#tables=21 sample#active-connections=2 sample#waiting-connections=0 sample#index-cache-hit-rate=0.99931 sample#table-cache-hit-rate=0.996 sample#load-avg-1m=0 sample#load-avg-5m=0 sample#load-avg-15m=0 sample#read-iops=0 sample#write-iops=0.029687 sample#memory-total=4044984kB sample#memory-free=1550284kB sample#memory-cached=1945568kB sample#memory-postgres=16880kB
Aug 25 03:33:39 myapplication app/heroku-postgres: source=HEROKU_POSTGRESQL_BROWN sample#current_transaction=2339 sample#db_size=25066008bytes sample#tables=21 sample#active-connections=2 sample#waiting-connections=0 sample#index-cache-hit-rate=0.99931 sample#table-cache-hit-rate=0.996 sample#load-avg-1m=0 sample#load-avg-5m=0 sample#load-avg-15m=0 sample#read-iops=0 sample#write-iops=0.030191 sample#memory-total=4044984kB sample#memory-free=1550128kB sample#memory-cached=1945580kB sample#memory-postgres=16880kB
Aug 25 03:33:51 myapplication heroku/router: at=info method=GET path="/" host=myapplication.herokuapp.com request_id=afa5c118-7319-4b9b-a945-60ed57a63062 fwd="90.87.43.215" dyno=web.1 connect=0ms service=72ms status=301 bytes=371 protocol=https
Aug 25 03:33:51 myapplication app/web.1: I, [2017-08-25T10:33:50.584824 #19] INFO -- : [afa5c118-7319-4b9b-a945-60ed57a63062] Started GET "/" for 90.87.43.215 at 2017-08-25 10:33:50 +0000
Aug 25 03:33:51 myapplication app/web.1: I, [2017-08-25T10:33:50.665212 #19] INFO -- : [6db31a1a-39a5-4a8f-9ba1-cf35ceae5f61] Started GET "/projets/new" for 90.87.43.215 at 2017-08-25 10:33:50 +0000
Aug 25 03:33:51 myapplication app/web.1: I, [2017-08-25T10:33:50.670054 #19] INFO -- : [6db31a1a-39a5-4a8f-9ba1-cf35ceae5f61] Processing by ProjetsController#new as HTML
Aug 25 03:33:51 myapplication app/web.1: D, [2017-08-25T10:33:50.783930 #19] DEBUG -- : [6db31a1a-39a5-4a8f-9ba1-cf35ceae5f61] User Load (3.2ms) SELECT "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2 [["id", 2], ["LIMIT", 1]]
Aug 25 03:33:51 myapplication app/web.1: D, [2017-08-25T10:33:50.928475 #19] DEBUG -- : [6db31a1a-39a5-4a8f-9ba1-cf35ceae5f61] Regleconfiguration Load (3.4ms) SELECT "regleconfigurations".* FROM "regleconfigurations" ORDER BY "regleconfigurations"."id" DESC LIMIT $1 [["LIMIT", 1]]
Aug 25 03:33:51 myapplication app/web.1: D, [2017-08-25T10:33:50.955570 #19] DEBUG -- : [6db31a1a-39a5-4a8f-9ba1-cf35ceae5f61] Tarifoptionbt Load (3.2ms) SELECT "tarifoptionbts".* FROM "tarifoptionbts"
Aug 25 03:33:51 myapplication app/web.1: I, [2017-08-25T10:33:50.989799 #19] INFO -- : [6db31a1a-39a5-4a8f-9ba1-cf35ceae5f61] Rendering projets/new.html.erb within layouts/application
Aug 25 03:34:21 myapplication heroku/router: at=error code=H12 desc="Request timeout" method=GET path="/projets/new" host=myapplication.herokuapp.com request_id=6db31a1a-39a5-4a8f-9ba1-cf35ceae5f61 fwd="90.87.43.215" dyno=web.1 connect=0ms service=30001ms status=503 bytes=0 protocol=https
Aug 25 03:34:39 myapplication app/heroku-postgres: source=HEROKU_POSTGRESQL_BROWN sample#current_transaction=2339 sample#db_size=25066008bytes sample#tables=21 sample#active-connections=3 sample#waiting-connections=0 sample#index-cache-hit-rate=0.99931 sample#table-cache-hit-rate=0.996 sample#load-avg-1m=0 sample#load-avg-5m=0 sample#load-avg-15m=0 sample#read-iops=0 sample#write-iops=0.029687 sample#memory-total=4044984kB sample#memory-free=1547512kB sample#memory-cached=1945596kB sample#memory-postgres=20036kB
Aug 25 03:35:37 myapplication app/web.1: I, [2017-08-25T10:35:37.131381 #19] INFO -- : [6db31a1a-39a5-4a8f-9ba1-cf35ceae5f61] Rendered projets/_etapebar.html.erb (106132.4ms)
[.....] render 30 partial view
Aug 25 03:35:38 myapplication app/web.1: I, [2017-08-25T10:35:37.495939 #19] INFO -- : [6db31a1a-39a5-4a8f-9ba1-cf35ceae5f61] Completed 200 OK in 106826ms (Views: 106499.5ms | ActiveRecord: 50.2ms)
If I render a second time the same view I get this log:
Aug 25 05:42:45 myapplication app/web.1: I, [2017-08-25T12:42:44.339695 #19] INFO -- : [9c38a6b8-73d4-4e31-9ac3-df2ec8b21049] Started GET "/projets/new" for 90.87.43.215 at 2017-08-25 12:42:44 +0000
Aug 25 05:42:45 myapplication app/web.1: I, [2017-08-25T12:42:44.341197 #19] INFO -- : [9c38a6b8-73d4-4e31-9ac3-df2ec8b21049] Processing by ProjetsController#new as HTML
Aug 25 05:42:45 myapplication app/web.1: D, [2017-08-25T12:42:44.348612 #19] DEBUG -- : [9c38a6b8-73d4-4e31-9ac3-df2ec8b21049] User Load (1.7ms) SELECT "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2 [["id", 2], ["LIMIT", 1]]
Aug 25 05:42:45 myapplication app/web.1: I, [2017-08-25T12:42:44.351579 #19] INFO -- : [9c38a6b8-73d4-4e31-9ac3-df2ec8b21049] Completed 200 OK in 10ms (ActiveRecord: 1.7ms)
The application jump from a 106 second to serve a first request ( that's create a Heroku error) to a very short time in a second render
ASSET
Log show that the second call get asset from request.
In my app, on each page, I load the js of the current controller:
in application.html.erb
<%= stylesheet_link_tag controller.controller_name if TarifsDynamique::Application.assets.find_asset("#{controller.controller_name}.css") %>
<%= javascript_include_tag params[:controller] if TarifsDynamique::Application.assets.find_asset("#{controller.controller_name}.js") %>
and in from application.js and .css, i remove //=require .
and in asset.rb , I add
Rails.application.config.assets.precompile += ["#{controller}.js", "#{controller}.css"]
whith all the controller.
It's work find ( in devvellpoment and in production after the first call).
but when, I try to
$Heroku run assets:precompile
I got this error
Running rake assets:precompile on ⬢ myapplication... up, run.9829 (Standard-1X)
Yarn executable was not detected in the system.
Download Yarn at https://yarnpkg.com/en/docs/install
...
CACHE
I try to add cache to speed up the first page
cache action inside the controler:
class ProjetsController < ApplicationController caches_action :new, :editcache the view: new.html.erb
<%= render 'form', projet: @projet, cached: true %>active cache inside production.rb
Rails.application.configure do config.cache_classes = true
NO IDEA
I have no more idea If you get an idea , its will be so helpfull !
Thanks.
[EDIT] SOLUTION
Hi, I finally found what's going on ! I have 50 images to compile in the asset folder. Even if I precompile them, at the first request after a long sleep, Rails precompile them again that take tomany time.
1- I move image on amason S3, 2- change image_tag to image_static_tag 3- create a image_static_tag helper that serve static file from s3 4- redeploy the app and now everything is ok !!
THANKS FOR YOUR HELP
