Commit 16926a67 authored by Yorick Peterse's avatar Yorick Peterse

Store block timings as transaction values

This makes it easier to query, simplifies the code, and makes it
possible to figure out what transaction the data belongs to (simply
because it's now stored _in_ the transaction).

This new setup keeps track of both the real/wall time _and_ CPU time
spent in a block, both measured using milliseconds (to keep all units
the same).
parent 85279c07
...@@ -2,36 +2,34 @@ ...@@ -2,36 +2,34 @@
GitLab Performance Monitoring allows instrumenting of custom blocks of Ruby GitLab Performance Monitoring allows instrumenting of custom blocks of Ruby
code. This can be used to measure the time spent in a specific part of a larger code. This can be used to measure the time spent in a specific part of a larger
chunk of code. The resulting data is written to a separate series. chunk of code. The resulting data is stored as a field in the transaction that
executed the block.
To start measuring a block of Ruby code you should use To start measuring a block of Ruby code you should use `Gitlab::Metrics.measure`
`Gitlab::Metrics.measure` and give it a name for the series to store the data and give it a name:
in:
```ruby ```ruby
Gitlab::Metrics.measure(:user_logins) do Gitlab::Metrics.measure(:foo) do
... ...
end end
``` ```
The first argument of this method is the series name and should be plural. This Two values are measured for a block:
name will be prefixed with `rails_` or `sidekiq_` depending on whether the code
was run in the Rails application or one of the Sidekiq workers. In the
above example the final series names would be as follows:
- rails_user_logins 1. The real time elapsed, stored in NAME_real_time
- sidekiq_user_logins 2. The CPU time elapsed, stored in NAME_cpu_time
Series names should be plural as this keeps the naming style in line with the Both the real and CPU timings are measured in milliseconds.
other series names.
By default metrics measured using a block contain a single value, "duration", Multiple calls to the same block will result in the final values being the sum
which contains the number of milliseconds it took to execute the block. Custom of all individual values. Take this code for example:
values can be added by passing a Hash as the 2nd argument. Custom tags can be
added by passing a Hash as the 3rd argument. A simple example is as follows:
```ruby ```ruby
Gitlab::Metrics.measure(:example_series, { number: 10 }, { class: self.class.to_s }) do 3.times do
... Gitlab::Metrics.measure(:sleep) do
sleep 1
end
end end
``` ```
Here the final value of `sleep_real_time` will be `3`, _not_ `1`.
...@@ -74,24 +74,29 @@ module Gitlab ...@@ -74,24 +74,29 @@ module Gitlab
# #
# Example: # Example:
# #
# Gitlab::Metrics.measure(:find_by_username_timings) do # Gitlab::Metrics.measure(:find_by_username_duration) do
# User.find_by_username(some_username) # User.find_by_username(some_username)
# end # end
# #
# series - The name of the series to store the data in. # name - The name of the field to store the execution time in.
# values - A Hash containing extra values to add to the metric.
# tags - A Hash containing extra tags to add to the metric.
# #
# Returns the value yielded by the supplied block. # Returns the value yielded by the supplied block.
def self.measure(series, values = {}, tags = {}) def self.measure(name)
return yield unless Transaction.current return yield unless Transaction.current
start = Time.now.to_f real_start = Time.now.to_f
cpu_start = System.cpu_time
retval = yield retval = yield
duration = (Time.now.to_f - start) * 1000.0
values = values.merge(duration: duration)
Transaction.current.add_metric(series, values, tags) cpu_stop = System.cpu_time
real_stop = Time.now.to_f
real_time = (real_stop - real_start) * 1000.0
cpu_time = cpu_stop - cpu_start
Transaction.current.increment("#{name}_real_time", real_time)
Transaction.current.increment("#{name}_cpu_time", cpu_time)
retval retval
end end
......
...@@ -30,6 +30,17 @@ module Gitlab ...@@ -30,6 +30,17 @@ module Gitlab
0 0
end end
end end
# THREAD_CPUTIME is not supported on OS X
if Process.const_defined?(:CLOCK_THREAD_CPUTIME_ID)
def self.cpu_time
Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID, :millisecond)
end
else
def self.cpu_time
Process.clock_gettime(Process::CLOCK_PROCESS_CPUTIME_ID, :millisecond)
end
end
end end
end end
end end
...@@ -79,19 +79,13 @@ describe Gitlab::Metrics do ...@@ -79,19 +79,13 @@ describe Gitlab::Metrics do
end end
it 'adds a metric to the current transaction' do it 'adds a metric to the current transaction' do
expect(transaction).to receive(:add_metric). expect(transaction).to receive(:increment).
with(:foo, { duration: a_kind_of(Numeric) }, { tag: 'value' }) with('foo_real_time', a_kind_of(Numeric))
Gitlab::Metrics.measure(:foo, {}, tag: 'value') { 10 } expect(transaction).to receive(:increment).
end with('foo_cpu_time', a_kind_of(Numeric))
it 'supports adding of custom values' do
values = { duration: a_kind_of(Numeric), number: 10 }
expect(transaction).to receive(:add_metric).
with(:foo, values, { tag: 'value' })
Gitlab::Metrics.measure(:foo, { number: 10 }, tag: 'value') { 10 } Gitlab::Metrics.measure(:foo) { 10 }
end end
it 'returns the return value of the block' do it 'returns the return value of the block' do
......
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