On Tue, Sep 18, 2007 at 01:45:58PM -0700, Ezra Zygmuntowicz wrote:
> In the big picture of a
> merb dispatch the current routers compiled_statement is not even
> close to being a significant slice of the time spent dispatching a
> request.
Good point.
I'm not sure what the current best way to profile merb is, so I hacked
something very simple:
--- /usr/lib/ruby/gems/1.8/gems/merb-0.4.0/lib/merb/server.rb.orig
2007-09-19 08:43:28.000000000 +0100
+++ /usr/lib/ruby/gems/1.8/gems/merb-0.4.0/lib/merb/server.rb 2007-09-19
08:47:03.000000000 +0100
@@ -439,6 +439,8 @@
start(@@merb_opts[:port])
else
trap('TERM') { exit }
+ trap("USR1") { require 'profiler'; Profiler__::start_profile }
+ trap("USR2") { Profiler__::stop_profile;
Profiler__::print_profile($stderr) }
mongrel_start(@@merb_opts[:port])
end
I tested with the following app, run in production mode (merb -e production):
Merb::Router.prepare do |r|
r.resources :foos
r.resources :bars
r.resources :bazs
r.default_routes
end
class Hello < Application
def world
"Hello, world!"
end
end
I then hit it 100 times on /hello/world, sent -USR1, hit it 100 times on
/hello/world again, and sent -USR2.
Here are the results:
% cumulative self self total
time seconds seconds calls ms/call ms/call name
5.41 0.84 0.84 1000 0.84 6.98 Logger#add
5.15 1.64 0.80 900 0.89 4.10 MonitorMixin.synchronize
3.41 2.17 0.53 900 0.59 0.79
Logger::Formatter#format_datetime
3.03 2.64 0.47 900 0.52 1.78 MonitorMixin.mon_exit
2.83 3.08 0.44 900 0.49 0.68 MonitorMixin.mon_release
2.25 3.43 0.35 900 0.39 0.43 Logger::Formatter#msg2str
2.12 3.76 0.33 900 0.37 0.40
Logger::LogDevice#check_shift_log
2.12 4.09 0.33 900 0.37 0.74 MonitorMixin.mon_enter
2.06 4.41 0.32 99 3.23 139.39 TCPServer#accept
2.00 4.72 0.31 100 3.10 4.80 Merb::Router#match
1.93 5.02 0.30 100 3.00 137.10 MerbHandler#process
1.93 5.32 0.30 3877 0.08 0.15 Hash#[]
1.93 5.62 0.30 900 0.33 1.77 Logger::Formatter#call
1.87 5.91 0.29 400 0.73 1.30 Hash#inspect
1.61 6.16 0.25 1900 0.13 0.14 Time#now
1.42 6.38 0.22 900 0.24 0.31
MonitorMixin.mon_check_owner
1.42 6.60 0.22 3600 0.06 0.06 Thread#critical=
1.35 6.81 0.21 900 0.23 2.02 Logger#format_message
1.35 7.02 0.21 400 0.52 0.52 String#split
1.29 7.22 0.20 100 2.00 148.80
Mongrel::HttpServer#process_client
1.29 7.42 0.20 700 0.29 0.33 Mash#convert_key
1.29 7.62 0.20 900 0.22 0.24 MonitorMixin.mon_acquire
1.22 7.81 0.19 300 0.63 1.37 Hash#each_pair
1.22 8.00 0.19 300 0.63 0.73 Mongrel::HeaderOut#[]=
1.16 8.18 0.18 2200 0.08 0.10 String#%
1.16 8.36 0.18 200 0.90 2.90
Mongrel::DirHandler#can_serve
1.09 8.53 0.17 1800 0.09 0.09 Array#shift
1.03 8.69 0.16 600 0.27 0.62
Class#read_inheritable_attribute
0.97 8.84 0.15 200 0.75 0.75 File#expand_path
0.97 8.99 0.15 1600 0.09 0.65 Class#new
0.97 9.14 0.15 100 1.50 2.70
Mongrel::HttpRequest#initialize
0.97 9.29 0.15 100 1.50 88.80 Merb::Dispatcher#handle
0.97 9.44 0.15 200 0.75 1.95 Merb::Request#query_parse
0.90 9.58 0.14 1800 0.08 0.08 Hash#default
0.90 9.72 0.14 78 1.79 19.87 Kernel.sleep
0.84 9.85 0.13 800 0.16 0.96
Merb::Request#route_params 0.77 9.97 0.12 200 0.60 0.80
Mash#default
0.77 10.09 0.12 800 0.15 0.78 Merb::Request#route_match
0.71 10.20 0.11 600 0.18 0.18
Class#inheritable_attributes
0.71 10.31 0.11 900 0.12 0.17 Logger#format_severity
0.64 10.41 0.10 1800 0.06 0.06 NilClass#nil?
0.64 10.51 0.10 1000 0.10 0.10 String#inspect
0.64 10.61 0.10 1300 0.08 0.08 Fixnum#==
0.64 10.71 0.10 900 0.11 0.11 Thread#pass
0.64 10.81 0.10 300 0.33 4.93 Merb::Request#params
0.64 10.91 0.10 106 0.94 1.60 Array#map
0.64 11.01 0.10 100 1.00 1.50 Merb::Request#path
0.64 11.11 0.10 200 0.50 0.70
Mongrel::HttpRequest#unescape
0.58 11.20 0.09 300 0.30 0.57
Merb::Request#controller_name
0.58 11.29 0.09 400 0.23 1.35
Merb::AbstractController#before_filters
0.58 11.38 0.09 100 0.90 4.00 Kernel.catch
0.58 11.47 0.09 753 0.12 18.46 Array#each
0.58 11.56 0.09 1200 0.08 0.08 Kernel.respond_to?
0.58 11.65 0.09 900 0.10 4.29 Logger::LogDevice#write
0.58 11.74 0.09 1300 0.07 0.07 IO#write
0.52 11.82 0.08 100 0.80 1.20 String#to_const_string
0.52 11.90 0.08 400 0.20 0.25 Mash#convert_value
0.52 11.98 0.08 100 0.80 0.80 Thread#initialize
0.52 12.06 0.08 400 0.20 0.28
Mongrel::HttpResponse#write
0.52 12.14 0.08 400 0.20 0.52
Merb::Controller#_session_id_key
0.52 12.22 0.08 100 0.80 5.60
Merb::Request#controller_class
0.52 12.30 0.08 1453 0.06 0.06 Kernel.nil?
0.45 12.37 0.07 400 0.18 0.88
Merb::AbstractController#after_filters
0.45 12.44 0.07 1800 0.04 0.04 Module#===
0.45 12.51 0.07 100 0.70 0.70 Fixnum#>=
0.45 12.58 0.07 300 0.23 0.33 Array#include?
0.45 12.65 0.07 900 0.08 7.90 Logger#info
0.45 12.72 0.07 800 0.09 0.09 Symbol#inspect
0.45 12.79 0.07 200 0.35 1.00
Mongrel::HttpResponse#send_status
0.45 12.86 0.07 1000 0.07 0.07 Time#strftime
0.39 12.92 0.06 1000 0.06 0.06 String#<<
0.39 12.98 0.06 100 0.60 1.80 Hash#each
0.39 13.04 0.06 100 0.60 2.80
Mongrel::HttpResponse#initialize
0.39 13.10 0.06 200 0.30 0.35 Enumerable.inject
0.39 13.16 0.06 200 0.30 1.30
Merb::Request#body_and_query_params
0.39 13.22 0.06 300 0.20 0.20 Hash#key?
0.39 13.28 0.06 100 0.60 2.50 Object#full_const_get
0.39 13.34 0.06 1100 0.05 0.05 Fixnum#-
0.39 13.40 0.06 100 0.60 7.00
Merb::AbstractController#dispatch
0.39 13.46 0.06 1800 0.03 0.03 Thread#current
0.32 13.51 0.05 100 0.50 1.30
Merb::CookieStore#initialize
0.32 13.56 0.05 100 0.50 0.70
Mongrel::HttpParser#execute
0.32 13.61 0.05 100 0.50 2.80
Merb::Controller#set_dispatch_variables
0.32 13.66 0.05 200 0.25 0.80 Hash#to_mash
0.32 13.71 0.05 200 0.25 0.40 Mash#initialize
0.32 13.76 0.05 100 0.50 39.90 Merb::Controller#dispatch
0.26 13.80 0.04 400 0.10 0.20
Merb::Request#content_type 0.26 13.84 0.04 600 0.07 0.07
String#==
0.26 13.88 0.04 100 0.40 1.00 Time#httpdate
0.26 13.92 0.04 100 0.40 1.30
Merb::Request#query_params 0.26 13.96 0.04 200 0.20 0.20
String#tr
0.26 14.00 0.04 1100 0.04 0.04 Fixnum#<
0.26 14.04 0.04 100 0.40 0.40
Merb::AbstractController#default_thrown_content
0.26 14.08 0.04 1100 0.04 0.04 Array#[]
... snip everything below 0.25%
0.00 15.53 0.00 1 0.00 15530.00 #toplevel
It looks like logging is the worst offender, with Logger#add and its mutex
(MonitorMixin) accounting for the top 8 slots, 4.09 out of 15.53 seconds, or
26%. In fact, it looks like Logger#add and its children, at 6.98ms per call
and called 1000 times, count for 6.98s in total.
TCPAccept is next, and Merb::Router#match is third. However this only
accounts for 2.00%
Now, I've seen figures for Merb performance typically in the 400-600
requests per second range. Are these measured with logging turned off? If
not, I think there is a strong argument for introducing a mutex-free logging
system.
(Simple idea: replace Logger#add with an append to a string buffer, which is
atomic. Then once per second empty the buffer using String#slice! which
should also be atomic, and write that to the log)
Finally, I repeated the test using merb -e production -l WARN
% cumulative self self total
time seconds seconds calls ms/call ms/call name
4.62 0.42 0.42 1000 0.42 0.51 Logger#add
3.85 0.77 0.35 100 3.50 6.00 Merb::Router#match
3.74 1.11 0.34 100 3.40 10.30 IO#close
3.19 1.40 0.29 100 2.90 79.70
Mongrel::HttpServer#process_client
3.19 1.69 0.29 100 2.90 71.40 MerbHandler#process
2.75 1.94 0.25 900 0.28 0.81 Logger#info
2.42 2.16 0.22 1600 0.14 0.86 Class#new
2.31 2.37 0.21 600 0.35 0.50
Class#read_inheritable_attribute
2.09 2.56 0.19 400 0.48 0.73 Hash#inspect
2.09 2.75 0.19 400 0.47 0.47 String#split
2.09 2.94 0.19 3742 0.05 0.11 Hash#[]
1.98 3.12 0.18 738 0.24 10.15 Array#each
1.98 3.30 0.18 100 1.80 2.00 Time#httpdate
1.65 3.45 0.15 400 0.38 1.23
Merb::AbstractController#before_filters
1.65 3.60 0.15 300 0.50 5.93 Merb::Request#params
1.65 3.75 0.15 100 1.50 1.90 Merb::Request#json_params
1.54 3.89 0.14 100 1.40 2.10
Mongrel::HttpRequest#initialize
1.54 4.03 0.14 1000 0.14 0.17 Time#now
1.43 4.16 0.13 200 0.65 1.40 Hash#to_mash
1.43 4.29 0.13 100 1.30 55.30 Merb::Dispatcher#handle
1.32 4.41 0.12 100 1.20 17.30 Merb::Controller#dispatch
1.32 4.53 0.12 700 0.17 0.24 Mash#convert_key
1.32 4.65 0.12 300 0.40 0.80 Mongrel::HeaderOut#[]=
1.21 4.76 0.11 100 1.10 3.90 Merb::Controller#build
1.10 4.86 0.10 800 0.13 1.03
Merb::Request#route_params 1.10 4.96 0.10 200 0.50 0.55
Mongrel::HttpResponse#send_header
0.99 5.05 0.09 300 0.30 1.00 Hash#each_pair
0.99 5.14 0.09 100 0.90 1.10 Merb::Request#method
0.99 5.23 0.09 55 1.64 24.73 Kernel.sleep
0.88 5.31 0.08 200 0.40 0.40 File#expand_path
0.88 5.39 0.08 400 0.20 0.20 String#%
0.88 5.47 0.08 200 0.40 0.70 Mash#initialize
0.88 5.55 0.08 200 0.40 0.55 Mash#include?
0.77 5.62 0.07 100 0.70 6.10
Merb::AbstractController#dispatch
0.77 5.69 0.07 100 0.70 4.90
Mongrel::HttpResponse#initialize
0.77 5.76 0.07 200 0.35 1.20
Mongrel::DirHandler#can_serve
0.77 5.83 0.07 1800 0.04 0.04 Hash#default
0.77 5.90 0.07 800 0.09 0.85 Merb::Request#route_match
0.77 5.97 0.07 100 0.70 1.60
Merb::Controller#set_dispatch_variables
0.66 6.03 0.06 400 0.15 0.62
Merb::AbstractController#after_filters
0.66 6.09 0.06 100 0.60 0.60 StringScanner#scan
0.66 6.15 0.06 100 0.60 0.70 Object#blank?
0.66 6.21 0.06 200 0.30 2.25 Merb::Request#query_parse
0.66 6.27 0.06 200 0.30 0.30 String#gsub
0.66 6.33 0.06 400 0.15 0.68
Merb::Controller#_session_id_key
0.66 6.39 0.06 1438 0.04 0.04 Kernel.nil?
0.66 6.45 0.06 1000 0.06 0.06 Hash#[]=
0.55 6.50 0.05 99 0.51 52.63 TCPServer#accept
0.55 6.55 0.05 200 0.25 1.40 Merb::Request#cookies
0.55 6.60 0.05 900 0.06 0.06 Array#last
0.55 6.65 0.05 100 0.50 1.20
Mongrel::HttpResponse#finished
0.55 6.70 0.05 100 0.50 5.70
Merb::SessionMixin.setup_session
0.55 6.75 0.05 76 0.66 1.18 Array#map
0.55 6.80 0.05 400 0.13 0.22 Mash#convert_value
0.55 6.85 0.05 300 0.17 0.23 StringIO#initialize
0.55 6.90 0.05 400 0.13 0.22
Mongrel::HttpResponse#write
0.55 6.95 0.05 400 0.13 0.27
Merb::Request#content_type 0.55 7.00 0.05 100 0.50 4.70
Merb::Request#controller_class
0.55 7.05 0.05 100 0.50 2.60 Object#full_const_get
0.55 7.10 0.05 200 0.25 0.25 String#to_s
0.55 7.15 0.05 100 0.50 1.00 Thread#new
0.55 7.20 0.05 100 0.50 0.50 Merb::Controller#status
... snip everything below 0.5%
0.00 9.09 0.00 1 0.00 9090.00 #toplevel
This is more interesting: even though nothing is actually logged, because of
the large number of calls to Logger#add it still accounts for 4.62%, with
another 2.75% for Logger#info and 1.54% for Time#now (the fact it has been
called 1000 times suggests that timestamps are being made for log entries
which are never written!)
Merb::Router#match is now the number two offender at 3.85%, but this is
probably still not enough by itself to warrant a rewrite.
Regards,
Brian.
_______________________________________________
Merb-devel mailing list
[email protected]
http://rubyforge.org/mailman/listinfo/merb-devel
