basecamp/marginalia — pull request #34 by jasonhl (2014-08-14 21:30:51+00:00)
Title: Optimize comment contruction to reduce CPU usage and object allocation

My lovely employer, Shopify, uses marginalia to annotate all our SQL queries. Due to it's size, that means that we are annotating millions of queries every day.

Using stackprof, I've discovered that roughly 1% of all objects and ~0.75% of the CPU used by Shopify is consumed by the ActiveSupport patch of String.blank?. The majority of these come form the marginalia code in construct_comment.

An easy way to avoid (at least) half these calls is to change the way the comment string is constructed. Rather than checking for a comma on every pass, it is just always added and the trailing one is chopped off at the end.

Here's some simplified benchmark code:

```ruby
require 'benchmark'
require 'stackprof'
require 'active_support/core_ext/object/blank'

iterations = 500000
DATA = {:controller => 'test', :request_id => '1234', :host => "db.example.com"}

class A
def name
"Marginalia HEAD"
end

def comment
ret = ''
DATA.each do |key, value|
ret << ',' if ret.present?
ret << key.to_s << ':' << value.to_s
end
ret
end
end

class B
def name
"Omitting present? check and chopping"
end

def comment
ret = ''
DATA.each do |key, value|
ret << key.to_s << ':' << value.to_s << ','
end
ret.chop!
ret
end

end

Benchmark.bmbm do |bm|
[A.new, B.new].each do |klass|
bm.report("#{klass.name}") do
iterations.times do
klass.comment
end
end

results = StackProf.run(mode: :object) do
iterations.times do
klass.comment
end
end
StackProf::Report.new(results).print_text(false, 20)
end
end
```

And the results... here's the original code's object allocation benchmark for 1 iteration:

```
==================================
Mode: object(1)
Samples: 17 (0.00% miss rate)
GC: 0 (0.00%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
16 (94.1%) 8 (47.1%) block in A#comment
8 (47.1%) 8 (47.1%) String#blank?
17 (100.0%) 1 (5.9%) A#comment
17 (100.0%) 0 (0.0%) block (2 levels) in

17 (100.0%) 0 (0.0%) block in

17 (100.0%) 0 (0.0%) block (3 levels) in

17 (100.0%) 0 (0.0%)

17 (100.0%) 0 (0.0%)

17 (100.0%) 0 (0.0%) block (4 levels) in

8 (47.1%) 0 (0.0%) Object#present?
17 (100.0%) 0 (0.0%) Benchmark#bmbm
```

Here's the code in this PR:
```
==================================
Mode: object(1)
Samples: 10 (0.00% miss rate)
GC: 0 (0.00%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
9 (90.0%) 9 (90.0%) block in B#comment
10 (100.0%) 1 (10.0%) B#comment
10 (100.0%) 0 (0.0%) block (3 levels) in

10 (100.0%) 0 (0.0%) block (2 levels) in

10 (100.0%) 0 (0.0%) block (4 levels) in

10 (100.0%) 0 (0.0%) Benchmark#bmbm
10 (100.0%) 0 (0.0%)

10 (100.0%) 0 (0.0%)

10 (100.0%) 0 (0.0%) block in

```

Here's the benchmark for 500,000 iterations on my mac book:
```
user system total real
Marginalia HEAD 1.860000 0.000000 1.860000 ( 1.865846)
Omitting present? check and chopping 1.010000 0.000000 1.010000 ( 1.011886)
```

So, nearly twice as fast and ~40% less objects. This won't make a difference for most applications, but it will make a difference at the scale Shopify operates.

cc: @arthurnn, @camilo