From 16926a676bdea4bfbbbaf9d390373073d2ff8bbd Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Mon, 11 Apr 2016 12:23:37 +0200 Subject: 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). --- doc/development/instrumentation.md | 36 +++++++++++++++++------------------- lib/gitlab/metrics.rb | 23 ++++++++++++++--------- lib/gitlab/metrics/system.rb | 11 +++++++++++ spec/lib/gitlab/metrics_spec.rb | 16 +++++----------- 4 files changed, 47 insertions(+), 39 deletions(-) diff --git a/doc/development/instrumentation.md b/doc/development/instrumentation.md index c0192bd6709..f7e148fb3e4 100644 --- a/doc/development/instrumentation.md +++ b/doc/development/instrumentation.md @@ -2,36 +2,34 @@ 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 -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 -`Gitlab::Metrics.measure` and give it a name for the series to store the data -in: +To start measuring a block of Ruby code you should use `Gitlab::Metrics.measure` +and give it a name: ```ruby -Gitlab::Metrics.measure(:user_logins) do +Gitlab::Metrics.measure(:foo) do ... end ``` -The first argument of this method is the series name and should be plural. This -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: +Two values are measured for a block: -- rails_user_logins -- sidekiq_user_logins +1. The real time elapsed, stored in NAME_real_time +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 -other series names. +Both the real and CPU timings are measured in milliseconds. -By default metrics measured using a block contain a single value, "duration", -which contains the number of milliseconds it took to execute the block. Custom -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: +Multiple calls to the same block will result in the final values being the sum +of all individual values. Take this code for example: ```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 ``` + +Here the final value of `sleep_real_time` will be `3`, _not_ `1`. diff --git a/lib/gitlab/metrics.rb b/lib/gitlab/metrics.rb index 4a3f47b5a95..4d64555027e 100644 --- a/lib/gitlab/metrics.rb +++ b/lib/gitlab/metrics.rb @@ -74,24 +74,29 @@ module Gitlab # # Example: # - # Gitlab::Metrics.measure(:find_by_username_timings) do + # Gitlab::Metrics.measure(:find_by_username_duration) do # User.find_by_username(some_username) # end # - # series - The name of the series to store the data in. - # values - A Hash containing extra values to add to the metric. - # tags - A Hash containing extra tags to add to the metric. + # name - The name of the field to store the execution time in. # # Returns the value yielded by the supplied block. - def self.measure(series, values = {}, tags = {}) + def self.measure(name) return yield unless Transaction.current - start = Time.now.to_f + real_start = Time.now.to_f + cpu_start = System.cpu_time + 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 end diff --git a/lib/gitlab/metrics/system.rb b/lib/gitlab/metrics/system.rb index 83371265278..a7d183b2f94 100644 --- a/lib/gitlab/metrics/system.rb +++ b/lib/gitlab/metrics/system.rb @@ -30,6 +30,17 @@ module Gitlab 0 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 diff --git a/spec/lib/gitlab/metrics_spec.rb b/spec/lib/gitlab/metrics_spec.rb index 8f63a5f2043..edefec909c9 100644 --- a/spec/lib/gitlab/metrics_spec.rb +++ b/spec/lib/gitlab/metrics_spec.rb @@ -79,19 +79,13 @@ describe Gitlab::Metrics do end it 'adds a metric to the current transaction' do - expect(transaction).to receive(:add_metric). - with(:foo, { duration: a_kind_of(Numeric) }, { tag: 'value' }) + expect(transaction).to receive(:increment). + with('foo_real_time', a_kind_of(Numeric)) - Gitlab::Metrics.measure(:foo, {}, tag: 'value') { 10 } - end - - 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' }) + expect(transaction).to receive(:increment). + with('foo_cpu_time', a_kind_of(Numeric)) - Gitlab::Metrics.measure(:foo, { number: 10 }, tag: 'value') { 10 } + Gitlab::Metrics.measure(:foo) { 10 } end it 'returns the return value of the block' do -- cgit v1.2.1 From 185d78bcb3064c25b764937949d2bb66ec66901a Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Mon, 11 Apr 2016 13:11:13 +0200 Subject: Added specs for Gitlab::Metrics::System.cpu_time --- spec/lib/gitlab/metrics/system_spec.rb | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/spec/lib/gitlab/metrics/system_spec.rb b/spec/lib/gitlab/metrics/system_spec.rb index f8c1d956ca1..d6ae54e25e8 100644 --- a/spec/lib/gitlab/metrics/system_spec.rb +++ b/spec/lib/gitlab/metrics/system_spec.rb @@ -26,4 +26,10 @@ describe Gitlab::Metrics::System do end end end + + describe '.cpu_time' do + it 'returns a Fixnum' do + expect(described_class.cpu_time).to be_an_instance_of(Fixnum) + end + end end -- cgit v1.2.1 From d9110a7ecab52ab0716a42c2075cebdf8028d5e7 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Mon, 11 Apr 2016 13:27:24 +0200 Subject: Track call counts in Gitlab::Metrics.measure_block --- doc/development/instrumentation.md | 7 ++++--- lib/gitlab/metrics.rb | 1 + spec/lib/gitlab/metrics_spec.rb | 3 +++ 3 files changed, 8 insertions(+), 3 deletions(-) diff --git a/doc/development/instrumentation.md b/doc/development/instrumentation.md index f7e148fb3e4..c1cf2e77c26 100644 --- a/doc/development/instrumentation.md +++ b/doc/development/instrumentation.md @@ -14,10 +14,11 @@ Gitlab::Metrics.measure(:foo) do end ``` -Two values are measured for a block: +3 values are measured for a block: -1. The real time elapsed, stored in NAME_real_time -2. The CPU time elapsed, stored in NAME_cpu_time +1. The real time elapsed, stored in NAME_real_time. +2. The CPU time elapsed, stored in NAME_cpu_time. +3. The call count, stored in NAME_call_count. Both the real and CPU timings are measured in milliseconds. diff --git a/lib/gitlab/metrics.rb b/lib/gitlab/metrics.rb index 4d64555027e..33dd3e39f4d 100644 --- a/lib/gitlab/metrics.rb +++ b/lib/gitlab/metrics.rb @@ -97,6 +97,7 @@ module Gitlab Transaction.current.increment("#{name}_real_time", real_time) Transaction.current.increment("#{name}_cpu_time", cpu_time) + Transaction.current.increment("#{name}_call_count", 1) retval end diff --git a/spec/lib/gitlab/metrics_spec.rb b/spec/lib/gitlab/metrics_spec.rb index edefec909c9..a3b68455260 100644 --- a/spec/lib/gitlab/metrics_spec.rb +++ b/spec/lib/gitlab/metrics_spec.rb @@ -85,6 +85,9 @@ describe Gitlab::Metrics do expect(transaction).to receive(:increment). with('foo_cpu_time', a_kind_of(Numeric)) + expect(transaction).to receive(:increment). + with('foo_call_count', 1) + Gitlab::Metrics.measure(:foo) { 10 } end -- cgit v1.2.1 From 7eed4608fe5adf65d6a29ef50c93485ca2e6806f Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Mon, 11 Apr 2016 14:29:38 +0200 Subject: Fixed stubbing for Gitlab::Metrics specs If the measure method uses Transaction.current directly the SQL subscriber (Subscribers::ActiveRecord) will add timings of queries triggered by DB cleaner. --- lib/gitlab/metrics.rb | 16 ++++++++++++---- spec/lib/gitlab/metrics_spec.rb | 2 +- 2 files changed, 13 insertions(+), 5 deletions(-) diff --git a/lib/gitlab/metrics.rb b/lib/gitlab/metrics.rb index 33dd3e39f4d..2a0a5629be5 100644 --- a/lib/gitlab/metrics.rb +++ b/lib/gitlab/metrics.rb @@ -82,7 +82,9 @@ module Gitlab # # Returns the value yielded by the supplied block. def self.measure(name) - return yield unless Transaction.current + trans = current_transaction + + return yield unless trans real_start = Time.now.to_f cpu_start = System.cpu_time @@ -95,9 +97,9 @@ module Gitlab 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) - Transaction.current.increment("#{name}_call_count", 1) + trans.increment("#{name}_real_time", real_time) + trans.increment("#{name}_cpu_time", cpu_time) + trans.increment("#{name}_call_count", 1) retval end @@ -113,5 +115,11 @@ module Gitlab new(udp: { host: host, port: port }) end end + + private + + def self.current_transaction + Transaction.current + end end end diff --git a/spec/lib/gitlab/metrics_spec.rb b/spec/lib/gitlab/metrics_spec.rb index a3b68455260..3dee13e27f4 100644 --- a/spec/lib/gitlab/metrics_spec.rb +++ b/spec/lib/gitlab/metrics_spec.rb @@ -74,7 +74,7 @@ describe Gitlab::Metrics do let(:transaction) { Gitlab::Metrics::Transaction.new } before do - allow(Gitlab::Metrics::Transaction).to receive(:current). + allow(Gitlab::Metrics).to receive(:current_transaction). and_return(transaction) end -- cgit v1.2.1