Skip to content

Heroku Timeouts on POSTs #79

Open
dfuentes77 opened this Issue Oct 1, 2012 · 9 comments

6 participants

@dfuentes77

heroku[router]: Error H12 (Request timeout) -> POST copycopter-instance.herokuapp.com/localizations/25991/versions dyno=web.2 queue= wait= service=30000ms status=503 bytes=0

for POSTs like this

$ time curl --compressed http://copycopter-instance.herokuapp.com/localizations/25991/versions -d utf8:%E2%9C%93 -d authenticity_token:eoQEOykJQIiUw5vVZPRs0IaF3K73S34%2BqfoWlQAcYGU%3D -d version%5Bpublished%5D:false -d "version%5Bcontent%5D:Upcoming+Awesome+Shows10" -d prefer_html:false -d commit:Save+Blurb -H "Authorization:Basic <secret>"

Outputs Heroku 503 error page after Herkou timeouts the request.

real 0m30.696s
user 0m0.015s
sys 0m0.005s

Here is the debug output in the copycopter server logs:

2012-10-01T22:00:45+00:00 app[web.1]: Started POST "/localizations/25991/versions" for 216.103.134.250 at 2012-10-01 22:00:45 +0000
2012-10-01T22:00:45+00:00 app[web.1]: Processing by VersionsController#create as HTML
2012-10-01T22:00:45+00:00 app[web.1]: Parameters: {"utf8"=>"�", "authenticity_token"=>"eoQEOykJQIiUw5vVZPRs0IaF3K73S34+qfoWlQAcYGU=", "version"=>{"published"=>"false", "content"=>"Upcoming Awesome Shows10"}, "prefer_html"=>"false", "commit"=>"Save Blurb", "localization_id"=>"25991"}
2012-10-01T22:00:45+00:00 app[web.1]: Localization Load (1.7ms) SELECT "localizations".* FROM "localizations" WHERE "localizations"."id" = $1 LIMIT 1 [["id", "25991"]]
2012-10-01T22:00:45+00:00 app[web.1]: Blurb Load (2.1ms) SELECT "blurbs".* FROM "blurbs" WHERE "blurbs"."id" = 1131 LIMIT 1
2012-10-01T22:00:45+00:00 app[web.1]: Project Load (1.3ms) SELECT "projects".* FROM "projects" WHERE "projects"."id" = 1 LIMIT 1
2012-10-01T22:00:45+00:00 app[web.1]: CACHE (0.0ms) SELECT "localizations".* FROM "localizations" WHERE "localizations"."id" = $1 LIMIT 1
2012-10-01T22:00:45+00:00 app[web.1]: Version Load (1.4ms) SELECT "versions".* FROM "versions" WHERE "versions"."localization_id" = 25991 ORDER BY "versions"."id" DESC LIMIT 1
2012-10-01T22:00:45+00:00 app[web.1]: Localization Load (1.3ms) SELECT "localizations".* FROM "localizations" WHERE "localizations"."id" = 25991 LIMIT 1
2012-10-01T22:00:45+00:00 app[web.1]: WARNING: Can't mass-assign protected attributes: id, created_at, updated_at, localization_id, number
2012-10-01T22:00:45+00:00 app[web.1]: (1.3ms) BEGIN
2012-10-01T22:00:45+00:00 app[web.1]: CACHE (0.0ms) SELECT "localizations".* FROM "localizations" WHERE "localizations"."id" = 25991 LIMIT 1
2012-10-01T22:00:45+00:00 app[web.1]: (1.7ms) SELECT COUNT() FROM "versions" WHERE "versions"."localization_id" = 25991
2012-10-01T22:00:45+00:00 app[web.1]: SQL (2.0ms) INSERT INTO "versions" ("content", "created_at", "localization_id", "number", "updated_at") VALUES ($1, $2, $3, $4, $5) RETURNING "id" [["content", "Upcoming Awesome Shows10"], ["created_at", Mon, 01 Oct 2012 22:00:45 UTC +00:00], ["localization_id", 25991], ["number", 28], ["updated_at", Mon, 01 Oct 2012 22:00:45 UTC +00:00]]
2012-10-01T22:00:45+00:00 app[web.1]: (1.4ms) UPDATE "localizations" SET "draft_content" = 'Upcoming Awesome Shows10', "updated_at" = '2012-10-01 22:00:45.314546' WHERE "localizations"."id" = 25991
2012-10-01T22:00:45+00:00 app[web.1]: Blurb Load (1.4ms) SELECT "blurbs".
FROM "blurbs" WHERE "blurbs"."id" = 1131 LIMIT 1
2012-10-01T22:00:45+00:00 app[web.1]: Project Load (1.3ms) SELECT "projects".* FROM "projects" WHERE "projects"."id" = 1 LIMIT 1
2012-10-01T22:00:45+00:00 app[web.1]: TextCache Load (468.7ms) SELECT "text_caches".* FROM "text_caches" WHERE "text_caches"."id" = 1 LIMIT 1
2012-10-01T22:00:46+00:00 app[web.1]: (385.0ms) SELECT blurbs.key AS blurb_key, locales.key AS locale_key, draft_content AS content FROM "blurbs" INNER JOIN "localizations" ON "localizations"."blurb_id" = "blurbs"."id" INNER JOIN "locales" ON "locales"."id" = "localizations"."locale_id" WHERE "blurbs"."project_id" = 1

