Commit 1b077d2d authored by Yorick Peterse's avatar Yorick Peterse

Use custom code for instrumenting method calls

The use of ActiveSupport would slow down instrumented method calls by
about 180x due to:

1. ActiveSupport itself not being the fastest thing on the planet
2. caller_locations() having quite some overhead

The use of caller_locations() has been removed because it's not _that_
useful since we already know the full namespace of receivers and the
names of the called methods.

The use of ActiveSupport has been replaced with some custom code that's
generated using eval() (which can be quite a bit faster than using
define_method).

This new setup results in instrumented methods only being about 35-40x
slower (compared to non instrumented methods).
parent b66a16c8
...@@ -7,7 +7,6 @@ if Gitlab::Metrics.enabled? ...@@ -7,7 +7,6 @@ if Gitlab::Metrics.enabled?
# ActiveSupport. # ActiveSupport.
require 'gitlab/metrics/subscribers/action_view' require 'gitlab/metrics/subscribers/action_view'
require 'gitlab/metrics/subscribers/active_record' require 'gitlab/metrics/subscribers/active_record'
require 'gitlab/metrics/subscribers/method_call'
Gitlab::Application.configure do |config| Gitlab::Application.configure do |config|
config.middleware.use(Gitlab::Metrics::RackMiddleware) config.middleware.use(Gitlab::Metrics::RackMiddleware)
......
...@@ -9,6 +9,8 @@ module Gitlab ...@@ -9,6 +9,8 @@ module Gitlab
# #
# Gitlab::Metrics::Instrumentation.instrument_method(User, :by_login) # Gitlab::Metrics::Instrumentation.instrument_method(User, :by_login)
module Instrumentation module Instrumentation
SERIES = 'method_calls'
# Instruments a class method. # Instruments a class method.
# #
# mod - The module to instrument as a Module/Class. # mod - The module to instrument as a Module/Class.
...@@ -31,19 +33,42 @@ module Gitlab ...@@ -31,19 +33,42 @@ module Gitlab
alias_name = "_original_#{name}" alias_name = "_original_#{name}"
target = type == :instance ? mod : mod.singleton_class target = type == :instance ? mod : mod.singleton_class
if type == :instance
target = mod
label = "#{mod.name}##{name}"
else
target = mod.singleton_class
label = "#{mod.name}.#{name}"
end
target.class_eval <<-EOF, __FILE__, __LINE__ + 1 target.class_eval <<-EOF, __FILE__, __LINE__ + 1
alias_method :#{alias_name}, :#{name} alias_method :#{alias_name}, :#{name}
def #{name}(*args, &block) def #{name}(*args, &block)
ActiveSupport::Notifications trans = Gitlab::Metrics::Instrumentation.transaction
.instrument("#{type}_method.method_call",
module: #{mod.name.inspect}, if trans
name: #{name.inspect}) do start = Time.now
#{alias_name}(*args, &block) retval = #{alias_name}(*args, &block)
end duration = (Time.now - start) * 1000.0
trans.add_metric(Gitlab::Metrics::Instrumentation::SERIES,
{ duration: duration },
method: #{label.inspect})
retval
else
#{alias_name}(*args, &block)
end
end end
EOF EOF
end end
# Small layer of indirection to make it easier to stub out the current
# transaction.
def self.transaction
Transaction.current
end
end end
end end
end end
module Gitlab
module Metrics
module Subscribers
# Class for tracking method call timings.
class MethodCall < ActiveSupport::Subscriber
attach_to :method_call
SERIES = 'method_calls'
def instance_method(event)
return unless current_transaction
label = "#{event.payload[:module]}##{event.payload[:name]}"
add_metric(label, event.duration)
end
def class_method(event)
return unless current_transaction
label = "#{event.payload[:module]}.#{event.payload[:name]}"
add_metric(label, event.duration)
end
private
def add_metric(label, duration)
file, line = Metrics.last_relative_application_frame
values = { duration: duration, file: file, line: line }
current_transaction.add_metric(SERIES, values, method: label)
end
def current_transaction
Transaction.current
end
end
end
end
end
require 'spec_helper' require 'spec_helper'
describe Gitlab::Metrics::Instrumentation do describe Gitlab::Metrics::Instrumentation do
let(:transaction) { Gitlab::Metrics::Transaction.new }
before do before do
@dummy = Class.new do @dummy = Class.new do
def self.foo(text = 'foo') def self.foo(text = 'foo')
...@@ -31,9 +33,13 @@ describe Gitlab::Metrics::Instrumentation do ...@@ -31,9 +33,13 @@ describe Gitlab::Metrics::Instrumentation do
expect(@dummy.foo).to eq('foo') expect(@dummy.foo).to eq('foo')
end end
it 'fires an ActiveSupport notification upon calling the method' do it 'tracks the call duration upon calling the method' do
expect(ActiveSupport::Notifications).to receive(:instrument). allow(Gitlab::Metrics::Instrumentation).to receive(:transaction).
with('class_method.method_call', module: 'Dummy', name: :foo) and_return(transaction)
expect(transaction).to receive(:add_metric).
with(described_class::SERIES, an_instance_of(Hash),
method: 'Dummy.foo')
@dummy.foo @dummy.foo
end end
...@@ -69,9 +75,13 @@ describe Gitlab::Metrics::Instrumentation do ...@@ -69,9 +75,13 @@ describe Gitlab::Metrics::Instrumentation do
expect(@dummy.new.bar).to eq('bar') expect(@dummy.new.bar).to eq('bar')
end end
it 'fires an ActiveSupport notification upon calling the method' do it 'tracks the call duration upon calling the method' do
expect(ActiveSupport::Notifications).to receive(:instrument). allow(Gitlab::Metrics::Instrumentation).to receive(:transaction).
with('instance_method.method_call', module: 'Dummy', name: :bar) and_return(transaction)
expect(transaction).to receive(:add_metric).
with(described_class::SERIES, an_instance_of(Hash),
method: 'Dummy#bar')
@dummy.new.bar @dummy.new.bar
end end
......
require 'spec_helper'
describe Gitlab::Metrics::Subscribers::MethodCall do
let(:transaction) { Gitlab::Metrics::Transaction.new }
let(:subscriber) { described_class.new }
let(:event) do
double(:event, duration: 0.2, payload: { module: 'Foo', name: :foo })
end
before do
allow(subscriber).to receive(:current_transaction).and_return(transaction)
allow(Gitlab::Metrics).to receive(:last_relative_application_frame).
and_return(['app/models/foo.rb', 4])
end
describe '#instance_method' do
it 'tracks the execution of an instance method' do
values = { duration: 0.2, file: 'app/models/foo.rb', line: 4 }
expect(transaction).to receive(:add_metric).
with(described_class::SERIES, values, method: 'Foo#foo')
subscriber.instance_method(event)
end
end
describe '#class_method' do
it 'tracks the execution of a class method' do
values = { duration: 0.2, file: 'app/models/foo.rb', line: 4 }
expect(transaction).to receive(:add_metric).
with(described_class::SERIES, values, method: 'Foo.foo')
subscriber.class_method(event)
end
end
end
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment