Commit a6e8ff21 authored by Robert Speicher's avatar Robert Speicher

Merge branch 'track-total-method-call-time' into 'master'

Track method call times/counts as a single metric

This changes method call tracking so only a single metric is emitted regardless of the number of calls. This allows us to more accurately measure the total execution time of a method as well as the number of times a method is called. See 851e3ff7578973c2206628424eac3b951a3c656d for more details.

Method call tracking tracked calls individually meaning the end statistics may not always be accurate enough to get a good understanding of where time is spent.

See merge request !4754
parents 4d916160 be3b8784
......@@ -36,6 +36,7 @@ v 8.9.0 (unreleased)
- Added shortcut 'y' for copying a files content hash URL #14470
- Fix groups API to list only user's accessible projects
- Fix horizontal scrollbar for long commit message.
- GitLab Performance Monitoring now tracks the total method execution time and call count per method
- Add Environments and Deployments
- Redesign account and email confirmation emails
- Don't fail builds for projects that are deleted
......
......@@ -94,23 +94,8 @@ Visibility: public
Number of lines: 21
def #{name}(#{args_signature})
trans = Gitlab::Metrics::Instrumentation.transaction
if trans
start = Time.now
cpu_start = Gitlab::Metrics::System.cpu_time
retval = super
duration = (Time.now - start) * 1000.0
if duration >= Gitlab::Metrics.method_call_threshold
cpu_duration = Gitlab::Metrics::System.cpu_time - cpu_start
trans.add_metric(Gitlab::Metrics::Instrumentation::SERIES,
{ duration: duration, cpu_duration: cpu_duration },
method: #{label.inspect})
end
retval
if trans = Gitlab::Metrics::Instrumentation.transaction
trans.measure_method(#{label.inspect}) { super }
else
super
end
......
......@@ -148,23 +148,8 @@ module Gitlab
proxy_module.class_eval <<-EOF, __FILE__, __LINE__ + 1
def #{name}(#{args_signature})
trans = Gitlab::Metrics::Instrumentation.transaction
if trans
start = Time.now
cpu_start = Gitlab::Metrics::System.cpu_time
retval = super
duration = (Time.now - start) * 1000.0
if duration >= Gitlab::Metrics.method_call_threshold
cpu_duration = Gitlab::Metrics::System.cpu_time - cpu_start
trans.add_metric(Gitlab::Metrics::Instrumentation::SERIES,
{ duration: duration, cpu_duration: cpu_duration },
method: #{label.inspect})
end
retval
if trans = Gitlab::Metrics::Instrumentation.transaction
trans.measure_method(#{label.inspect}) { super }
else
super
end
......
module Gitlab
module Metrics
# Class for tracking timing information about method calls
class MethodCall
attr_reader :real_time, :cpu_time, :call_count
# name - The full name of the method (including namespace) such as
# `User#sign_in`.
#
# series - The series to use for storing the data.
def initialize(name, series)
@name = name
@series = series
@real_time = 0.0
@cpu_time = 0.0
@call_count = 0
end
# Measures the real and CPU execution time of the supplied block.
def measure
start_real = Time.now
start_cpu = System.cpu_time
retval = yield
@real_time += (Time.now - start_real) * 1000.0
@cpu_time += System.cpu_time.to_f - start_cpu
@call_count += 1
retval
end
# Returns a Metric instance of the current method call.
def to_metric
Metric.new(
@series,
{
duration: real_time,
cpu_duration: cpu_time,
call_count: call_count
},
method: @name
)
end
# Returns true if the total runtime of this method exceeds the method call
# threshold.
def above_threshold?
real_time >= Metrics.method_call_threshold
end
end
end
end
......@@ -4,7 +4,7 @@ module Gitlab
class Transaction
THREAD_KEY = :_gitlab_metrics_transaction
attr_reader :tags, :values
attr_reader :tags, :values, :methods
attr_accessor :action
......@@ -16,6 +16,7 @@ module Gitlab
# plus method name.
def initialize(action = nil)
@metrics = []
@methods = {}
@started_at = nil
@finished_at = nil
......@@ -51,9 +52,23 @@ module Gitlab
end
def add_metric(series, values, tags = {})
prefix = sidekiq? ? 'sidekiq_' : 'rails_'
@metrics << Metric.new("#{series_prefix}#{series}", values, tags)
end
# Measures the time it takes to execute a method.
#
# Multiple calls to the same method add up to the total runtime of the
# method.
#
# name - The full name of the method to measure (e.g. `User#sign_in`).
def measure_method(name, &block)
unless @methods[name]
series = "#{series_prefix}#{Instrumentation::SERIES}"
@metrics << Metric.new("#{prefix}#{series}", values, tags)
@methods[name] = MethodCall.new(name, series)
end
@methods[name].measure(&block)
end
def increment(name, value)
......@@ -84,7 +99,13 @@ module Gitlab
end
def submit
metrics = @metrics.map do |metric|
submit = @metrics.dup
@methods.each do |name, method|
submit << method.to_metric if method.above_threshold?
end
submit_hashes = submit.map do |metric|
hash = metric.to_hash
hash[:tags][:action] ||= @action if @action
......@@ -92,12 +113,16 @@ module Gitlab
hash
end
Metrics.submit_metrics(metrics)
Metrics.submit_metrics(submit_hashes)
end
def sidekiq?
Sidekiq.server?
end
def series_prefix
sidekiq? ? 'sidekiq_' : 'rails_'
end
end
end
end
......@@ -78,9 +78,8 @@ describe Gitlab::Metrics::Instrumentation do
allow(described_class).to receive(:transaction).
and_return(transaction)
expect(transaction).to receive(:add_metric).
with(described_class::SERIES, hash_including(:duration, :cpu_duration),
method: 'Dummy.foo')
expect(transaction).to receive(:measure_method).
with('Dummy.foo')
@dummy.foo
end
......@@ -158,9 +157,8 @@ describe Gitlab::Metrics::Instrumentation do
allow(described_class).to receive(:transaction).
and_return(transaction)
expect(transaction).to receive(:add_metric).
with(described_class::SERIES, hash_including(:duration, :cpu_duration),
method: 'Dummy#bar')
expect(transaction).to receive(:measure_method).
with('Dummy#bar')
@dummy.new.bar
end
......
require 'spec_helper'
describe Gitlab::Metrics::MethodCall do
let(:method_call) { described_class.new('Foo#bar', 'foo') }
describe '#measure' do
it 'measures the performance of the supplied block' do
method_call.measure { 'foo' }
expect(method_call.real_time).to be_a_kind_of(Numeric)
expect(method_call.cpu_time).to be_a_kind_of(Numeric)
expect(method_call.call_count).to eq(1)
end
end
describe '#to_metric' do
it 'returns a Metric instance' do
method_call.measure { 'foo' }
metric = method_call.to_metric
expect(metric).to be_an_instance_of(Gitlab::Metrics::Metric)
expect(metric.series).to eq('foo')
expect(metric.values[:duration]).to be_a_kind_of(Numeric)
expect(metric.values[:cpu_duration]).to be_a_kind_of(Numeric)
expect(metric.values[:call_count]).to an_instance_of(Fixnum)
expect(metric.tags).to eq({ method: 'Foo#bar' })
end
end
describe '#above_threshold?' do
it 'returns false when the total call time is not above the threshold' do
expect(method_call.above_threshold?).to eq(false)
end
it 'returns true when the total call time is above the threshold' do
expect(method_call).to receive(:real_time).and_return(9000)
expect(method_call.above_threshold?).to eq(true)
end
end
describe '#call_count' do
context 'without any method calls' do
it 'returns 0' do
expect(method_call.call_count).to eq(0)
end
end
context 'with method calls' do
it 'returns the number of method calls' do
method_call.measure { 'foo' }
expect(method_call.call_count).to eq(1)
end
end
end
describe '#cpu_time' do
context 'without timings' do
it 'returns 0.0' do
expect(method_call.cpu_time).to eq(0.0)
end
end
context 'with timings' do
it 'returns the total CPU time' do
method_call.measure { 'foo' }
expect(method_call.cpu_time >= 0.0).to be(true)
end
end
end
describe '#real_time' do
context 'without timings' do
it 'returns 0.0' do
expect(method_call.real_time).to eq(0.0)
end
end
context 'with timings' do
it 'returns the total real time' do
method_call.measure { 'foo' }
expect(method_call.real_time >= 0.0).to be(true)
end
end
end
end
......@@ -46,6 +46,22 @@ describe Gitlab::Metrics::Transaction do
end
end
describe '#measure_method' do
it 'adds a new method if it does not exist already' do
transaction.measure_method('Foo#bar') { 'foo' }
expect(transaction.methods['Foo#bar']).
to be_an_instance_of(Gitlab::Metrics::MethodCall)
end
it 'adds timings to an existing method call' do
transaction.measure_method('Foo#bar') { 'foo' }
transaction.measure_method('Foo#bar') { 'foo' }
expect(transaction.methods['Foo#bar'].call_count).to eq(2)
end
end
describe '#increment' do
it 'increments a counter' do
transaction.increment(:time, 1)
......
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