Then it logs this massive update:

2012-10-01T22:01:02+00:00 app[web.1]: (972.3ms) UPDATE "text_caches" SET "data" = '{"ko.artists.show.view_past":"Past Shows","ja.artists.show.view_past":"Past Shows","it.artists.show.view_past":"Past Shows","hu.artists.show.view_past":"Past Shows","hr.artists.show.view_past":"Past Shows"
....
looks like all of our blurbs
....
"updated_at" = '2012-10-01 22:01:01.321787' WHERE "text_caches"."id" = 1

and then

2012-10-01T22:01:18+00:00 app[web.1]: SQL (1.6ms) UPDATE "projects" SET "updated_at" = '2012-10-01 22:01:18.480287' WHERE "projects"."id" = 1
2012-10-01T22:01:18+00:00 app[web.1]: (3.4ms) COMMIT
2012-10-01T22:01:18+00:00 app[web.1]: Redirected to http://copycopter-instance.herokuapp.com/localizations/25991/versions/new
2012-10-01T22:01:18+00:00 app[web.1]: Completed 302 Found in 33193ms

and I've even upgraded to the Heroku Postgres "Crane" database from the "Basic" database, for a bit more performance. That didn't help. It looks like this is happening on all POSTs. But getting or "downloading translation" is fast and just fine.

I've been getting these issues for the latest sha 'd3607c4a032357d121148fee278cba44f87f41e9'
as well as a previous version '5bcf493ecfa1190cc6716bcd6554b2bce9c8e8d1'

@michaeldauria
copycopter member

I was seeing this and what I ended up doing was bringing back a background worker. How many blurbs do you have currently?

@dfuentes77

2400+ blurbs. This was setup before me but I was told that when setup, it auto added activeadmin activerecord attributes, error.attributes, formtastic.* , etc blurbs... which I'm guessing is why this is taking over 30 seconds to complete update the text_caches. And yet we only actually use a couple dozen. Is there an easy way of cleaning it all up?

@driv3r
driv3r commented Feb 8, 2013

I have the same, that's why I'm thinking of adding something like inserts in batches if its more than some amount or something similar, you can check out copycopter/copycopter-ruby-client#41 because I would probably need some advice there.

@dfuentes77

I didn't like these issues and didn't prefer the client/server model and so I went to https://github.com/Vermonster/copycat

@p1nox
p1nox commented Feb 11, 2013

Have you tried offline mode?

https://gist.github.com/p1nox/4755262

@dfuentes77

Didn't see it but it wouldn't work for us anyway since any change would require a push

@p1nox
p1nox commented Feb 11, 2013

Indeed, if that's your case then it's better to find another way.

@peresleguine

I ran into the same problem, couldn't find the solution.

@aaronpark

I have also ran into the same problem. form builder labels and such are getting added to the server. I am using copycopter client gem 2.0.1

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Something went wrong with that request. Please try again.