Super Simple Ruby Performance Tip
This tip is so simple it can be expressed with two characters, {}, curly braces. I've encountered this issue twice now. Once with some code in a project I work on as part of my day job, and once in a map reduce project I was evaluating.
As we all know the Ruby stdlib Logger class defines a bunch of useful logging methods (debug, info, warn, etc ) which take a string argument as the message to log. We can control which level of message is written to the log file quite easily, so that we only see the messages we care about appear in the log. This should be old news to any Rails or Ruby developer.
These Logger methods also take a block argument. When a block is given, it's return value is used as the message for the log file.
For instance:
<a href="http://logger.info">logger.info</a> "some message"
<a href="http://logger.info">logger.info</a> { "some message" }
They look similar but they do have one major difference tucked away in the source that is not made obvious in the rdoc. When using the block form, the block is evaluated after the level check is made. This is an important difference.
Lets have a look at some sample programs to get a feel for what I am talking about.
Benchmark.bmbm do |x|
x.report("string form") {
100_000.times do
logger.debug "a simple string message"
end
}
x.report("block form") {
100_000.times do
logger.debug { "a simple string message" }
end
}
end
# Rehearsal -----------------------------------------------
# string form 0.140000 0.000000 0.140000 ( 0.146751)
# block form 0.330000 0.010000 0.340000 ( 0.336446)
# -------------------------------------- total: 0.480000sec
#
# user system total real
# string form 0.140000 0.000000 0.140000 ( 0.144761)
# block form 0.320000 0.000000 0.320000 ( 0.326912)
At first glance it looks like my point is invalid. Simple strings flat out beat the block form. But if you take a moment to think about what is actually happening then this makes sense. Ruby just needs to construct a string something that it can optimize, instead of bundling up all the necessary context data in a block.
But most of the time when you are logging you need to add some data to that message.
array = []
1.upto(10) {|i| array << i}
Benchmark.bmbm do |x|
x.report("string form") {
100_000.times do
logger.debug "a message with #{array.inspect}"
end
}
x.report("block form") {
100_000.times do
logger.debug { "a message with #{array.inspect}" }
end
}
end
# Rehearsal -----------------------------------------------
# string form 0.910000 0.000000 0.910000 ( 0.914628)
# block form 0.320000 0.000000 0.320000 ( 0.322889)
# -------------------------------------- total: 1.230000sec
#
# user system total real
# string form 0.900000 0.000000 0.900000 ( 0.911639)
# block form 0.330000 0.000000 0.330000 ( 0.329468)
Here we're just inspecting a 10 item array, but already we can see that the block version hasn't budged in terms of execution time, but the string version has crept up a little. Now lets take a look at some more extreme examples.
array = []
1.upto(1_000) {|i| array << i}
Benchmark.bmbm do |x|
x.report("string form") {
100_000.times do
logger.debug "a message with #{array.inspect}"
end
}
x.report("block form") {
100_000.times do
logger.debug { "a message with #{array.inspect}" }
end
}
end
# Rehearsal -----------------------------------------------
# string form 65.790000 0.260000 66.050000 ( 68.107083)
# block form 0.330000 0.000000 0.330000 ( 0.338018)
# ------------------------------------- total: 66.380000sec
#
# user system total real
# string form 65.480000 0.250000 65.730000 ( 68.099213)
# block form 0.330000 0.000000 0.330000 ( 0.350882)
We're now taking over 1 minute to loop over all those debug messages. The block version is almost 150 times quicker!
One more example just to drive my message home. This example is what drove me to write this post. I encountered some logging just like this in a map/reduce library. The library was attempting to log, albeit at the debug level, the entire entry data set for the map process. Even though I was running my evaluation script at the ERROR log level, it looked like the master process had locked up in a busy loop, but really the process was just trying to construct a string object that was going to be discarded in 3 lines anyways.
array = []
1.upto(1_000_000) {|i| array << i}
Benchmark.bmbm do |x|
x.report("string form") {
100.times do
logger.debug "a message with #{array.inspect}"
end
}
x.report("block form") {
100.times do
logger.debug { "a message with #{array.inspect}" }
end
}
end
# Rehearsal -----------------------------------------------
# string form 94.360000 1.990000 96.350000 ( 97.137403)
# block form 0.000000 0.000000 0.000000 ( 0.000299)
# ------------------------------------- total: 96.350000sec
#
# user system total real
# string form 94.370000 2.080000 96.450000 ( 97.750037)
# block form 0.000000 0.000000 0.000000 ( 0.000245)
I got impatient waiting for 100_000 iterations of this benchmark and dropped it to just 100.
So what's the moral of the story. You need to be aware of what you are logging. Keep in mind the amount of effort that is being spent in order to construct that lovely log message. I'll leave you with another sample program that hopefully showcases some other common logging tasks.
array = []
1.upto(10) {|i| array << i}
attributes = {
:id => 1,
:title => "Super Simple Ruby Performance Tip",
:published_at => Date.today,
:tags => ["ruby", "performance", "tips"],
:categories => ["Ruby"]
}
Benchmark.bmbm do |x|
x.report("string form (array.first)") {
100_000.times do
logger.debug "a message with #{array.first}"
end
}
x.report("string form (array.inspect)") {
100_000.times do
logger.debug "a message with #{array.inspect}"
end
}
x.report("string form (attributes.inspect)") {
100_000.times do
logger.debug "a message with #{attributes.inspect}"
end
}
x.report("block form (array.first)") {
100_000.times do
logger.debug { "a message with #{array.first}" }
end
}
x.report("block form (array.inspect)") {
100_000.times do
logger.debug { "a message with #{array.inspect}" }
end
}
x.report("block form (attributes.inspect)") {
100_000.times do
logger.debug { "a message with #{attributes.inspect}" }
end
}
end
# Rehearsal --------------------------------------------------------------------
# string form (array.first) 0.230000 0.000000 0.230000 ( 0.239445)
# string form (array.inspect) 0.900000 0.010000 0.910000 ( 0.918498)
# string form (attributes.inspect) 2.050000 0.000000 2.050000 ( 2.056928)
# block form (array.first) 0.320000 0.010000 0.330000 ( 0.330422)
# block form (array.inspect) 0.350000 0.000000 0.350000 ( 0.347880)
# block form (attributes.inspect) 0.320000 0.000000 0.320000 ( 0.326636)
# ----------------------------------------------------------- total: 4.190000sec
#
# user system total real
# string form (array.first) 0.240000 0.000000 0.240000 ( 0.237537)
# string form (array.inspect) 0.900000 0.010000 0.910000 ( 0.907226)
# string form (attributes.inspect) 2.040000 0.000000 2.040000 ( 2.063976)
# block form (array.first) 0.320000 0.000000 0.320000 ( 0.332216)
# block form (array.inspect) 0.330000 0.010000 0.340000 ( 0.330169)
# block form (attributes.inspect) 0.330000 0.000000 0.330000 ( 0.328436)
