Carrierwave + S3 Storage + Counter Cache Taking too Long

Question

I have a simple app that receives POSTed images via an API and sends them to S3, via Carrierwave. My Photos table has a counter_cache as well.

80% of the time my transaction time is HUGE, like 60 seconds or more, and more than 90% of this time is spent uploading the image to S3 and updating counter_cache.

Does anybody have a clue about why this uploading time is so big and why counter cache queries are taking so long?

Just added some photos on http://carrierwave-s3-upload-test.herokuapp.com

Behavior was similar:

Just removed counter_cache from my code and did some more uploading.... Odd behavior again.

---

EDIT 1

Logs from last batch upload. EXCON_DEBUG is set to True: https://gist.github.com/rafaelcgo/561f516a85823e30fbad

---

EDIT 2

My logs weren't showing any EXCON output info. So I realized I was using fog 1.3.1. Updated to Fog 1.19.0 (which uses a newer version of the excon gem) and everything works nicely now.

Tips.. If you need to debug external connections, use the newer version of excon and set the env EXCON_DEBUG=true in order to see some verbose, like this: https://gist.github.com/geemus/8097874

---

EDIT 3

Guys, updated the gem fog and now it's sweet. Don't know why old versions of fog and excon have this odd performance.

Ploughboy

How many rows you have on the events table? – Chinfest

Not so many, right now I have only 10. And I might have something like 2k photos. – Ploughboy

What's the size of the images you're uploading to S3? – Chinfest

If you can provide a small sample app that demonstrates the behavior, it shouldn't be hard for us to track down. – Collator

Thx for the attention Taavo, I will try to provide it today, evening. – Ploughboy

@Collator there you go: github.com/rafaelcgo/carrierwave-s3-upload-test . I still havent made some batch uploading to test if the behaviour is the same, but I will as soon as possible – Ploughboy

Looks like the "baixar fotos" link is broken. Was there supposed to be some js hooking that up or something? Also: As below, have you tried updating fog? – Collator

@Collator is broken on purpose, it would trigger a worker to zip all the photos on S3, save the zip and send the link to the user... Nothing related, this is working great. WOW, I'm using fog from March 2012.. never noticed that, lemme update it. – Ploughboy

Ah. I thought that might be an upload link, sorry. So, for clarification, we're talking about this line taking forever, and saving a new photo causes the same behavior on the console on both your workstation and your heroku dyno? – Collator

@Taavo, yeap.. Sorry Taavo, I've been messed up with another issue here, but I will continue to investigate. I even didn't realized that my bount was expiring... I will open another one in the future to reward your help so far. Hope you can keep helping me... :) – Ploughboy

I'll try to keep an eye on this question in case you post more information. I'm pretty curious as to what could be going on. – Collator

@Collator I just added more info.. Without counter_cache same thing is happnening. I really don't know what's going on. – Ploughboy

@RafaelOliveira could you try running it with EXCON_DEBUG=true set? That will setup an instrumenter which will dump a lot more detailed info about what excon is doing out to the logs. I think that would give me much more to work with (though you should be cautious as it may require a bit of redaction before sharing). – Flawed

Sure @geemus, where do I need to set this? heroku config:add ? Just like an ENV var ? – Ploughboy

Yeah, sorry for the lack of specificity there. If you add it with config:add on Heroku or as an ENV_VAR locally it should do the same thing. Seems like putting it on Heroku is more apt to get us the info we need here though. Thanks! – Flawed

Just added but my logging output is still the same. I'm using foreman, don't know if this is conflicting or restricting my logging. – Ploughboy

Guys, updated the gem and now it's sweet. Don't know why old versions of fog and excon have this odd performance. thx for all the support. – Ploughboy

Answer 1

Three clues, but not the whole story:

1. CarrierWave transfers the file to s3 inside your database transaction. Because counter_cache's update also occurs inside the transaction, it's possible that your benchmarking code thinks the update is taking forever, when really it's the file transfer that's taking forever.

2. Last I checked it wasn't even possible for a heroku application dyno to sustain a connection as long as you're seeing. You should be seeing H12 or H15 errors in your logs if you've got synchronous uploads going past about 30 seconds. More on heroku timeouts here.

3. Have you tried updating fog? 1.3.1 is a year and a half old, and they've probably fixed a bug or two since then.

Past that, the only thing that comes to mind is that you're uploading a file of epic scale. I've been disappointed in both the latency and throughput I've been able to achieve from heroku to s3, so that also could be involved.

Obligatory: You aren't letting users upload directly to your dyno, are you?

Collator

My files are something around 100kb, they're not so big... And my S3 bucket is located at us-east-1, just like Heroku. 1. Yeap, I tought of that, but transaction time is the sum of upload AND counter_cache update... but it might be some kind of misunderstanding of new relic. 2. I'm receiving those H12 errors, but after the H12 the heroku dyno continues what it was doing. So my client think the file was not uploaded to S3, but after some more 30 seconds, the file is there. My main problem is that huge upload time. Why an upload of 100kb FROM Heroku to S3, on the same region, is taking SO LONG? – Ploughboy