Ruby: Proxy pattern, reducing method calls

Question

How do I proxy the ruby logger and keep performance?

So, we have an requirement at work, quite reasonable. When a program is sent the signal HUP the log is flushed and restarted.

class LocalObject

  attr_accessor :logger

  def initialize context
    # one less method call! Yea! performance++
    @logger = context.logger
  end

  def something
    @logger.info "Hello world"
  end

end

The problem, is that if context.logger is reset, then @logger still points to the old one.

So, I thought I would proxy logger:

class LoggerProxy
  attr_accessor :logger

  def debug *args
    @logger.send :debug, args
  end

  def info *args
    @logger.send :info, args
  end
end

context.logger = LoggerProxy.new
context.logger.logger = Logger.new 'my_file.log'

Signal.trap('HUP') { 
  context.logger.logger = Logger.new 'my_file.log'
}
...
@logger = context.logger
@logger.info "Hello world"

This works fine, except I've traded one method call for 2 method calls (1 accessor; which returns the logger). I still have to call LoggerProxy.:debug, :info, ..., which in turn calls the original logger! Ergo, 2 methods calls, where there was one.

I don't want to monkey with Logger class, or overload it, because I want to use other loggers in the future, syslog, roll my own, or some such.

Is there a way reduce the number of method calls for performance?

-daniel

Update: in response to a question about performance, here is the sample test.

require 'logger'
require 'benchmark';

class MyLogger

  attr_accessor :logger

  def info msg
    @logger.info msg
  end

end

myLogger = Logger.new '/dev/null' # dev null to avoid IO issues
myLoggerProxy = MyLogger.new
myLoggerProxy.logger = myLogger

n = 100000
Benchmark.bm do | benchmarker |
  # plain logger
  benchmarker.report { n.times { myLogger.info 'opps' } }

  # via accessor
  benchmarker.report { n.times { myLoggerProxy.logger.info 'opps' } }

  # via proxy
  benchmarker.report { n.times { myLoggerProxy.info 'opps' } }
end


      user     system      total        real
  1.580000   0.150000   1.730000 (  1.734956)
  1.600000   0.150000   1.750000 (  1.747969)
  1.610000   0.160000   1.770000 (  1.767886)

Ohmygoodness. Unless I am much mistaken, this has nothing to do with blogging, so I removed the "blogger" tag. — Jonathan Sterling, Dec 01 '10 at 00:13
@Jonathan: If you type in "logger" into the tag list and press tab, you get "blogger" as it's higher up in the list (98 versus 84 uses). — Andrew Grimm, Dec 01 '10 at 05:52
I don't see you saying that you have measured the performance and found it lacking. Out of curiosity: how much slower is the extra method call, and what are you doing that is sensitive to this small slow down? — Phrogz, Dec 07 '10 at 00:07
I'm writing web applications, I like leaving "lots" of logging in, but it costs. A minor cost, but one that we pay all the time. — Daniel, Dec 09 '10 at 23:11
I've added the code with timing tests. You can see the additional cost. Since logging is done "everywhere" I am a bit sensitive to the extra cost. — Daniel, Dec 09 '10 at 23:14

score 4 · Answer 1 · answered Dec 04 '10 at 18:00

4

Instead of resetting the logger itself, flush and reopen its output:

logfile = File.open 'my_file.log', 'w+'
context.logger = Logger.new logfile

Signal.trap('HUP') {
  logfile.flush
  logfile.reopen 'my_file.log', 'w+'
}

answered Dec 04 '10 at 18:00

John

29,546
11
78
79

The problem is in the future, I want to add something, that may not have a reopen capability. Say, syslog... – Daniel Dec 06 '10 at 20:08

levinalex · Accepted Answer · 2010-12-10T01:29:00.640

First: your question smells like you're optimizing prematurely. You should only optimize if you know your code is too slow. (And your benchmark show only a tiny difference)

That said, you could make the Context notify every proxy if logger is ever updated:

class ProxyLogger
  attr_accessor :logger

  def initialize(context)
    context.register(self)
  end
end

class Context
  attr_accessor :logger

  def initialize
    @proxies = []
  end

  def logger=(val)
    @logger = val
    @proxies.each { |p| p.logger = val }
  end

  def register(proxy)
    @proxies << proxy
  end
end

but again, this does not really seem worth the additional complexity.

(related: this is a very nice presentation showing @tenderlove optimizing the ARel gem)

+1 for the premature optimization remark. And IMO, if you find yourself making your code convoluted in order to eliminate a method call, perhaps you should consider language other than Ruby. — Mladen Jablanović, Dec 10 '10 at 16:04

Ruby: Proxy pattern, reducing method calls

2 Answers2