Skip to content

Instantly share code, notes, and snippets.

@kbrock

kbrock/0README.md

Created December 11, 2017 17:03
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save kbrock/e3968adbcbaaa6d490e2b6c13b40ec19 to your computer and use it in GitHub Desktop.
Save kbrock/e3968adbcbaaa6d490e2b6c13b40ec19 to your computer and use it in GitHub Desktop.
Download ZIP
Comparing
Raw
0README.md

Looking at the difference between using ActiveSupport::Notification, and rolling our own metrics counters.

When logging, Notifications are 66% slower than manually adding the metrics code. The metrics code is actually 50% slower when not logging the results (no subscriber). Having no subscriber does speed up performance for all the cases.

The difference for timing for payload is probably due to allocations. Having a fixed payload ended up being equivalent to the no payload case. This is a reminder for us to pay attention to what we pass in the payload.

Adding dual GC.stat calls slow it down enough that I moved into a separate graph.

#         dc  pay x-t: 10,832,743.0 i/s - 5x faster than "x pay x"
#
#         x   pay x  :  2,370,325.2 i/s - these 2 are the same
#        gcx  pay x  :  2,177,583.4 i/s - these 2 are the same
#         x   pay s  :  1,236,371.8 i/s - 1.92x  slower - these 3 are the same
#         x   pay ss :  1,201,322.4 i/s - 1.97x  slower - these 3 are the same
#         dc  pay x  :  1,177,721.8 i/s - 2.01x  slower - these 3 are the same
#         x   pay sss:  1,166,839.7 i/s - 2.03x  slower (is slower - close, but slower)
#         dc  pay sss:    730,067.5 i/s - 3.25x  slower
#         sub pay fff:    367,253.5 i/s - 6.45x  slower
#         sub pay x  :    362,046.8 i/s - 6.55x  slower
#        dual pay x  :    326,984.6 i/s - 7.25x  slower
#         sub pay ss :    320,510.1 i/s - 7.40x  slower
#         sub pay sss:    314,632.6 i/s - 7.53x  slower
#         sub pay s  :    308,644.6 i/s - 7.68x  slower
#        dual pay s  :    299,379.9 i/s - 7.92x  slower
#         bench pay x:    165,345.3 i/s - 14.34x  slower

---

