Rails core - May 2009 - Why does ActionController::Response write line-by-line to the network?

I''ve been doing some benchmarking of our application recently, and  
comparing implementing components in Metal vs. traditional controller  
actions.  One thing I discovered was that there was a substantial gap  
between the time reported within Rails to serve pages, versus what  
apachebench measured.  Also, this gap was much larger for the  
traditional serving compared to Metal.  In one case, ab reported 65ms  
more than what was seen inside Rails.  The same page served via Metal  
had only a 3.5ms gap between the two measurements.  I was pretty  
puzzled until I finally discovered that the controller returned an  
ActionController::Response to Rack, whereas the metal component was  
returning an [String].  Going to the source I found this

     def each(&callback)
       if @body.respond_to?(:call)
         @writer = lambda { |x| callback.call(x) }
         @body.call(self, self)
       elsif @body.is_a?(String)
         @body.each_line(&callback)        <======== look here
       else
         @body.each(&callback)
       end

       @writer = callback
       @block.call(self) if @block
     end


In the case where the body of the response is a String (which always  
seems to be the case in our application; I''m not sure how you get the  
other cases), each() yields each line of the response individually.   
As a result, every line in the output leads to a socket write and a  
system call.  For the particular page I was looking at, admittedly  
rather substantial, this was 1300 calls.  This is, to put it mildly,  
bad for performance.  I changed that line to  
"[@body].each(&callback)", and *poof* the page got 65ms faster.

This particular line was added in
http://github.com/rails/rails/commit/5eb893f72d189a7ad82c9a6f45873e2317f202d5
, which doesn''t seem to give any particular justification for  
iterating by line, rather than just returning the whole string.  Is  
there any argument for why it should be this way?  It seems to me like  
it can only be a pessimization.


-kevin

That commit was probably made for 1.9 compatibility. Since then there
were some changes to the actual rack SPEC that the body must respond
to each and can no longer be a string.

@body.each_line(&callback)

should probably just be changed to

yield @body

Can you test that and see if it fixes your performance problems.

On May 7, 10:48 pm, Kevin Scaldeferri <kevin+goo...@scaldeferri.com>
wrote:
> I''ve been doing some benchmarking of our application recently, and
 
> comparing implementing components in Metal vs. traditional controller  
> actions.  One thing I discovered was that there was a substantial gap  
> between the time reported within Rails to serve pages, versus what  
> apachebench measured.  Also, this gap was much larger for the  
> traditional serving compared to Metal.  In one case, ab reported 65ms  
> more than what was seen inside Rails.  The same page served via Metal  
> had only a 3.5ms gap between the two measurements.  I was pretty  
> puzzled until I finally discovered that the controller returned an  
> ActionController::Response to Rack, whereas the metal component was  
> returning an [String].  Going to the source I found this
>
>      def each(&callback)
>        if @body.respond_to?(:call)
>          @writer = lambda { |x| callback.call(x) }
>          @body.call(self, self)
>        elsif @body.is_a?(String)
>          @body.each_line(&callback)        <======== look here
>        else
>          @body.each(&callback)
>        end
>
>        @writer = callback
>        @block.call(self) if @block
>      end
>
> In the case where the body of the response is a String (which always  
> seems to be the case in our application; I''m not sure how you get
the  
> other cases), each() yields each line of the response individually.  
> As a result, every line in the output leads to a socket write and a  
> system call.  For the particular page I was looking at, admittedly  
> rather substantial, this was 1300 calls.  This is, to put it mildly,  
> bad for performance.  I changed that line to  
> "[@body].each(&callback)", and *poof* the page got 65ms
faster.
>
> This particular line was added
inhttp://github.com/rails/rails/commit/5eb893f72d189a7ad82c9a6f45873e23...
> , which doesn''t seem to give any particular justification for  
> iterating by line, rather than just returning the whole string.  Is  
> there any argument for why it should be this way?  It seems to me like  
> it can only be a pessimization.
>
> -kevin

Yes, that change fixes the performance issue.

-kevin


On May 7, 2009, at 9:24 PM, Joshua Peek wrote:
>
> That commit was probably made for 1.9 compatibility. Since then there
> were some changes to the actual rack SPEC that the body must respond
> to each and can no longer be a string.
>
> @body.each_line(&callback)
>
> should probably just be changed to
>
> yield @body
>
> Can you test that and see if it fixes your performance problems.
>
> On May 7, 10:48 pm, Kevin Scaldeferri <kevin+goo...@scaldeferri.com>
> wrote:
>> I''ve been doing some benchmarking of our application recently,
and
>> comparing implementing components in Metal vs. traditional controller
>> actions.  One thing I discovered was that there was a substantial gap
>> between the time reported within Rails to serve pages, versus what
>> apachebench measured.  Also, this gap was much larger for the
>> traditional serving compared to Metal.  In one case, ab reported 65ms
>> more than what was seen inside Rails.  The same page served via Metal
>> had only a 3.5ms gap between the two measurements.  I was pretty
>> puzzled until I finally discovered that the controller returned an
>> ActionController::Response to Rack, whereas the metal component was
>> returning an [String].  Going to the source I found this
>>
>>     def each(&callback)
>>       if @body.respond_to?(:call)
>>         @writer = lambda { |x| callback.call(x) }
>>         @body.call(self, self)
>>       elsif @body.is_a?(String)
>>         @body.each_line(&callback)        <======== look here
>>       else
>>         @body.each(&callback)
>>       end
>>
>>       @writer = callback
>>       @block.call(self) if @block
>>     end
>>
>> In the case where the body of the response is a String (which always
>> seems to be the case in our application; I''m not sure how you
get the
>> other cases), each() yields each line of the response individually.
>> As a result, every line in the output leads to a socket write and a
>> system call.  For the particular page I was looking at, admittedly
>> rather substantial, this was 1300 calls.  This is, to put it mildly,
>> bad for performance.  I changed that line to
>> "[@body].each(&callback)", and *poof* the page got 65ms
faster.
>>
>> This particular line was added
inhttp://github.com/rails/rails/commit/5eb893f72d189a7ad82c9a6f45873e23
>> ...
>> , which doesn''t seem to give any particular justification for
>> iterating by line, rather than just returning the whole string.  Is
>> there any argument for why it should be this way?  It seems to me  
>> like
>> it can only be a pessimization.
>>
>> -kevin
> >