Routes

[Ezra Zygmuntowicz]

Hi~

On Sep 19, 2007, at 2:36 AM, Brian Candler wrote:

> OK, I hacked together a simple replacement logger, and this is what  
> I get
> with logging *enabled* (merb -e production)
>
>   %   cumulative   self              self     total
>  time   seconds   seconds    calls  ms/call  ms/call  name
>   3.69     0.34      0.34      100     3.40    76.60   
> MerbHandler#process
>   3.25     0.64      0.30      800     0.38     0.73   
> Merb::Logger#info
>   3.15     0.93      0.29     3724     0.08     0.20  Hash#[]
>   3.04     1.21      0.28      400     0.70     1.47  Hash#inspect
>   2.93     1.48      0.27      300     0.90     2.10  Hash#each_pair
>   2.60     1.72      0.24       52     4.62    43.27  Kernel.sleep
>   2.60     1.96      0.24      200     1.20     1.75   
> Mongrel::HttpResponse#send_status
>   2.49     2.19      0.23      400     0.58     1.02   
> Merb::AbstractController#after_filters
>   2.17     2.39      0.20      100     2.00     2.60   
> Mongrel::HttpRequest#initialize
>   2.17     2.59      0.20      100     2.00    25.80  IO#close
>   2.06     2.78      0.19     1600     0.12     0.73  Class#new
>   2.06     2.97      0.19      100     1.90     4.60   
> Merb::Request#query_params  1.95     3.15      0.18      200      
> 0.90     1.60  Mash#include?
>   1.95     3.33      0.18      400     0.45     0.45  String#split
>   1.84     3.50      0.17      100     1.70     8.50   
> Merb::AbstractController#dispatch
>   1.63     3.65      0.15      700     0.21     0.29  Mash#convert_key
>   1.52     3.79      0.14      100     1.40    19.90   
> Merb::Controller#dispatch
>   1.52     3.93      0.14      100     1.40    70.10   
> Mongrel::HttpServer#process_client
>   1.41     4.06      0.13      100     1.30     2.80   
> Merb::Router#match
>   1.41     4.19      0.13      800     0.16     0.59   
> Merb::Request#route_params  1.41     4.32      0.13      300      
> 0.43     0.67  Mongrel::HeaderOut#[]=
>   1.30     4.44      0.12      300     0.40     0.40  Hash#key?
>   1.30     4.56      0.12      400     0.30     0.30  NilClass#inspect
>   1.19     4.67      0.11      400     0.28     0.28   
> Mash#convert_value
>   1.19     4.78      0.11     1300     0.08     0.08  Kernel.class
>   1.19     4.89      0.11      900     0.12     0.12  String#[]
>   1.19     5.00      0.11      100     1.10    56.20   
> Merb::Dispatcher#handle
>   1.08     5.10      0.10      400     0.25     0.70   
> Merb::AbstractController#before_filters
>   1.08     5.20      0.10      200     0.50     2.10  Mash#default
> ... snip less than 1%
>   0.00     9.22      0.00        1     0.00  9220.00  #toplevel
>
> Performance test using ab -n 1000 http://localhost:4000/hello/world
>
> [Before patch]
>
> Requests per second:    276.78 [#/sec] (mean)
> Time per request:       3.613 [ms] (mean)
>
> [After patch]
>
> Requests per second:    401.49 [#/sec] (mean)
> Time per request:       2.491 [ms] (mean)
>
> This is on a 1.1GHz Pentium M. It would be interesting to see what  
> people
> with higher-performance servers achieve.
>
> Cheers,
>
> Brian.
>
> P.S. In this code, a single write is done at the end of each  
> request. I've
> not protected it with a mutex, because I think that IO#write is  
> atomic, but
> I may be wrong.
>
> More performance could perhaps be achieved by not flushing after every
> request, but by doing this in a background thread. However I think  
> it might
> make more sense if we're going this route to give each request its  
> own log
> buffer, so that logs don't get interspersed from overlapping  
> requests in a
> multi-threaded application.
>
> Also, I notice that the logger class and initialisation is currently
> hard-coded into merb.rb; perhaps it would be better to make this
> configurable.
> <newlog.diff>


	Nice one. We were actually just talking about fixing the logger the  
other day after some profiling and I was going to make a logger that  
collected up the strings and then output them once per request. I;ll  
take a look at your patch and will probably make the logger  
configurable so we can test different loggers.

Cheers-
-- Ezra Zygmuntowicz 
-- Founder & Ruby Hacker
-- ez at engineyard.com
-- Engine Yard, Serious Rails Hosting
-- (866) 518-YARD (9273)