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 -- [EMAIL PROTECTED] -- Engine Yard, Serious Rails Hosting -- (866) 518-YARD (9273) _______________________________________________ Merb-devel mailing list [email protected] http://rubyforge.org/mailman/listinfo/merb-devel