#         gcx pay x  : 2,301,010.6 i/s
#            just gc :   187,783.8 i/s
#
#       sub g;pay ss :   110,868.1 i/s - these 2 are the same
#         sub pay gs :   109,375.4 i/s - these 2 are the same
#         gc  pay x  :    67,997.3 i/s - 1.63x  slower - these 2 are the same
#         sub pay gg :    65,832.8 i/s - 1.68x  slower - these 2 are the same
Raw
gcstat_bench.rb
require 'benchmark/ips'
require 'active_support'
require "#{ENV["HOME"]}/src/manageiq-gems-pending/lib/gems/pending/util/extensions/miq-benchmark.rb"
class VoidSubscriber
def call(name, started, finished, unique_id, payload)
end
end
class DualSubscriber
def start(name, id, payload)
(Thread.current[:_note] ||= []).push(Time.now)
end
def finish(name, id, payload)
call(name, (Thread.current[:_note]).pop, Time.now, id, payload)
end
def call(name, started, finished, unique_id, payload)
end
end
class GcSubscriber
def start(name, id, payload)
(Thread.current[:_gcnote] ||= []).push(Time.now).push(GC.stat)
end
def finish(name, id, payload)
timestack = Thread.current[:_gcnote]
gc = timestack.pop
started = timestack.pop
call(name, started, gc, Time.now, GC.stat, id, payload)
end
def call(name, started, started_gc, finished, finished_gc, unique_id, payload)
end
end
#ActiveSupport::Notifications.subscribe('call.x') # call.x: call - no subscriber
ActiveSupport::Notifications.subscribe('call.s', VoidSubscriber.new) # call.s: call - subscriber
ActiveSupport::Notifications.subscribe('dual.s', DualSubscriber.new) # dual.s: dual method subscriber call
#ActiveSupport::Notifications.subscribe('gc.x', GcSubscriber.new) # gc.x: using GC.stat in subscriber no subscriber
ActiveSupport::Notifications.subscribe('gc.s', GcSubscriber.new) # gc.s: using GC.stat in subscriber
# dc pay x-t: 10,832,743.0 i/s - 5x faster than "x pay x"
#
# x pay x : 2,370,325.2 i/s - these 2 are the same
# gcx pay x : 2,177,583.4 i/s - these 2 are the same
# x pay s : 1,236,371.8 i/s - 1.92x slower - these 3 are the same
# x pay ss : 1,201,322.4 i/s - 1.97x slower - these 3 are the same
# dc pay x : 1,177,721.8 i/s - 2.01x slower - these 3 are the same
# x pay sss: 1,166,839.7 i/s - 2.03x slower (is slower - close, but slower)
# dc pay sss: 730,067.5 i/s - 3.25x slower
# sub pay fff: 367,253.5 i/s - 6.45x slower
# sub pay x : 362,046.8 i/s - 6.55x slower
# dual pay x : 326,984.6 i/s - 7.25x slower
# sub pay ss : 320,510.1 i/s - 7.40x slower
# sub pay sss: 314,632.6 i/s - 7.53x slower
# sub pay s : 308,644.6 i/s - 7.68x slower
# dual pay s : 299,379.9 i/s - 7.92x slower
# bench pay x: 165,345.3 i/s - 14.34x slower
ONE = VoidSubscriber.new
ASN = ActiveSupport::Notifications # no perf impact
P3Frozen = {pay: :one, pay2: :two, pay3: :thr}.freeze
none = Benchmark.ips(:time => 2, :warmup => 1) do |x|
# x.report("dc pay x-t") { |t| t.times { x = 5 ; ONE.call('call.x', nil, nil, nil, nil) } }
x.report("dc pay x ") { |t| t.times { b = Time.now ; x = 5 ; a = Time.now ; ONE.call('call.x', b, a, "55", nil ) } }
x.report("dc pay sss") { |t| t.times { b = Time.now ; x = 5 ; a = Time.now ; ONE.call('call.s', b, a, "55", pay: :one, pay2: :two, pay3: :thr ) } }
x.report("x pay x ") { |t| t.times { ASN.instrument('call.x') { x = 5 } } }
x.report("x pay s ") { |t| t.times { ASN.instrument('call.x', pay: :one) { x = 5 } } }
x.report("x pay ss ") { |t| t.times { ASN.instrument('call.x', pay: :one, pay2: :two) { x = 5 } } }
x.report("x pay sss") { |t| t.times { ASN.instrument('call.x', pay: :one, pay2: :two, pay3: :thr) { x = 5 } } }
x.report("sub pay x ") { |t| t.times { ASN.instrument('call.s') { x = 5 } } }
x.report("sub pay s ") { |t| t.times { ASN.instrument('call.s', pay: :one) { x = 5 } } }
x.report("sub pay ss ") { |t| t.times { ASN.instrument('call.s', pay: :one, pay2: :two) { x = 5 } } }
x.report("sub pay sss") { |t| t.times { ASN.instrument('call.s', pay: :one, pay2: :two, pay3: :thr) { x = 5 } } }
x.report("sub pay fff") { |t| t.times { ASN.instrument('call.s', P3Frozen) { x = 5 } } }
x.report("bench pay x") { |t| t.times { Benchmark.realtime_block(:db_find_prev_perfs) { ONE.call('call.x', nil, nil, nil, nil) } }}
x.report("sub pay x ") { |t| t.times { ASN.instrument('call.s') { x = 5 } } }
x.report("sub pay s ") { |t| t.times { ASN.instrument('call.s', pay: :one) { x = 5 } } }
x.report("gcx pay x "){ |t| t.times { ASN.instrument('gc.x') { x = 5 } } } # was skewing gc benchmarks
x.report("dual pay x "){ |t| t.times { ASN.instrument('dual.s') { x = 5 } } }
x.report("dual pay s "){ |t| t.times { ASN.instrument('dual.s', pay: :one) { x = 5 } } }
end
# gcx pay x : 2,301,010.6 i/s
# just gc : 187,783.8 i/s
#
# sub g;pay ss : 110,868.1 i/s - these 2 are the same
# sub pay gs : 109,375.4 i/s - these 2 are the same
# gc pay x : 67,997.3 i/s - 1.63x slower - these 2 are the same
# sub pay gg : 65,832.8 i/s - 1.68x slower - these 2 are the same
cgs = Benchmark.ips(:time => 2, :warmup => 1) do |x|
# x.report("just gc") { |t| t.times { GC.stat } }
x.report("sub g;pay ss ") { |t| t.times { GC.stat; ASN.instrument('call.s', pay: :one, pay2: :two) { x = 5 } } }
x.report("sub pay gs ") { |t| t.times { ASN.instrument('call.s', pay: GC.stat, pay2: :two) { x = 5 } } }
x.report("sub pay gg ") { |t| t.times { ASN.instrument('call.s', pay: GC.stat, pay2: GC.stat) { x = 5 } } }
# x.report("gcx pay x ") { |t| t.times { ASN.instrument('gc.x') { x = 5 } } }
x.report("gc pay x ") { |t| t.times { ASN.instrument('gc.s') { x = 5 } } }
end
puts "subscribers", "------"
puts none.run_comparison
puts "gc", "------"
puts cgs.run_comparison
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment