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.
--- lib/merb.rb.orig 2007-09-19 09:55:24.000000000 +0100
+++ lib/merb.rb 2007-09-19 09:56:37.000000000 +0100
@@ -10,7 +10,7 @@
end
require 'fileutils'
require 'merb/erubis_ext'
-require 'logger'
+require 'merb/logger'
require 'json'
require 'set'
autoload :MerbUploadHandler, 'merb/upload_handler'
@@ -67,8 +67,8 @@
MERB_VIEW_ROOT = MERB_ROOT / "app/views"
MERB_SKELETON_DIR = File.join(MERB_FRAMEWORK_ROOT,
'../app_generators/merb/templates')
logpath = $TESTING ? "#{MERB_ROOT}/merb_test.log" :
"#{MERB_ROOT}/log/merb.#{Merb::Server.config[:port]}.log"
-MERB_LOGGER = Logger.new(logpath)
-MERB_LOGGER.level = Logger.const_get(Merb::Server.config[:log_level].upcase)
rescue Logger::INFO
+MERB_LOGGER = Merb::Logger.new(logpath)
+MERB_LOGGER.level =
Merb::Logger.const_get(Merb::Server.config[:log_level].upcase) rescue
Merb::Logger::INFO
MERB_PATHS = [
"/app/models/**/*.rb",
"/app/controllers/application.rb",
@@ -82,4 +82,4 @@
if $TESTING
test_files = File.join(lib, 'test', '*.rb')
Dir[test_files].each { |file| require file }
-end
\ No newline at end of file
+end
--- lib/merb/mongrel_handler.rb.orig 2007-09-16 19:32:04.000000000 +0100
+++ lib/merb/mongrel_handler.rb 2007-09-19 10:10:39.000000000 +0100
@@ -145,8 +145,8 @@
total_request_time = Time.now - start
benchmarks[:total_request_time] = total_request_time
- MERB_LOGGER.info("Request Times: #{benchmarks.inspect}")
- MERB_LOGGER.info("Response status: #{response.status}\nComplete Request
took: #{total_request_time} seconds, #{1.0/total_request_time}
Requests/Second\n\n")
+ MERB_LOGGER.info("Request Times: #{benchmarks.inspect}\nResponse status:
#{response.status}\nComplete Request took: #{total_request_time} seconds,
#{1.0/total_request_time} Requests/Second\n\n")
+ MERB_LOGGER.flush
end
rescue Object => e
# if an exception is raised here then something is
--- lib/merb/logger.rb.orig 2007-09-19 10:14:33.000000000 +0100
+++ lib/merb/logger.rb 2007-09-19 10:06:37.000000000 +0100
@@ -0,0 +1,70 @@
+module Merb
+ # Logging is called several times for each request, so keep it short and
+ # sweet. Use << for atomic add to buffer, and slice! for atomic removal.
+
+ class Logger
+ module Severity
+ DEBUG = 0
+ INFO = 1
+ WARN = 2
+ ERROR = 3
+ FATAL = 4
+ UNKNOWN = 5
+ end
+ include Severity
+
+ attr_accessor :level
+ attr_reader :buf
+ def initialize(log)
+ @level = level
+ @buf = ""
+ if log.respond_to?(:write)
+ @log = log
+ elsif File.exist?(log)
+ @log = open(log, (File::WRONLY | File::APPEND))
+ @log.sync = true
+ else
+ @log = open(log, (File::WRONLY | File::APPEND | File::CREAT))
+ @log.sync = true
+ @log.write("# Logfile created on %s" % [Time.now.to_s])
+ end
+ end
+
+ def flush
+ return if @buf.size == 0
+ @log.write @buf.slice!(0..-1)
+ end
+
+ def close
+ flush
+ @log.close if @log.respond_to? :close
+ @log = nil
+ end
+
+ def debug(msg)
+ return if @level > DEBUG
+ msg << "\n" unless msg[-1] == ?\n
+ @buf << msg
+ end
+ def info(msg)
+ return if @level > INFO
+ msg << "\n" unless msg[-1] == ?\n
+ @buf << msg
+ end
+ def warn(msg)
+ return if @level > WARN
+ msg << "\n" unless msg[-1] == ?\n
+ @buf << msg
+ end
+ def error(msg)
+ return if @level > ERROR
+ msg << "\n" unless msg[-1] == ?\n
+ @buf << msg
+ end
+ def error(msg)
+ return if @level > FATAL
+ msg << "\n" unless msg[-1] == ?\n
+ @buf << msg
+ end
+ end
+end
_______________________________________________
Merb-devel mailing list
[email protected]
http://rubyforge.org/mailman/listinfo/merb-devel
