Speeding up a Rails request by 150ms by changing 1 line(kevin.scaldeferri.com)
kevin.scaldeferri.com
Speeding up a Rails request by 150ms by changing 1 line
http://kevin.scaldeferri.com/blog/2009/05/08/RailsRackResponse.html
34 comments
You've missed an important but subtle point. The article points out that the reason this was overlooked is not because Rails isn't profiled but because this behaviour is happening outside the standard rails profiling scope. That is a) why it's not a "relatively-straightforward bug fix", b) why it hadn't been caught already and c) why it is interesting. Actually I take that back, it is a relatively-straightforward bug fix. As with all the best bugs it's finding it that wasn't straightforward.
I think a similar thing happened about a year ago when people were profiling rails but not profiling memory usage. After they realised GC was impacting their performance they shifted their focus and improved things in that regard. The most recent "X line Y% speedup" article I read here took this even further and examined the impact of the size of stack vs. heap memory on GC times.
My particular favourite example of this is Steve Souders work showing how much your web app performance is affected by the end users browser and its wacky network and cache behaviour. He has claimed these factors can account for 80-90% of the end-users' waiting time. I know rails core have been working to fix these issues as they did a presentation about.
That sounds to me like a bunch of useful lessons to be learned from. Certainly more info than just "profiling good", more like non-holistic profiling can be misleading. Your response certainly doesn't cover this as you talk about "basic profiling", so what is outside the profiling you do? How would you know if it is affecting performance and to what degree?
I think a similar thing happened about a year ago when people were profiling rails but not profiling memory usage. After they realised GC was impacting their performance they shifted their focus and improved things in that regard. The most recent "X line Y% speedup" article I read here took this even further and examined the impact of the size of stack vs. heap memory on GC times.
My particular favourite example of this is Steve Souders work showing how much your web app performance is affected by the end users browser and its wacky network and cache behaviour. He has claimed these factors can account for 80-90% of the end-users' waiting time. I know rails core have been working to fix these issues as they did a presentation about.
That sounds to me like a bunch of useful lessons to be learned from. Certainly more info than just "profiling good", more like non-holistic profiling can be misleading. Your response certainly doesn't cover this as you talk about "basic profiling", so what is outside the profiling you do? How would you know if it is affecting performance and to what degree?
You've missed an important but subtle point. The article points out that the reason this was overlooked is not because Rails isn't profiled but because this behaviour is happening outside the standard rails profiling scope. That is a) why it's not a "relatively-straightforward bug fix", b) why it hadn't been caught already and c) why it is interesting. Actually I take that back, it is a relatively-straightforward bug fix. As with all the best bugs it's finding it that wasn't straightforward.
Properly profiling the full execution path should be an entirely obvious step to take.
Properly profiling the full execution path should be an entirely obvious step to take.
The short and to-the-point version of the post went to the Rails-core mailing list. On my blog, I prefer to tell stories.
Bragging about how fast you can serve a request is really meaningless when there's no way to know what's involved in that request. On my personal side projects (also using Rails), I serve requests in a couple milliseconds too. But, there's a vast, vast difference in what those sites do, vs what's involved in running a large-scale e-commerce operation.
Bragging about how fast you can serve a request is really meaningless when there's no way to know what's involved in that request. On my personal side projects (also using Rails), I serve requests in a couple milliseconds too. But, there's a vast, vast difference in what those sites do, vs what's involved in running a large-scale e-commerce operation.
The short and to-the-point version of the post went to the Rails-core mailing list. On my blog, I prefer to tell stories.
There are quite a few stories of this nature, which could simply be summarized as individuals finding incredibly simple inefficiencies and then fixing them.
There are quite a few stories of this nature, which could simply be summarized as individuals finding incredibly simple inefficiencies and then fixing them.
IME, many many developers have no idea how to measure and profile their code. The reason for the stories is to help educate people with less experience in what tools to use, and how to use them.
I'll admit that I don't know enough about this. Got any pointers or links for the intermediate Rails hacker? (I'll check out ab, as mentioned in your post.)
Great! Then you should find them and write about them.
I like this type of blog post. I'd much rather read stories about people solving real problems with real code than blowhards pontificating about their favorite design patterns.
Whether Rails is immature doesn't make it less interesting to see how people track down its problems and fix them.
Whether Rails is immature doesn't make it less interesting to see how people track down its problems and fix them.
Having lived in Ruby code for a bit, I think it's fair to say that you're entirely right. It's immature, it's poorly profiled, it has memory leaks, and the scoping rules are a nightmare.
But it sounds like you were doing profiling and optimization early and often, which might have been premature, and thus might have been a waste of time.
Who's to say? Ruby isn't for everyone. Perhaps your ideal web stack is what you're using. (What're you using, btw?) I've been itching to use Haskell for a webapp.
But it sounds like you were doing profiling and optimization early and often, which might have been premature, and thus might have been a waste of time.
Who's to say? Ruby isn't for everyone. Perhaps your ideal web stack is what you're using. (What're you using, btw?) I've been itching to use Haskell for a webapp.
"Perhaps your ideal web stack is what you're using. (What're you using, btw?)"
He has stated in previous comments that he's using scala.
Interestingly, merb on jruby has reportedly reached 14000 rps on similar hardware to what he's refering to (8 cores, since he previously claimed to get 5000 rps on a 4 core machine).
He has stated in previous comments that he's using scala.
Interestingly, merb on jruby has reportedly reached 14000 rps on similar hardware to what he's refering to (8 cores, since he previously claimed to get 5000 rps on a 4 core machine).
Between the lot of these, the only message I'm getting is "ruby and rails authors happily dump speed in favor of not thinking terribly hard."
Seriously, is it that hard to pull up dtrace and do a little analysis? They even have dtrace-ruby bindings on MacOS! http://www.infoq.com/news/2007/10/ruby-leopard
Seriously, is it that hard to pull up dtrace and do a little analysis? They even have dtrace-ruby bindings on MacOS! http://www.infoq.com/news/2007/10/ruby-leopard
Rails returns the body 1 line at a time? That can't seriously be true, can it?
True. Seriously. At least in 2.3. Pre-Rack, I don't imagine that code would have been present.
It's in 2.3 stable, but it appears to no longer be present in edge (in fact, ActionPack has already gone through a lot of changes):
http://is.gd/xP8Y (github link)
http://is.gd/xP8Y (github link)
String.each is the same as String.each_line in ruby 1.8. This code rewrite seems to be the reason that code breaks on ruby 1.9 if body is a string (this is guarded against in the body setter). (ruby 1.9 removes String.each)
http://github.com/josh/rack/tree/master :
* NOTE: String bodies break in 1.9, use an Array consisting of a single String instead.
p.s. this is definitely worth a 2.3.3 tag and release
http://github.com/josh/rack/tree/master :
* NOTE: String bodies break in 1.9, use an Array consisting of a single String instead.
p.s. this is definitely worth a 2.3.3 tag and release
yeah, 3.0 changes a lot. It does appear that it will not exhibit the same problem.
Is there a lot of per-line processing in Rails? Or is this something caused by Rack?
I know next to nothing about Rails, so I'm sorry if these are questions with obvious answers. I just think the decision to process body responses on a per-line basis seems odd.
I know next to nothing about Rails, so I'm sorry if these are questions with obvious answers. I just think the decision to process body responses on a per-line basis seems odd.
It's definitely odd. I'm inclined to attribute it to carelessness, and just not really thinking about the implications of precisely how they chose to implement the Rack specification.
What's frustrating is that apparently there wasn't any performance testing of the 2.3 release that ought to have found this problem. It's been in the code base for about a year at this point.
What's frustrating is that apparently there wasn't any performance testing of the 2.3 release that ought to have found this problem. It's been in the code base for about a year at this point.
How often is ActionResponse.body a String? It's not really clear to me without digging deeper, but I could see this easily being an edge case related to certain caching and rendering methods. In any case, suggesting that any performance testing of Rails would have magically found this problem is unfair. Many many many Rails app instances are serving orders of magnitude more than 10reqs/sec, so clearly this is not a universal problem.
My guess as to the reasoning here is so that large files can be served without blocking while the whole thing is written to the socket. Granted, that's just my gut instinct looking at that code, maybe it is just careless...
My guess as to the reasoning here is so that large files can be served without blocking while the whole thing is written to the socket. Granted, that's just my gut instinct looking at that code, maybe it is just careless...
I checked that, and I couldn't find any case where the body _wasn't_ a String.
It's true, that the problem only becomes really glaring when the pages being served are quite large (this example was 1300 lines of HTML), but I still assert that good performance regression testing ought to have popped this up. With 100 lines of output, which is pretty reasonable, you'd still be looking at an extra 10ms on each request.
It's true, that the problem only becomes really glaring when the pages being served are quite large (this example was 1300 lines of HTML), but I still assert that good performance regression testing ought to have popped this up. With 100 lines of output, which is pretty reasonable, you'd still be looking at an extra 10ms on each request.
I've been running Rails 2.3 in production for a while with great performance.
In the article the author mentions it has to do with serving static files, which is something that nobody should be using Rails to do anyway. I'm not surprised nobody found it until now.
In the article the author mentions it has to do with serving static files, which is something that nobody should be using Rails to do anyway. I'm not surprised nobody found it until now.
Why the... ???
It makes me want to cry that people are still writing things in technologies that require you to drop little timing statements into your code to profile them.
Profilers have been around for what? 30 years? I think the first time I hooked Ants Profiler up to an ASP.NET site was 2002. Are these other web technologies really that far behind the state of the art?
Profilers have been around for what? 30 years? I think the first time I hooked Ants Profiler up to an ASP.NET site was 2002. Are these other web technologies really that far behind the state of the art?
I didn't feel like getting into the nitty-gritty details of my analysis, but Ruby does have a profiler, and it integrates into Rails quite well, and I was using it together with timers in this investigation. However, the exact same issue applies to the profiler as to simple timers, which is that the 150ms in question happens _after_ Rails hands off the reply to the web server, so as long as you are only measuring within the Rails framework, you will not see it.
Strange. My expectation would be that you'd hook a profiler up to the web process and it would simply follow all ruby code paths, regardless of whether Rails were involved or not. Or do we have different definitions of Profiler?
You're talking about a separate application that watches executing code and keeps statistics, right? As in, not simply a set of timing functions in a wrapper somewhere in the framework? If so, how does it come off the trolley after Rails finishes its job?
You're talking about a separate application that watches executing code and keeps statistics, right? As in, not simply a set of timing functions in a wrapper somewhere in the framework? If so, how does it come off the trolley after Rails finishes its job?
ruby-prof is a module that runs inside the ruby process, and hooks into the interpreter to track what's happening. You have options for how to run it. You can run the entire program within the profiler, but if you do that, you won't get data out until the process ends (you kill the webserver, in this case). Or, you can do what's more typical for profiling Rails, which is to explicitly activate the profiler for the course of a single request, and report on that single request.
Take these kind of comments to Reddit, you obviously know nothing about Rails and Ruby, especially Rack and Metal.
"Metal components operate outside the realm of the usual Rails timing and logging components, so you don’t get any internal measurements of page performance."
Indeed, I'd never heard of Metal before reading this post. The quote you included is what lead me to wonder why there are not better tools for such a popular development framework as Ruby on Rails.
As that quote states, there doesn't appear to be a profiler as such, but rather a set of "timing and logging components" built into the framework. If it's true, then ruby today is essentially handling profiling the same way PHP did it in 1998. I find that surprising and saddening.
As that quote states, there doesn't appear to be a profiler as such, but rather a set of "timing and logging components" built into the framework. If it's true, then ruby today is essentially handling profiling the same way PHP did it in 1998. I find that surprising and saddening.
See above comment about dtrace probes, also there is ruby-perf and services like http://www.newrelic.com/features.html
Also, what is the way PHP handles profiling in 2009 ? I haven't developed in php in quite a while, and I admit I never used anything more complicated then the profiling tools built in Zend Studio.
Also, what is the way PHP handles profiling in 2009 ? I haven't developed in php in quite a while, and I admit I never used anything more complicated then the profiling tools built in Zend Studio.
The regular occurrence of such issues in a project implies an immature, poorly profiled code base, and are the kinds of things that other projects fix without fanfare.
Our most recent database-backed dynamic web application can serve >10000 requests/sec on our mid-range hardware at <2 ms/req, which we achieved by running the most basic of profiling early on and throughout the development process, and using software that does the same. I don't expect a gold star for this.