I’m having an odd timeout error with a certain page on my personal Rails app on a particular page that doesn’t reproduce itself local in development or production mode.
Every Project model of the page, a projects page, as well as its dependencies checked out as being valid on Heroku’s remote rails console.
The error code is H12 which translates to being a timeout error.
Any thoughts?
Could you paste whole log from heroku logs?
DL is deprecated, please use Fiddle
2013-12-05T20:08:57.153144+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/ser
ver.rb:250:in `block in run'
2013-12-05T20:08:57.152989+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/ser
ver.rb:486:in `handle_request'
2013-12-05T20:08:57.152989+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/ser
ver.rb:357:in `process_client'
2013-12-05T20:08:57.153144+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/thr
ead_pool.rb:92:in `call'
2013-12-05T20:08:57.153144+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/thr
ead_pool.rb:92:in `block in spawn_thread'
2013-12-05T20:08:57.153144+00:00 app[web.1]:
2013-12-05T20:08:57.153144+00:00 app[web.1]:
2013-12-05T20:08:57.153144+00:00 app[web.1]:
2013-12-05T20:08:57.153144+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.0/lib/ac
tion_dispatch/middleware/debug_exceptions.rb:21:in `call'
2013-12-05T20:08:57.153570+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/railties-4.0.0/lib/rail
s/rack/logger.rb:21:in `block in call'
2013-12-05T20:08:57.153144+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/railties-4.0.0/lib/rail
s/rack/logger.rb:38:in `call_app'
2013-12-05T20:08:57.153570+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.0/lib
/active_support/tagged_logging.rb:25:in `tagged'
2013-12-05T20:08:57.153144+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.0/lib/ac
tion_dispatch/middleware/show_exceptions.rb:30:in `call'
2013-12-05T20:08:57.153570+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.0/lib
/active_support/tagged_logging.rb:67:in `tagged'
2013-12-05T20:08:57.153570+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/railties-4.0.0/lib/rail
s/rack/logger.rb:21:in `call'
2013-12-05T20:08:57.153144+00:00 app[web.1]: ActionController::RoutingError (No route matches [GET]
"/js/lib/cssParser.js"):
2013-12-05T20:08:57.153570+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.0/lib
/active_support/tagged_logging.rb:67:in `block in tagged'
2013-12-05T20:08:57.153570+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/rack-1.5.2/lib/rack/met
hodoverride.rb:21:in `call'
2013-12-05T20:08:57.153570+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/rack-1.5.2/lib/rack/run
time.rb:17:in `call'
2013-12-05T20:08:57.153570+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.0/lib/ac
tion_dispatch/middleware/request_id.rb:21:in `call'
2013-12-05T20:08:57.153570+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.0/lib
/active_support/cache/strategy/local_cache.rb:83:in `call'
2013-12-05T20:08:57.153570+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.0/lib/ac
tion_dispatch/middleware/static.rb:64:in `call'
2013-12-05T20:08:57.153744+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/railties-4.0.0/lib/rail
s/application.rb:97:in `call'
2013-12-05T20:08:57.153744+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/rack-1.5.2/lib/rack/con
tent_length.rb:14:in `call'
2013-12-05T20:08:57.153744+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/railties-4.0.0/lib/rail
s/engine.rb:511:in `call'
2013-12-05T20:08:57.153744+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/ser
ver.rb:486:in `handle_request'
2013-12-05T20:08:57.153744+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/ser
ver.rb:357:in `process_client'
2013-12-05T20:08:57.153744+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/ser
ver.rb:250:in `block in run'
2013-12-05T20:08:57.153744+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/thr
ead_pool.rb:92:in `call'
2013-12-05T20:08:57.153744+00:00 app[web.1]:
2013-12-05T20:08:57.153744+00:00 app[web.1]:
2013-12-05T20:08:57.153663+00:00 heroku[router]: at=info method=GET path=/js/lib/cssParser.js host=k
evinlozandier.herokuapp.com fwd="206.117.88.4" dyno=web.1 connect=2ms service=27ms status=404 bytes=
1351
2013-12-05T20:08:57.153744+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/thr
ead_pool.rb:92:in `block in spawn_thread'
2013-12-05T20:08:57.165878+00:00 app[web.1]: Started GET "/js/lib/css-filters-polyfill.js" for 206.1
17.88.12 at 2013-12-05 20:08:57 +0000
2013-12-05T20:08:57.167270+00:00 app[web.1]: ActionController::RoutingError (No route matches [GET]
"/js/lib/css-filters-polyfill.js"):
2013-12-05T20:08:57.167270+00:00 app[web.1]:
2013-12-05T20:08:57.167270+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.0/lib/ac
tion_dispatch/middleware/show_exceptions.rb:30:in `call'
2013-12-05T20:08:57.165878+00:00 app[web.1]: Started GET "/js/lib/css-filters-polyfill.js" for 206.1
17.88.12 at 2013-12-05 20:08:57 +0000
2013-12-05T20:08:57.167270+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.0/lib/ac
tion_dispatch/middleware/debug_exceptions.rb:21:in `call'
2013-12-05T20:08:57.167270+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/railties-4.0.0/lib/rail
s/rack/logger.rb:21:in `block in call'
2013-12-05T20:08:57.167270+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.0/lib
/active_support/tagged_logging.rb:67:in `block in tagged'
2013-12-05T20:08:57.167270+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/railties-4.0.0/lib/rail
s/rack/logger.rb:38:in `call_app'
2013-12-05T20:08:57.167270+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.0/lib
/active_support/tagged_logging.rb:67:in `tagged'
2013-12-05T20:08:57.167270+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.0/lib
/active_support/tagged_logging.rb:25:in `tagged'
2013-12-05T20:08:57.167437+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.0/lib/ac
tion_dispatch/middleware/request_id.rb:21:in `call'
2013-12-05T20:08:57.167270+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/railties-4.0.0/lib/rail
s/rack/logger.rb:21:in `call'
2013-12-05T20:08:57.167437+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/rack-1.5.2/lib/rack/met
hodoverride.rb:21:in `call'
2013-12-05T20:08:57.167437+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/rack-1.5.2/lib/rack/run
time.rb:17:in `call'
2013-12-05T20:08:57.167622+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/thr
ead_pool.rb:92:in `block in spawn_thread'
2013-12-05T20:08:57.167622+00:00 app[web.1]:
2013-12-05T20:08:57.167437+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/ser
ver.rb:357:in `process_client'
2013-12-05T20:08:57.167437+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.0/lib
/active_support/cache/strategy/local_cache.rb:83:in `call'
2013-12-05T20:08:57.167437+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.0/lib/ac
tion_dispatch/middleware/static.rb:64:in `call'
2013-12-05T20:08:57.167437+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/rack-1.5.2/lib/rack/con
tent_length.rb:14:in `call'
2013-12-05T20:08:57.167622+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/thr
ead_pool.rb:92:in `call'
2013-12-05T20:08:57.167622+00:00 app[web.1]:
2013-12-05T20:08:57.167437+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/railties-4.0.0/lib/rail
s/engine.rb:511:in `call'
2013-12-05T20:08:57.167622+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/railties-4.0.0/lib/rail
s/rack/logger.rb:38:in `call_app'
2013-12-05T20:08:57.167622+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.0/lib/ac
tion_dispatch/middleware/show_exceptions.rb:30:in `call'
2013-12-05T20:08:57.167622+00:00 app[web.1]:
2013-12-05T20:08:57.167622+00:00 app[web.1]: ActionController::RoutingError (No route matches [GET]
"/js/lib/css-filters-polyfill.js"):
2013-12-05T20:08:57.168011+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.0/lib
/active_support/tagged_logging.rb:67:in `tagged'
2013-12-05T20:08:57.167437+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/railties-4.0.0/lib/rail
s/application.rb:97:in `call'
2013-12-05T20:08:57.168011+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.0/lib
/active_support/tagged_logging.rb:67:in `block in tagged'
2013-12-05T20:08:57.167622+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.0/lib/ac
tion_dispatch/middleware/debug_exceptions.rb:21:in `call'
2013-12-05T20:08:57.168011+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.0/lib/ac
tion_dispatch/middleware/request_id.rb:21:in `call'
2013-12-05T20:08:57.168151+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/rack-1.5.2/lib/rack/con
tent_length.rb:14:in `call'
2013-12-05T20:08:57.168011+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/rack-1.5.2/lib/rack/met
hodoverride.rb:21:in `call'
2013-12-05T20:08:57.168011+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/railties-4.0.0/lib/rail
s/rack/logger.rb:21:in `call'
2013-12-05T20:08:57.168151+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/ser
ver.rb:250:in `block in run'
2013-12-05T20:08:57.168011+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.0/lib
/active_support/cache/strategy/local_cache.rb:83:in `call'
2013-12-05T20:08:57.167437+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/ser
ver.rb:486:in `handle_request'
2013-12-05T20:08:57.168151+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/thr
ead_pool.rb:92:in `call'
2013-12-05T20:08:57.168151+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/ser
ver.rb:357:in `process_client'
2013-12-05T20:08:57.168011+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.0/lib
/active_support/tagged_logging.rb:25:in `tagged'
2013-12-05T20:08:57.168011+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/rack-1.5.2/lib/rack/run
time.rb:17:in `call'
2013-12-05T20:08:57.168151+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/railties-4.0.0/lib/rail
s/application.rb:97:in `call'
2013-12-05T20:08:57.168011+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.0/lib/ac
tion_dispatch/middleware/static.rb:64:in `call'
2013-12-05T20:08:57.168151+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/railties-4.0.0/lib/rail
s/engine.rb:511:in `call'
2013-12-05T20:08:57.167622+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/ser
ver.rb:250:in `block in run'
2013-12-05T20:08:57.168011+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/railties-4.0.0/lib/rail
s/rack/logger.rb:21:in `block in call'
2013-12-05T20:08:57.168151+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/ser
ver.rb:486:in `handle_request'
2013-12-05T20:08:57.168151+00:00 app[web.1]:
2013-12-05T20:08:57.168151+00:00 app[web.1]: vendor/bundle/ruby/2.0.0/gems/puma-2.6.0/lib/puma/thr
ead_pool.rb:92:in `block in spawn_thread'
2013-12-05T20:08:57.168151+00:00 app[web.1]:
2013-12-05T20:08:57.184929+00:00 heroku[router]: at=info method=GET path=/js/lib/css-filters-polyfil
l.js host=kevinlozandier.herokuapp.com fwd="206.117.88.12" dyno=web.1 connect=5ms service=25ms statu
s=404 bytes=1351
2013-12-05T20:09:05.867724+00:00 app[web.1]: Started GET "/projects" for 206.117.88.4 at 2013-12-05
20:09:05 +0000
2013-12-05T20:09:05.867724+00:00 app[web.1]: Started GET "/projects" for 206.117.88.4 at 2013-12-05
20:09:05 +0000
2013-12-05T20:09:05.874927+00:00 app[web.1]: Processing by ProjectsController#index as HTML
2013-12-05T20:09:05.874927+00:00 app[web.1]: Processing by ProjectsController#index as HTML
2013-12-05T20:09:06.050617+00:00 app[web.1]: Rendered projects/_project.html.haml (33.3ms)
2013-12-05T20:09:06.048447+00:00 app[web.1]: Rendered projects/_project.html.haml (33.3ms)
2013-12-05T20:09:06.056391+00:00 app[web.1]: Rendered projects/index.html.haml within layouts/appl
ication (168.3ms)
2013-12-05T20:09:06.055910+00:00 app[web.1]: Rendered technologies/_technology_showcased.html.haml
(0.0ms)
2013-12-05T20:09:06.055764+00:00 app[web.1]: Rendered technologies/_technology_showcased.html.haml
(0.0ms)
2013-12-05T20:09:06.056275+00:00 app[web.1]: Rendered projects/index.html.haml within layouts/appl
ication (168.3ms)
2013-12-05T20:09:17.103896+00:00 app[web.1]: Completed 200 OK in 137951ms (Views: 137844.2ms | Activ
eRecord: 64.3ms)
2013-12-05T20:09:17.103896+00:00 app[web.1]: Completed 200 OK in 137951ms (Views: 137844.2ms | Activ
eRecord: 64.3ms)
2013-12-05T20:07:16.579317+00:00 heroku[router]: at=info method=GET path=/js/lib/css-filters-polyfil
l.js host=kevinlozandier.herokuapp.com fwd="206.117.88.4" dyno=web.1 connect=95ms service=44ms statu
s=404 bytes=1351
2013-12-05T20:06:20.550628+00:00 heroku[router]: at=info method=GET path=/js/lib/css-filters-polyfil
l.js host=kevinlozandier.herokuapp.com fwd="206.117.88.4" dyno=web.1 connect=1057ms service=168ms st
atus=404 bytes=1351
2013-12-05T20:09:35.488218+00:00 heroku[router]: at=error code=H12 desc="Request timeout" method=GET
path=/projects host=kevinlozandier.herokuapp.com fwd="206.117.88.4" dyno=web.1 connect=2092ms servi
ce=30005ms status=503 bytes=0
PS C:\sites\personal> heroku logs
What’s this page doing? Have you inspected your development logs to see if it’s perhaps issuing too many queries? Your local logs will be more detailed than what you see on Heroku.
Another angle: What is this particular page doing that is different than other pages in your application?
I thought I replied via an reply through Gmail but apparently not, sorry about that:
It’s aggregetting the projects.json which has a json file that looks like the first JSON snippet below.
While admittedly not using :pluck or cache declerations like I normally do when something production-ready, it’s odd how inconsistent it is.
I’m inexperienced of what the free experience of Heroku App is, so could it be possible that’s the reason? I haven’t been able to reproduce the problem in any mode of rails server to explain the inconsistent time out errors.
The second code block shows what individual project pages get from the server which is more taxing technically as it gets things from the persona, goal interest, technology, technology_profile models, 2 of which are polymorphic.
projects: [
{
id: 2,
title: "Campus Connect",
description: "<p>A project in hopes of making Campus Life more accessible for all. </p> ",
medium: "Website",
state: "approved",
created_at: "2013-10-07T23:56:33.542Z",
updated_at: "2013-10-20T01:02:49.640Z",
slug: "campus-connect",
background_image_file_name: "Mock_up_Page_1.png",
background_image_content_type: "image/png",
background_image_file_size: 0,
background_image_updated_at: "2013-10-08T22:19:59.607Z",
experiment: true,
released_on: "2012-01-07",
url: "",
missing_url_reason: "Have to hard drive hunt for the prototypes. ",
main_image_file_name: "campus_connect_cover.png",
main_image_content_type: "image/png",
main_image_file_size: 0,
main_image_updated_at: "2013-10-08T22:20:08.266Z",
lock_version: 31,
personas_count: 2,
byline: ""
},
{
id: 1,
title: "Special Project",
description: "<p>It’s a special project for me and only me. </p> ",
medium: "Website",
state: "approved",
created_at: "2013-10-03T18:10:18.454Z",
updated_at: "2013-10-20T02:00:30.356Z",
slug: "special-project",
background_image_file_name: "3e9ccb998abbe9190af0c7f916422e91_133_76_Angela-Rypien-Facebook.jpg",
background_image_content_type: "image/jpeg",
background_image_file_size: 3049,
background_image_updated_at: "2013-10-18T21:36:26.569Z",
experiment: true,
released_on: "2013-10-31",
url: "http://ign.com",
missing_url_reason: "http://ign.com",
main_image_file_name: "original_attack_on_titan.jpg",
main_image_content_type: "image/jpeg",
main_image_file_size: 356354,
main_image_updated_at: "2013-10-18T21:36:25.706Z",
lock_version: 20,
personas_count: 1,
byline: "Special"
}
]
}
{
project: {
id: 2,
main_image: "http://kevin-lozandier-personal-website.s3.amazonaws.com/projects/main_images/000/000/002/original/campus_connect_cover.png?1381270808",
medium: "Website",
technology_profiles: [
{
id: 3,
name: "Sass ",
color: "#d0146c",
percentage_of_project: 5
},
{
id: 4,
name: "HAML",
color: "#e45e0c",
percentage_of_project: 20
},
{
id: 10,
name: "HTML5",
color: "#000000",
percentage_of_project: 75
}
],
personas: [
{
id: 3,
interest_ids: [ ],
influencer_ids: [
10,
9
],
goal_ids: [ ]
},
{
id: 2,
interest_ids: [
1,
2,
3
],
influencer_ids: [
4,
5,
6,
7,
8
],
goal_ids: [
1,
2,
3,
4,
5
]
}
],
photos: [
{
id: 6,
caption: "New Photo ",
image_url: "http://kevin-lozandier-personal-website.s3.amazonaws.com/photos/images/000/000/006/original/IMG_4419.JPG?1382137086"
},
{
id: 5,
caption: "AA",
image_url: "http://kevin-lozandier-personal-website.s3.amazonaws.com/photos/images/000/000/005/original/blackalumniassociation.png?1382134728"
},
{
id: 4,
caption: "AA",
image_url: "http://kevin-lozandier-personal-website.s3.amazonaws.com/photos/images/000/000/004/original/persona03.jpg?1382063158"
}
]
}
}
The heroku basic “free” instance only allows 20 connections, and has 0 bytes of RAM available for the postgres instance. So if you are doing a complex query it will most likely page out to virtual memory. You are using a postgres database by default in heroku unless you specify otherwise. If you aren’t already, you might want to use postgres in development mode also so you are comparing apples to apples, so to speak.
To see what is slowing your app down try installing gem "rack-mini-profiler" in your gemfile development group.
In development mode it will produce a timing box in the upper left corner of the web page. Clicking on each time will expand it to show how much time is being taken in what part of the code, particularly the SQL calls. You can keep clicking and drill down into the code.
Make sure to place it below the gems for your database, i.e. pg or sqlite, or it won’t pick up the SQL calls. See MiniProfiler / rack-mini-profiler repo for more documentation.
Appreciate the advice; I’ll give rack-mini-profiler a try. I exclusively use postgres in development and production, using the --database=postgresql option with every rails app I generate, ensuring pg is installed and that my usage of pgadmin has all the appropriate databases made.
I didn’t know that about the free instance of Heroku that makes it easier to wrap my head around what’s the problem; thanks.
If it helps, I use active_record_serializers to generate my json iwth the embed options utilized, is that a bit too taxing you think w/ a free instance of Heroku? Or is that irrelevant?