search

assaf / vanity

Experiment Driven Development for Ruby
http://vanity.labnotes.org
MIT License
1.55k stars 269 forks source link

Performance hotspot on VanityMetric#updated_at #183

Open stangel opened 10 years ago

stangel commented 10 years ago

We experienced database performance problems today resulting from a dozen or more simultaneous calls to the track! helper method. Turns out the database (Postgresql 9.2) was experiencing high contention (wait locks) on the following query, which originated from https://github.com/assaf/vanity/blob/master/lib/vanity/adapters/active_record_adapter.rb#L139 

UPDATE "vanity_metrics" SET "updated_at" = '2014-01-28 04:31:37.577345' WHERE "id" = 19"

That timestamp seems of little value compared to the importance of functioning smoothly in a highly-concurrent environment. I considered submitting a pull request that adds "respond_to? :updated_at" to that line as well as line 129 [so I could then drop that column from my database], however I thought it best to approach you about it first. Do you have any thoughts on this?

phillbaker commented 10 years ago

@stangel, thanks for the bug report. I want to do a little more digging, but just want to confirm a few things:

Here's what I've found so far:

In general, I'd agree that database contention is a much bigger issue than updating this value - especially because it doesn't seem to be used. If you're working off of a fork, the quick fix might be to remove that line. If you don't want to fork but do have some sort of asynchronous processing (Sidekiq, Resque, DelayedJob, SuckerPunch, etc.), it might be even easier to throw the track! into an async call.

Going forward, I'm not sure off hand what the best solution to this is, I'll do some homework and get back to you.

On Tue, Jan 28, 2014 at 3:57 PM, Mike Stangel notifications@github.com wrote:

We experienced database performance problems today resulting from a dozen or more simultaneous calls to the track! helper method. Turns out the database (Postgresql 9.2) was experiencing high contention (wait locks) on the following query, which originated from https://github.com/assaf/vanity/blob/master/lib/vanity/adapters/active_record_adapter.rb#L139

UPDATE "vanity_metrics" SET "updated_at" = '2014-01-28 04:31:37.577345' WHERE "id" = 19"

That timestamp seems of little value compared to the importance of functioning smoothly in a highly-concurrent environment. I considered submitting a pull request that adds "respond_to? :updated_at" to that line as well as line 129 [so I could then drop that column from my database], however I thought it best to approach you about it first. Do you have any thoughts on this?

Reply to this email directly or view it on GitHub.

stangel commented 10 years ago

Thanks @phillbaker. We're running Ruby on Rails with unicorn, yes each process has its own database connection (they are pooled sequentially using pgbouncer in front of Postgres but this shouldn't matter for concurrent queries). We have our own back-end asynchronous system (https://github.com/stangel/sweatshop) but moving the track! call to those back-end servers won't make a difference if the waiting locks are causing the connection pool to be exhausted. After some consideration I think I'll monkey-patch L139 to only update the timestamp if more than a minute has passed, i.e.

now = Time.now
record.updated_at = now if now - record.updated_at >= 1.minute

This preserves the functionality (more or less) while avoiding the concurrency problem.

phillbaker commented 10 years ago

@stangel that's a good compromise, that's something I'd be comfortable merging.

Also, I'd like to be able to reproduce this, but it sounds like you have a few parts to your stack. Any chance you could reproduce this simply? On Jan 29, 2014 12:37 PM, "Mike Stangel" notifications@github.com wrote:

Thanks @phillbaker https://github.com/phillbaker. We're running Ruby on Rails, yes each process has its own database connection (they are pooled sequentially using pgbouncer in front of Postgres but this shouldn't matter for concurrent queries). We have our own back-end asynchronous system ( https://github.com/stangel/sweatshop) but moving the track! call to those back-end servers won't make a difference if the waiting locks are causing the connection pool to be exhausted. After some consideration I think I'll monkey-patch L139 to only update the timestamp if more than a minute has passed, i.e.

now = Time.now record.updated_at = now if now - record.updated_at >= 1.minute

This preserves the functionality (more or less) while avoiding the concurrency problem.

Reply to this email directly or view it on GitHubhttps://github.com/assaf/vanity/issues/183#issuecomment-33608874 .

stangel commented 10 years ago

To reproduce you'll need a highly-concurrent environment, say 20 or 30 threads that will all call track! on the same metric at the same time. You might also need a database under heavy load, which ours is. :-) I'll submit a pull request.

phillbaker commented 10 years ago

Yea, I figured. I'd like to play with something to mimic that, but it's not going to happen in the near term. I'll leave this as something to look at when I have some time.

Did you find any other (performance) pain points when using vanity? I know we've had missing indexes in the past.

stangel commented 10 years ago

No, this is the only issue we've encountered. I got your note on my pull request and will refactor it per your suggestion.