From 141e946c3da97c7af02aaca5324c6e4ce7362a04 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Wed, 9 Dec 2015 16:45:51 +0100 Subject: Storing of application metrics in InfluxDB This adds the ability to write application metrics (e.g. SQL timings) to InfluxDB. These metrics can in turn be visualized using Grafana, or really anything else that can read from InfluxDB. These metrics can be used to track application performance over time, between different Ruby versions, different GitLab versions, etc. == Transaction Metrics Currently the following is tracked on a per transaction basis (a transaction is a Rails request or a single Sidekiq job): * Timings per query along with the raw (obfuscated) SQL and information about what file the query originated from. * Timings per view along with the path of the view and information about what file triggered the rendering process. * The duration of a request itself along with the controller/worker class and method name. * The duration of any instrumented method calls (more below). == Sampled Metrics Certain metrics can't be directly associated with a transaction. For example, a process' total memory usage is unrelated to any running transactions. While a transaction can result in the memory usage going up there's no accurate way to determine what transaction is to blame, this becomes especially problematic in multi-threaded environments. To solve this problem there's a separate thread that takes samples at a fixed interval. This thread (using the class Gitlab::Metrics::Sampler) currently tracks the following: * The process' total memory usage. * The number of file descriptors opened by the process. * The amount of Ruby objects (using ObjectSpace.count_objects). * GC statistics such as timings, heap slots, etc. The default/current interval is 15 seconds, any smaller interval might put too much pressure on InfluxDB (especially when running dozens of processes). == Method Instrumentation While currently not yet used methods can be instrumented to track how long they take to run. Unlike the likes of New Relic this doesn't require modifying the source code (e.g. including modules), it all happens from the outside. For example, to track `User.by_login` we'd add the following code somewhere in an initializer: Gitlab::Metrics::Instrumentation. instrument_method(User, :by_login) to instead instrument an instance method: Gitlab::Metrics::Instrumentation. instrument_instance_method(User, :save) Instrumentation for either all public model methods or a few crucial ones will be added in the near future, I simply haven't gotten to doing so just yet. == Configuration By default metrics are disabled. This means users don't have to bother setting anything up if they don't want to. Metrics can be enabled by editing one's gitlab.yml configuration file (see config/gitlab.yml.example for example settings). == Writing Data To InfluxDB Because InfluxDB is still a fairly young product I expect the worse. Data loss, unexpected reboots, the database not responding, you name it. Because of this data is _not_ written to InfluxDB directly, instead it's queued and processed by Sidekiq. This ensures that users won't notice anything when InfluxDB is giving trouble. The metrics worker can be started in a standalone manner as following: bundle exec sidekiq -q metrics The corresponding class is called MetricsWorker. --- Gemfile | 6 ++ Gemfile.lock | 30 ++++--- Procfile | 2 +- app/workers/metrics_worker.rb | 29 +++++++ config/gitlab.yml.example | 17 ++++ config/initializers/metrics.rb | 25 ++++++ lib/gitlab/metrics.rb | 52 ++++++++++++ lib/gitlab/metrics/delta.rb | 32 ++++++++ lib/gitlab/metrics/instrumentation.rb | 47 +++++++++++ lib/gitlab/metrics/metric.rb | 34 ++++++++ lib/gitlab/metrics/obfuscated_sql.rb | 39 +++++++++ lib/gitlab/metrics/rack_middleware.rb | 49 ++++++++++++ lib/gitlab/metrics/sampler.rb | 77 ++++++++++++++++++ lib/gitlab/metrics/sidekiq_middleware.rb | 30 +++++++ lib/gitlab/metrics/subscribers/action_view.rb | 48 +++++++++++ lib/gitlab/metrics/subscribers/active_record.rb | 43 ++++++++++ lib/gitlab/metrics/subscribers/method_call.rb | 42 ++++++++++ lib/gitlab/metrics/system.rb | 35 ++++++++ lib/gitlab/metrics/transaction.rb | 66 ++++++++++++++++ spec/lib/gitlab/metrics/delta_spec.rb | 16 ++++ spec/lib/gitlab/metrics/instrumentation_spec.rb | 91 +++++++++++++++++++++ spec/lib/gitlab/metrics/metric_spec.rb | 57 ++++++++++++++ spec/lib/gitlab/metrics/obfuscated_sql_spec.rb | 79 +++++++++++++++++++ spec/lib/gitlab/metrics/rack_middleware_spec.rb | 63 +++++++++++++++ spec/lib/gitlab/metrics/sampler_spec.rb | 92 ++++++++++++++++++++++ spec/lib/gitlab/metrics/sidekiq_middleware_spec.rb | 34 ++++++++ .../gitlab/metrics/subscribers/action_view_spec.rb | 32 ++++++++ .../metrics/subscribers/active_record_spec.rb | 31 ++++++++ .../gitlab/metrics/subscribers/method_call_spec.rb | 41 ++++++++++ spec/lib/gitlab/metrics/system_spec.rb | 29 +++++++ spec/lib/gitlab/metrics/transaction_spec.rb | 77 ++++++++++++++++++ spec/lib/gitlab/metrics_spec.rb | 36 +++++++++ 32 files changed, 1368 insertions(+), 13 deletions(-) create mode 100644 app/workers/metrics_worker.rb create mode 100644 config/initializers/metrics.rb create mode 100644 lib/gitlab/metrics.rb create mode 100644 lib/gitlab/metrics/delta.rb create mode 100644 lib/gitlab/metrics/instrumentation.rb create mode 100644 lib/gitlab/metrics/metric.rb create mode 100644 lib/gitlab/metrics/obfuscated_sql.rb create mode 100644 lib/gitlab/metrics/rack_middleware.rb create mode 100644 lib/gitlab/metrics/sampler.rb create mode 100644 lib/gitlab/metrics/sidekiq_middleware.rb create mode 100644 lib/gitlab/metrics/subscribers/action_view.rb create mode 100644 lib/gitlab/metrics/subscribers/active_record.rb create mode 100644 lib/gitlab/metrics/subscribers/method_call.rb create mode 100644 lib/gitlab/metrics/system.rb create mode 100644 lib/gitlab/metrics/transaction.rb create mode 100644 spec/lib/gitlab/metrics/delta_spec.rb create mode 100644 spec/lib/gitlab/metrics/instrumentation_spec.rb create mode 100644 spec/lib/gitlab/metrics/metric_spec.rb create mode 100644 spec/lib/gitlab/metrics/obfuscated_sql_spec.rb create mode 100644 spec/lib/gitlab/metrics/rack_middleware_spec.rb create mode 100644 spec/lib/gitlab/metrics/sampler_spec.rb create mode 100644 spec/lib/gitlab/metrics/sidekiq_middleware_spec.rb create mode 100644 spec/lib/gitlab/metrics/subscribers/action_view_spec.rb create mode 100644 spec/lib/gitlab/metrics/subscribers/active_record_spec.rb create mode 100644 spec/lib/gitlab/metrics/subscribers/method_call_spec.rb create mode 100644 spec/lib/gitlab/metrics/system_spec.rb create mode 100644 spec/lib/gitlab/metrics/transaction_spec.rb create mode 100644 spec/lib/gitlab/metrics_spec.rb diff --git a/Gemfile b/Gemfile index b23e274081b..90db2c43006 100644 --- a/Gemfile +++ b/Gemfile @@ -208,6 +208,12 @@ gem 'select2-rails', '~> 3.5.9' gem 'virtus', '~> 1.0.1' gem 'net-ssh', '~> 3.0.1' +# Metrics +group :metrics do + gem 'influxdb', '~> 0.2', require: false + gem 'connection_pool', '~> 2.0', require: false +end + group :development do gem "foreman" gem 'brakeman', '3.0.1', require: false diff --git a/Gemfile.lock b/Gemfile.lock index 4dfff211134..7d592ba93a7 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -65,7 +65,7 @@ GEM attr_encrypted (1.3.4) encryptor (>= 1.3.0) attr_required (1.0.0) - autoprefixer-rails (6.1.1) + autoprefixer-rails (6.1.2) execjs json awesome_print (1.2.0) @@ -102,7 +102,7 @@ GEM bundler-audit (0.4.0) bundler (~> 1.2) thor (~> 0.18) - byebug (8.2.0) + byebug (8.2.1) cal-heatmap-rails (0.0.1) capybara (2.4.4) mime-types (>= 1.16) @@ -117,6 +117,7 @@ GEM activemodel (>= 3.2.0) activesupport (>= 3.2.0) json (>= 1.7) + cause (0.1) charlock_holmes (0.7.3) chunky_png (1.3.5) cliver (0.3.2) @@ -140,10 +141,10 @@ GEM term-ansicolor (~> 1.3) thor (~> 0.19.1) tins (~> 1.6.0) - crack (0.4.2) + crack (0.4.3) safe_yaml (~> 1.0.0) creole (0.5.0) - d3_rails (3.5.6) + d3_rails (3.5.11) railties (>= 3.1.0) daemons (1.2.3) database_cleaner (1.4.1) @@ -230,7 +231,7 @@ GEM ipaddress (~> 0.5) nokogiri (~> 1.5, >= 1.5.11) opennebula - fog-brightbox (0.9.0) + fog-brightbox (0.10.1) fog-core (~> 1.22) fog-json inflecto (~> 0.0.2) @@ -249,7 +250,7 @@ GEM fog-core (>= 1.21.0) fog-json fog-xml (>= 0.0.1) - fog-sakuracloud (1.4.0) + fog-sakuracloud (1.5.0) fog-core fog-json fog-softlayer (1.0.2) @@ -277,11 +278,11 @@ GEM ruby-progressbar (~> 1.4) gemnasium-gitlab-service (0.2.6) rugged (~> 0.21) - gemojione (2.1.0) + gemojione (2.1.1) json get_process_mem (0.2.0) gherkin-ruby (0.3.2) - github-linguist (4.7.2) + github-linguist (4.7.3) charlock_holmes (~> 0.7.3) escape_utils (~> 1.1.0) mime-types (>= 1.19) @@ -298,7 +299,7 @@ GEM posix-spawn (~> 0.3) gitlab_emoji (0.2.0) gemojione (~> 2.1) - gitlab_git (7.2.21) + gitlab_git (7.2.22) activesupport (~> 4.0) charlock_holmes (~> 0.7.3) github-linguist (~> 4.7.0) @@ -370,6 +371,9 @@ GEM i18n (0.7.0) ice_nine (0.11.1) inflecto (0.0.2) + influxdb (0.2.3) + cause + json ipaddress (0.8.0) jquery-atwho-rails (1.3.2) jquery-rails (3.1.4) @@ -416,11 +420,11 @@ GEM net-ldap (0.12.1) net-ssh (3.0.1) netrc (0.11.0) - newrelic-grape (2.0.0) + newrelic-grape (2.1.0) grape newrelic_rpm newrelic_rpm (3.9.4.245) - nokogiri (1.6.7) + nokogiri (1.6.7.1) mini_portile2 (~> 2.0.0.rc2) nprogress-rails (0.1.6.7) oauth (0.4.7) @@ -783,7 +787,7 @@ GEM coercible (~> 1.0) descendants_tracker (~> 0.0, >= 0.0.3) equalizer (~> 0.0, >= 0.0.9) - warden (1.2.3) + warden (1.2.4) rack (>= 1.0) web-console (2.2.1) activemodel (>= 4.0) @@ -836,6 +840,7 @@ DEPENDENCIES charlock_holmes (~> 0.7.3) coffee-rails (~> 4.1.0) colorize (~> 0.7.0) + connection_pool (~> 2.0) coveralls (~> 0.8.2) creole (~> 0.5.0) d3_rails (~> 3.5.5) @@ -873,6 +878,7 @@ DEPENDENCIES hipchat (~> 1.5.0) html-pipeline (~> 1.11.0) httparty (~> 0.13.3) + influxdb (~> 0.2) jquery-atwho-rails (~> 1.3.2) jquery-rails (~> 3.1.3) jquery-scrollto-rails (~> 1.4.3) diff --git a/Procfile b/Procfile index 9cfdee7040f..bbafdd33a2d 100644 --- a/Procfile +++ b/Procfile @@ -3,5 +3,5 @@ # lib/support/init.d, which call scripts in bin/ . # web: bundle exec unicorn_rails -p ${PORT:="3000"} -E ${RAILS_ENV:="development"} -c ${UNICORN_CONFIG:="config/unicorn.rb"} -worker: bundle exec sidekiq -q post_receive -q mailers -q archive_repo -q system_hook -q project_web_hook -q gitlab_shell -q incoming_email -q runner -q common -q default +worker: bundle exec sidekiq -q post_receive -q mailers -q archive_repo -q system_hook -q project_web_hook -q gitlab_shell -q incoming_email -q runner -q common -q default -q metrics # mail_room: bundle exec mail_room -q -c config/mail_room.yml diff --git a/app/workers/metrics_worker.rb b/app/workers/metrics_worker.rb new file mode 100644 index 00000000000..8fffe371572 --- /dev/null +++ b/app/workers/metrics_worker.rb @@ -0,0 +1,29 @@ +class MetricsWorker + include Sidekiq::Worker + + sidekiq_options queue: :metrics + + def perform(metrics) + prepared = prepare_metrics(metrics) + + Gitlab::Metrics.pool.with do |connection| + connection.write_points(prepared) + end + end + + def prepare_metrics(metrics) + metrics.map do |hash| + new_hash = hash.symbolize_keys + + new_hash[:tags].each do |key, value| + new_hash[:tags][key] = escape_value(value) + end + + new_hash + end + end + + def escape_value(value) + value.gsub('=', '\\=') + end +end diff --git a/config/gitlab.yml.example b/config/gitlab.yml.example index db378118f85..38b0920890f 100644 --- a/config/gitlab.yml.example +++ b/config/gitlab.yml.example @@ -421,9 +421,22 @@ production: &base # # Ban an IP for one hour (3600s) after too many auth attempts # bantime: 3600 + metrics: + enabled: false + # The name of the InfluxDB database to store metrics in. + database: gitlab + # Credentials to use for logging in to InfluxDB. + # username: + # password: + # The amount of InfluxDB connections to open. + # pool_size: 16 + # The timeout of a connection in seconds. + # timeout: 10 development: <<: *base + metrics: + enabled: false test: <<: *base @@ -466,6 +479,10 @@ test: user_filter: '' group_base: 'ou=groups,dc=example,dc=com' admin_group: '' + metrics: + enabled: false staging: <<: *base + metrics: + enabled: false diff --git a/config/initializers/metrics.rb b/config/initializers/metrics.rb new file mode 100644 index 00000000000..bde04232725 --- /dev/null +++ b/config/initializers/metrics.rb @@ -0,0 +1,25 @@ +if Gitlab::Metrics.enabled? + require 'influxdb' + require 'socket' + require 'connection_pool' + + # These are manually require'd so the classes are registered properly with + # ActiveSupport. + require 'gitlab/metrics/subscribers/action_view' + require 'gitlab/metrics/subscribers/active_record' + require 'gitlab/metrics/subscribers/method_call' + + Gitlab::Application.configure do |config| + config.middleware.use(Gitlab::Metrics::RackMiddleware) + end + + Sidekiq.configure_server do |config| + config.server_middleware do |chain| + chain.add Gitlab::Metrics::SidekiqMiddleware + end + end + + GC::Profiler.enable + + Gitlab::Metrics::Sampler.new.start +end diff --git a/lib/gitlab/metrics.rb b/lib/gitlab/metrics.rb new file mode 100644 index 00000000000..08393995165 --- /dev/null +++ b/lib/gitlab/metrics.rb @@ -0,0 +1,52 @@ +module Gitlab + module Metrics + def self.pool_size + Settings.metrics['pool_size'] || 16 + end + + def self.timeout + Settings.metrics['timeout'] || 10 + end + + def self.enabled? + !!Settings.metrics['enabled'] + end + + def self.pool + @pool + end + + def self.hostname + @hostname + end + + def self.last_relative_application_frame + root = Rails.root.to_s + metrics = Rails.root.join('lib', 'gitlab', 'metrics').to_s + + frame = caller_locations.find do |l| + l.path.start_with?(root) && !l.path.start_with?(metrics) + end + + if frame + return frame.path.gsub(/^#{Rails.root.to_s}\/?/, ''), frame.lineno + else + return nil, nil + end + end + + @hostname = Socket.gethostname + + # When enabled this should be set before being used as the usual pattern + # "@foo ||= bar" is _not_ thread-safe. + if enabled? + @pool = ConnectionPool.new(size: pool_size, timeout: timeout) do + db = Settings.metrics['database'] + user = Settings.metrics['username'] + pw = Settings.metrics['password'] + + InfluxDB::Client.new(db, username: user, password: pw) + end + end + end +end diff --git a/lib/gitlab/metrics/delta.rb b/lib/gitlab/metrics/delta.rb new file mode 100644 index 00000000000..bcf28eed84d --- /dev/null +++ b/lib/gitlab/metrics/delta.rb @@ -0,0 +1,32 @@ +module Gitlab + module Metrics + # Class for calculating the difference between two numeric values. + # + # Every call to `compared_with` updates the internal value. This makes it + # possible to use a single Delta instance to calculate the delta over time + # of an ever increasing number. + # + # Example usage: + # + # delta = Delta.new(0) + # + # delta.compared_with(10) # => 10 + # delta.compared_with(15) # => 5 + # delta.compared_with(20) # => 5 + class Delta + def initialize(value = 0) + @value = value + end + + # new_value - The value to compare with as a Numeric. + # + # Returns a new Numeric (depending on the type of `new_value`). + def compared_with(new_value) + delta = new_value - @value + @value = new_value + + delta + end + end + end +end diff --git a/lib/gitlab/metrics/instrumentation.rb b/lib/gitlab/metrics/instrumentation.rb new file mode 100644 index 00000000000..1c2f84fb09a --- /dev/null +++ b/lib/gitlab/metrics/instrumentation.rb @@ -0,0 +1,47 @@ +module Gitlab + module Metrics + # Module for instrumenting methods. + # + # This module allows instrumenting of methods without having to actually + # alter the target code (e.g. by including modules). + # + # Example usage: + # + # Gitlab::Metrics::Instrumentation.instrument_method(User, :by_login) + module Instrumentation + # Instruments a class method. + # + # mod - The module to instrument as a Module/Class. + # name - The name of the method to instrument. + def self.instrument_method(mod, name) + instrument(:class, mod, name) + end + + # Instruments an instance method. + # + # mod - The module to instrument as a Module/Class. + # name - The name of the method to instrument. + def self.instrument_instance_method(mod, name) + instrument(:instance, mod, name) + end + + def self.instrument(type, mod, name) + return unless Metrics.enabled? + + alias_name = "_original_#{name}" + target = type == :instance ? mod : mod.singleton_class + + target.class_eval do + alias_method(alias_name, name) + + define_method(name) do |*args, &block| + ActiveSupport::Notifications. + instrument("#{type}_method.method_call", module: mod, name: name) do + __send__(alias_name, *args, &block) + end + end + end + end + end + end +end diff --git a/lib/gitlab/metrics/metric.rb b/lib/gitlab/metrics/metric.rb new file mode 100644 index 00000000000..f592f4e571f --- /dev/null +++ b/lib/gitlab/metrics/metric.rb @@ -0,0 +1,34 @@ +module Gitlab + module Metrics + # Class for storing details of a single metric (label, value, etc). + class Metric + attr_reader :series, :values, :tags, :created_at + + # series - The name of the series (as a String) to store the metric in. + # values - A Hash containing the values to store. + # tags - A Hash containing extra tags to add to the metrics. + def initialize(series, values, tags = {}) + @values = values + @series = series + @tags = tags + @created_at = Time.now.utc + end + + # Returns a Hash in a format that can be directly written to InfluxDB. + def to_hash + { + series: @series, + tags: @tags.merge( + hostname: Metrics.hostname, + ruby_engine: RUBY_ENGINE, + ruby_version: RUBY_VERSION, + gitlab_version: Gitlab::VERSION, + process_type: Sidekiq.server? ? 'sidekiq' : 'rails' + ), + values: @values, + timestamp: @created_at.to_i + } + end + end + end +end diff --git a/lib/gitlab/metrics/obfuscated_sql.rb b/lib/gitlab/metrics/obfuscated_sql.rb new file mode 100644 index 00000000000..45f2e2bc62a --- /dev/null +++ b/lib/gitlab/metrics/obfuscated_sql.rb @@ -0,0 +1,39 @@ +module Gitlab + module Metrics + # Class for producing SQL queries with sensitive data stripped out. + class ObfuscatedSQL + REPLACEMENT = / + \d+(\.\d+)? # integers, floats + | '.+?' # single quoted strings + | \/.+?(? 'GET', 'REQUEST_URI' => '/foo' } } + + describe '#call' do + before do + expect_any_instance_of(Gitlab::Metrics::Transaction).to receive(:finish) + end + + it 'tracks a transaction' do + expect(app).to receive(:call).with(env).and_return('yay') + + expect(middleware.call(env)).to eq('yay') + end + + it 'tags a transaction with the name and action of a controller' do + klass = double(:klass, name: 'TestController') + controller = double(:controller, class: klass, action_name: 'show') + + env['action_controller.instance'] = controller + + allow(app).to receive(:call).with(env) + + expect(middleware).to receive(:tag_controller). + with(an_instance_of(Gitlab::Metrics::Transaction), env) + + middleware.call(env) + end + end + + describe '#transaction_from_env' do + let(:transaction) { middleware.transaction_from_env(env) } + + it 'returns a Transaction' do + expect(transaction).to be_an_instance_of(Gitlab::Metrics::Transaction) + end + + it 'tags the transaction with the request method and URI' do + expect(transaction.tags[:request_method]).to eq('GET') + expect(transaction.tags[:request_uri]).to eq('/foo') + end + end + + describe '#tag_controller' do + let(:transaction) { middleware.transaction_from_env(env) } + + it 'tags a transaction with the name and action of a controller' do + klass = double(:klass, name: 'TestController') + controller = double(:controller, class: klass, action_name: 'show') + + env['action_controller.instance'] = controller + + middleware.tag_controller(transaction, env) + + expect(transaction.tags[:action]).to eq('TestController#show') + end + end +end diff --git a/spec/lib/gitlab/metrics/sampler_spec.rb b/spec/lib/gitlab/metrics/sampler_spec.rb new file mode 100644 index 00000000000..b486d38870f --- /dev/null +++ b/spec/lib/gitlab/metrics/sampler_spec.rb @@ -0,0 +1,92 @@ +require 'spec_helper' + +describe Gitlab::Metrics::Sampler do + let(:sampler) { described_class.new(5) } + + describe '#start' do + it 'gathers a sample at a given interval' do + expect(sampler).to receive(:sleep).with(5) + expect(sampler).to receive(:sample) + expect(sampler).to receive(:loop).and_yield + + sampler.start.join + end + end + + describe '#sample' do + it 'samples various statistics' do + expect(sampler).to receive(:sample_memory_usage) + expect(sampler).to receive(:sample_file_descriptors) + expect(sampler).to receive(:sample_objects) + expect(sampler).to receive(:sample_gc) + expect(sampler).to receive(:flush) + + sampler.sample + end + + it 'clears any GC profiles' do + expect(sampler).to receive(:flush) + expect(GC::Profiler).to receive(:clear) + + sampler.sample + end + end + + describe '#flush' do + it 'schedules the metrics using Sidekiq' do + expect(MetricsWorker).to receive(:perform_async). + with([an_instance_of(Hash)]) + + sampler.sample_memory_usage + sampler.flush + end + end + + describe '#sample_memory_usage' do + it 'adds a metric containing the memory usage' do + expect(Gitlab::Metrics::System).to receive(:memory_usage). + and_return(9000) + + expect(Gitlab::Metrics::Metric).to receive(:new). + with('memory_usage', value: 9000). + and_call_original + + sampler.sample_memory_usage + end + end + + describe '#sample_file_descriptors' do + it 'adds a metric containing the amount of open file descriptors' do + expect(Gitlab::Metrics::System).to receive(:file_descriptor_count). + and_return(4) + + expect(Gitlab::Metrics::Metric).to receive(:new). + with('file_descriptors', value: 4). + and_call_original + + sampler.sample_file_descriptors + end + end + + describe '#sample_objects' do + it 'adds a metric containing the amount of allocated objects' do + expect(Gitlab::Metrics::Metric).to receive(:new). + with('object_counts', an_instance_of(Hash)). + and_call_original + + sampler.sample_objects + end + end + + describe '#sample_gc' do + it 'adds a metric containing garbage collection statistics' do + expect(GC::Profiler).to receive(:total_time).and_return(0.24) + + expect(Gitlab::Metrics::Metric).to receive(:new). + with('gc_statistics', an_instance_of(Hash)). + and_call_original + + sampler.sample_gc + end + end +end diff --git a/spec/lib/gitlab/metrics/sidekiq_middleware_spec.rb b/spec/lib/gitlab/metrics/sidekiq_middleware_spec.rb new file mode 100644 index 00000000000..05214efc565 --- /dev/null +++ b/spec/lib/gitlab/metrics/sidekiq_middleware_spec.rb @@ -0,0 +1,34 @@ +require 'spec_helper' + +describe Gitlab::Metrics::SidekiqMiddleware do + let(:middleware) { described_class.new } + + describe '#call' do + it 'tracks the transaction' do + worker = Class.new.new + + expect_any_instance_of(Gitlab::Metrics::Transaction).to receive(:finish) + + middleware.call(worker, 'test', :test) { nil } + end + + it 'does not track jobs of the MetricsWorker' do + worker = MetricsWorker.new + + expect(Gitlab::Metrics::Transaction).to_not receive(:new) + + middleware.call(worker, 'test', :test) { nil } + end + end + + describe '#tag_worker' do + it 'adds the worker class and action to the transaction' do + trans = Gitlab::Metrics::Transaction.new + worker = double(:worker, class: double(:class, name: 'TestWorker')) + + expect(trans).to receive(:add_tag).with(:action, 'TestWorker#perform') + + middleware.tag_worker(trans, worker) + end + end +end diff --git a/spec/lib/gitlab/metrics/subscribers/action_view_spec.rb b/spec/lib/gitlab/metrics/subscribers/action_view_spec.rb new file mode 100644 index 00000000000..77f3e69d523 --- /dev/null +++ b/spec/lib/gitlab/metrics/subscribers/action_view_spec.rb @@ -0,0 +1,32 @@ +require 'spec_helper' + +describe Gitlab::Metrics::Subscribers::ActionView do + let(:transaction) { Gitlab::Metrics::Transaction.new } + + let(:subscriber) { described_class.new } + + let(:event) do + root = Rails.root.to_s + + double(:event, duration: 2.1, + payload: { identifier: "#{root}/app/views/x.html.haml" }) + end + + before do + allow(subscriber).to receive(:current_transaction).and_return(transaction) + + allow(Gitlab::Metrics).to receive(:last_relative_application_frame). + and_return(['app/views/x.html.haml', 4]) + end + + describe '#render_template' do + it 'tracks rendering of a template' do + values = { duration: 2.1, file: 'app/views/x.html.haml', line: 4 } + + expect(transaction).to receive(:add_metric). + with(described_class::SERIES, values, path: 'app/views/x.html.haml') + + subscriber.render_template(event) + end + end +end diff --git a/spec/lib/gitlab/metrics/subscribers/active_record_spec.rb b/spec/lib/gitlab/metrics/subscribers/active_record_spec.rb new file mode 100644 index 00000000000..58e8e84df9b --- /dev/null +++ b/spec/lib/gitlab/metrics/subscribers/active_record_spec.rb @@ -0,0 +1,31 @@ +require 'spec_helper' + +describe Gitlab::Metrics::Subscribers::ActiveRecord do + let(:transaction) { Gitlab::Metrics::Transaction.new } + + let(:subscriber) { described_class.new } + + let(:event) do + double(:event, duration: 0.2, + payload: { sql: 'SELECT * FROM users WHERE id = 10' }) + 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 '#sql' do + it 'tracks the execution of a SQL query' do + values = { duration: 0.2, file: 'app/models/foo.rb', line: 4 } + sql = 'SELECT * FROM users WHERE id = ?' + + expect(transaction).to receive(:add_metric). + with(described_class::SERIES, values, sql: sql) + + subscriber.sql(event) + end + end +end diff --git a/spec/lib/gitlab/metrics/subscribers/method_call_spec.rb b/spec/lib/gitlab/metrics/subscribers/method_call_spec.rb new file mode 100644 index 00000000000..65de95d6d1e --- /dev/null +++ b/spec/lib/gitlab/metrics/subscribers/method_call_spec.rb @@ -0,0 +1,41 @@ +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: double(:mod, name: '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 diff --git a/spec/lib/gitlab/metrics/system_spec.rb b/spec/lib/gitlab/metrics/system_spec.rb new file mode 100644 index 00000000000..f8c1d956ca1 --- /dev/null +++ b/spec/lib/gitlab/metrics/system_spec.rb @@ -0,0 +1,29 @@ +require 'spec_helper' + +describe Gitlab::Metrics::System do + if File.exist?('/proc') + describe '.memory_usage' do + it "returns the process' memory usage in bytes" do + expect(described_class.memory_usage).to be > 0 + end + end + + describe '.file_descriptor_count' do + it 'returns the amount of open file descriptors' do + expect(described_class.file_descriptor_count).to be > 0 + end + end + else + describe '.memory_usage' do + it 'returns 0.0' do + expect(described_class.memory_usage).to eq(0.0) + end + end + + describe '.file_descriptor_count' do + it 'returns 0' do + expect(described_class.file_descriptor_count).to eq(0) + end + end + end +end diff --git a/spec/lib/gitlab/metrics/transaction_spec.rb b/spec/lib/gitlab/metrics/transaction_spec.rb new file mode 100644 index 00000000000..5f17ff8ee75 --- /dev/null +++ b/spec/lib/gitlab/metrics/transaction_spec.rb @@ -0,0 +1,77 @@ +require 'spec_helper' + +describe Gitlab::Metrics::Transaction do + let(:transaction) { described_class.new } + + describe '#duration' do + it 'returns the duration of a transaction in seconds' do + transaction.run { sleep(0.5) } + + expect(transaction.duration).to be >= 0.5 + end + end + + describe '#run' do + it 'yields the supplied block' do + expect { |b| transaction.run(&b) }.to yield_control + end + + it 'stores the transaction in the current thread' do + transaction.run do + expect(Thread.current[described_class::THREAD_KEY]).to eq(transaction) + end + end + + it 'removes the transaction from the current thread upon completion' do + transaction.run { } + + expect(Thread.current[described_class::THREAD_KEY]).to be_nil + end + end + + describe '#add_metric' do + it 'adds a metric tagged with the transaction UUID' do + expect(Gitlab::Metrics::Metric).to receive(:new). + with('foo', { number: 10 }, { transaction_id: transaction.uuid }) + + transaction.add_metric('foo', number: 10) + end + end + + describe '#add_tag' do + it 'adds a tag' do + transaction.add_tag(:foo, 'bar') + + expect(transaction.tags).to eq({ foo: 'bar' }) + end + end + + describe '#finish' do + it 'tracks the transaction details and submits them to Sidekiq' do + expect(transaction).to receive(:track_self) + expect(transaction).to receive(:submit) + + transaction.finish + end + end + + describe '#track_self' do + it 'adds a metric for the transaction itself' do + expect(transaction).to receive(:add_metric). + with(described_class::SERIES, { duration: transaction.duration }, {}) + + transaction.track_self + end + end + + describe '#submit' do + it 'submits the metrics to Sidekiq' do + transaction.track_self + + expect(MetricsWorker).to receive(:perform_async). + with([an_instance_of(Hash)]) + + transaction.submit + end + end +end diff --git a/spec/lib/gitlab/metrics_spec.rb b/spec/lib/gitlab/metrics_spec.rb new file mode 100644 index 00000000000..ebc69f8a75f --- /dev/null +++ b/spec/lib/gitlab/metrics_spec.rb @@ -0,0 +1,36 @@ +require 'spec_helper' + +describe Gitlab::Metrics do + describe '.pool_size' do + it 'returns a Fixnum' do + expect(described_class.pool_size).to be_an_instance_of(Fixnum) + end + end + + describe '.timeout' do + it 'returns a Fixnum' do + expect(described_class.timeout).to be_an_instance_of(Fixnum) + end + end + + describe '.enabled?' do + it 'returns a boolean' do + expect([true, false].include?(described_class.enabled?)).to eq(true) + end + end + + describe '.hostname' do + it 'returns a String containing the hostname' do + expect(described_class.hostname).to eq(Socket.gethostname) + end + end + + describe '.last_relative_application_frame' do + it 'returns an Array containing a file path and line number' do + file, line = described_class.last_relative_application_frame + + expect(line).to eq(30) + expect(file).to eq('spec/lib/gitlab/metrics_spec.rb') + end + end +end -- cgit v1.2.1 From 60a6a240ea21cbfa564b9373b1c3bb57316aae46 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Thu, 10 Dec 2015 13:25:16 +0100 Subject: Improved last_relative_application_frame timings The previous setup wasn't exactly fast, resulting in instrumented method calls taking about 600 times longer than non instrumented calls (including any ActiveSupport code involved). With this commit this slowdown has been reduced to around 185 times. --- lib/gitlab/metrics.rb | 13 ++++++++----- 1 file changed, 8 insertions(+), 5 deletions(-) diff --git a/lib/gitlab/metrics.rb b/lib/gitlab/metrics.rb index 08393995165..007429fa194 100644 --- a/lib/gitlab/metrics.rb +++ b/lib/gitlab/metrics.rb @@ -1,5 +1,9 @@ module Gitlab module Metrics + RAILS_ROOT = Rails.root.to_s + METRICS_ROOT = Rails.root.join('lib', 'gitlab', 'metrics').to_s + PATH_REGEX = /^#{RAILS_ROOT}\/?/ + def self.pool_size Settings.metrics['pool_size'] || 16 end @@ -20,16 +24,15 @@ module Gitlab @hostname end + # Returns a relative path and line number based on the last application call + # frame. def self.last_relative_application_frame - root = Rails.root.to_s - metrics = Rails.root.join('lib', 'gitlab', 'metrics').to_s - frame = caller_locations.find do |l| - l.path.start_with?(root) && !l.path.start_with?(metrics) + l.path.start_with?(RAILS_ROOT) && !l.path.start_with?(METRICS_ROOT) end if frame - return frame.path.gsub(/^#{Rails.root.to_s}\/?/, ''), frame.lineno + return frame.path.sub(PATH_REGEX, ''), frame.lineno else return nil, nil end -- cgit v1.2.1 From b66a16c8384b64eabeb04f3f32017581e4711eb8 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Thu, 10 Dec 2015 13:38:45 +0100 Subject: Use string evaluation for method instrumentation This is faster than using define_method since we don't have to keep block bindings around. --- lib/gitlab/metrics/instrumentation.rb | 16 +++++++++------- lib/gitlab/metrics/subscribers/method_call.rb | 4 ++-- spec/lib/gitlab/metrics/instrumentation_spec.rb | 6 ++++-- spec/lib/gitlab/metrics/subscribers/method_call_spec.rb | 3 +-- 4 files changed, 16 insertions(+), 13 deletions(-) diff --git a/lib/gitlab/metrics/instrumentation.rb b/lib/gitlab/metrics/instrumentation.rb index 1c2f84fb09a..982e35adfc9 100644 --- a/lib/gitlab/metrics/instrumentation.rb +++ b/lib/gitlab/metrics/instrumentation.rb @@ -31,16 +31,18 @@ module Gitlab alias_name = "_original_#{name}" target = type == :instance ? mod : mod.singleton_class - target.class_eval do - alias_method(alias_name, name) + target.class_eval <<-EOF, __FILE__, __LINE__ + 1 + alias_method :#{alias_name}, :#{name} - define_method(name) do |*args, &block| - ActiveSupport::Notifications. - instrument("#{type}_method.method_call", module: mod, name: name) do - __send__(alias_name, *args, &block) + def #{name}(*args, &block) + ActiveSupport::Notifications + .instrument("#{type}_method.method_call", + module: #{mod.name.inspect}, + name: #{name.inspect}) do + #{alias_name}(*args, &block) end end - end + EOF end end end diff --git a/lib/gitlab/metrics/subscribers/method_call.rb b/lib/gitlab/metrics/subscribers/method_call.rb index 1606134b7e5..0094ed0dc6a 100644 --- a/lib/gitlab/metrics/subscribers/method_call.rb +++ b/lib/gitlab/metrics/subscribers/method_call.rb @@ -10,7 +10,7 @@ module Gitlab def instance_method(event) return unless current_transaction - label = "#{event.payload[:module].name}##{event.payload[:name]}" + label = "#{event.payload[:module]}##{event.payload[:name]}" add_metric(label, event.duration) end @@ -18,7 +18,7 @@ module Gitlab def class_method(event) return unless current_transaction - label = "#{event.payload[:module].name}.#{event.payload[:name]}" + label = "#{event.payload[:module]}.#{event.payload[:name]}" add_metric(label, event.duration) end diff --git a/spec/lib/gitlab/metrics/instrumentation_spec.rb b/spec/lib/gitlab/metrics/instrumentation_spec.rb index eb31c9e52cd..3e7e9869e30 100644 --- a/spec/lib/gitlab/metrics/instrumentation_spec.rb +++ b/spec/lib/gitlab/metrics/instrumentation_spec.rb @@ -11,6 +11,8 @@ describe Gitlab::Metrics::Instrumentation do text end end + + allow(@dummy).to receive(:name).and_return('Dummy') end describe '.instrument_method' do @@ -31,7 +33,7 @@ describe Gitlab::Metrics::Instrumentation do it 'fires an ActiveSupport notification upon calling the method' do expect(ActiveSupport::Notifications).to receive(:instrument). - with('class_method.method_call', module: @dummy, name: :foo) + with('class_method.method_call', module: 'Dummy', name: :foo) @dummy.foo end @@ -69,7 +71,7 @@ describe Gitlab::Metrics::Instrumentation do it 'fires an ActiveSupport notification upon calling the method' do expect(ActiveSupport::Notifications).to receive(:instrument). - with('instance_method.method_call', module: @dummy, name: :bar) + with('instance_method.method_call', module: 'Dummy', name: :bar) @dummy.new.bar end diff --git a/spec/lib/gitlab/metrics/subscribers/method_call_spec.rb b/spec/lib/gitlab/metrics/subscribers/method_call_spec.rb index 65de95d6d1e..5c76eb3ba50 100644 --- a/spec/lib/gitlab/metrics/subscribers/method_call_spec.rb +++ b/spec/lib/gitlab/metrics/subscribers/method_call_spec.rb @@ -6,8 +6,7 @@ describe Gitlab::Metrics::Subscribers::MethodCall do let(:subscriber) { described_class.new } let(:event) do - double(:event, duration: 0.2, - payload: { module: double(:mod, name: 'Foo'), name: :foo }) + double(:event, duration: 0.2, payload: { module: 'Foo', name: :foo }) end before do -- cgit v1.2.1 From 1b077d2d81bd25fe37492ea56c8bd884f944ce52 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Thu, 10 Dec 2015 15:16:56 +0100 Subject: 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). --- config/initializers/metrics.rb | 1 - lib/gitlab/metrics/instrumentation.rb | 37 +++++++++++++++---- lib/gitlab/metrics/subscribers/method_call.rb | 42 ---------------------- spec/lib/gitlab/metrics/instrumentation_spec.rb | 22 ++++++++---- .../gitlab/metrics/subscribers/method_call_spec.rb | 40 --------------------- 5 files changed, 47 insertions(+), 95 deletions(-) delete mode 100644 lib/gitlab/metrics/subscribers/method_call.rb delete mode 100644 spec/lib/gitlab/metrics/subscribers/method_call_spec.rb diff --git a/config/initializers/metrics.rb b/config/initializers/metrics.rb index bde04232725..556e968137e 100644 --- a/config/initializers/metrics.rb +++ b/config/initializers/metrics.rb @@ -7,7 +7,6 @@ if Gitlab::Metrics.enabled? # ActiveSupport. require 'gitlab/metrics/subscribers/action_view' require 'gitlab/metrics/subscribers/active_record' - require 'gitlab/metrics/subscribers/method_call' Gitlab::Application.configure do |config| config.middleware.use(Gitlab::Metrics::RackMiddleware) diff --git a/lib/gitlab/metrics/instrumentation.rb b/lib/gitlab/metrics/instrumentation.rb index 982e35adfc9..5b56f2e8513 100644 --- a/lib/gitlab/metrics/instrumentation.rb +++ b/lib/gitlab/metrics/instrumentation.rb @@ -9,6 +9,8 @@ module Gitlab # # Gitlab::Metrics::Instrumentation.instrument_method(User, :by_login) module Instrumentation + SERIES = 'method_calls' + # Instruments a class method. # # mod - The module to instrument as a Module/Class. @@ -31,19 +33,42 @@ module Gitlab alias_name = "_original_#{name}" 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 alias_method :#{alias_name}, :#{name} def #{name}(*args, &block) - ActiveSupport::Notifications - .instrument("#{type}_method.method_call", - module: #{mod.name.inspect}, - name: #{name.inspect}) do - #{alias_name}(*args, &block) - end + trans = Gitlab::Metrics::Instrumentation.transaction + + if trans + start = Time.now + retval = #{alias_name}(*args, &block) + 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 EOF end + + # Small layer of indirection to make it easier to stub out the current + # transaction. + def self.transaction + Transaction.current + end end end end diff --git a/lib/gitlab/metrics/subscribers/method_call.rb b/lib/gitlab/metrics/subscribers/method_call.rb deleted file mode 100644 index 0094ed0dc6a..00000000000 --- a/lib/gitlab/metrics/subscribers/method_call.rb +++ /dev/null @@ -1,42 +0,0 @@ -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 diff --git a/spec/lib/gitlab/metrics/instrumentation_spec.rb b/spec/lib/gitlab/metrics/instrumentation_spec.rb index 3e7e9869e30..9308fb157d8 100644 --- a/spec/lib/gitlab/metrics/instrumentation_spec.rb +++ b/spec/lib/gitlab/metrics/instrumentation_spec.rb @@ -1,6 +1,8 @@ require 'spec_helper' describe Gitlab::Metrics::Instrumentation do + let(:transaction) { Gitlab::Metrics::Transaction.new } + before do @dummy = Class.new do def self.foo(text = 'foo') @@ -31,9 +33,13 @@ describe Gitlab::Metrics::Instrumentation do expect(@dummy.foo).to eq('foo') end - it 'fires an ActiveSupport notification upon calling the method' do - expect(ActiveSupport::Notifications).to receive(:instrument). - with('class_method.method_call', module: 'Dummy', name: :foo) + it 'tracks the call duration upon calling the method' do + allow(Gitlab::Metrics::Instrumentation).to receive(:transaction). + and_return(transaction) + + expect(transaction).to receive(:add_metric). + with(described_class::SERIES, an_instance_of(Hash), + method: 'Dummy.foo') @dummy.foo end @@ -69,9 +75,13 @@ describe Gitlab::Metrics::Instrumentation do expect(@dummy.new.bar).to eq('bar') end - it 'fires an ActiveSupport notification upon calling the method' do - expect(ActiveSupport::Notifications).to receive(:instrument). - with('instance_method.method_call', module: 'Dummy', name: :bar) + it 'tracks the call duration upon calling the method' do + allow(Gitlab::Metrics::Instrumentation).to receive(:transaction). + and_return(transaction) + + expect(transaction).to receive(:add_metric). + with(described_class::SERIES, an_instance_of(Hash), + method: 'Dummy#bar') @dummy.new.bar end diff --git a/spec/lib/gitlab/metrics/subscribers/method_call_spec.rb b/spec/lib/gitlab/metrics/subscribers/method_call_spec.rb deleted file mode 100644 index 5c76eb3ba50..00000000000 --- a/spec/lib/gitlab/metrics/subscribers/method_call_spec.rb +++ /dev/null @@ -1,40 +0,0 @@ -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 -- cgit v1.2.1 From ad69ba57d6e7d52b2a44a20393c072538c299653 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Thu, 10 Dec 2015 16:15:02 +0100 Subject: Proper method instrumentation for special symbols This ensures that methods such as "==" can be instrumented without producing syntax errors. --- lib/gitlab/metrics/instrumentation.rb | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/lib/gitlab/metrics/instrumentation.rb b/lib/gitlab/metrics/instrumentation.rb index 5b56f2e8513..2ed75495650 100644 --- a/lib/gitlab/metrics/instrumentation.rb +++ b/lib/gitlab/metrics/instrumentation.rb @@ -30,7 +30,8 @@ module Gitlab def self.instrument(type, mod, name) return unless Metrics.enabled? - alias_name = "_original_#{name}" + name = name.to_sym + alias_name = :"_original_#{name}" target = type == :instance ? mod : mod.singleton_class if type == :instance @@ -42,14 +43,14 @@ module Gitlab end target.class_eval <<-EOF, __FILE__, __LINE__ + 1 - alias_method :#{alias_name}, :#{name} + alias_method #{alias_name.inspect}, #{name.inspect} def #{name}(*args, &block) trans = Gitlab::Metrics::Instrumentation.transaction if trans start = Time.now - retval = #{alias_name}(*args, &block) + retval = duration = (Time.now - start) * 1000.0 trans.add_metric(Gitlab::Metrics::Instrumentation::SERIES, @@ -58,7 +59,7 @@ module Gitlab retval else - #{alias_name}(*args, &block) + __send__(#{alias_name.inspect}, *args, &block) end end EOF -- cgit v1.2.1 From 5dbcb635a17aff6543150a66b597c75b819801e2 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Thu, 10 Dec 2015 16:15:46 +0100 Subject: Methods for instrumenting multiple methods The methods Instrumentation.instrument_methods and Instrumentation.instrument_instance_methods can be used to instrument all methods of a module at once. --- lib/gitlab/metrics/instrumentation.rb | 23 +++++++++++++++++ spec/lib/gitlab/metrics/instrumentation_spec.rb | 34 +++++++++++++++++++++---- 2 files changed, 52 insertions(+), 5 deletions(-) diff --git a/lib/gitlab/metrics/instrumentation.rb b/lib/gitlab/metrics/instrumentation.rb index 2ed75495650..12d5ede4be3 100644 --- a/lib/gitlab/metrics/instrumentation.rb +++ b/lib/gitlab/metrics/instrumentation.rb @@ -27,6 +27,29 @@ module Gitlab instrument(:instance, mod, name) end + # Instruments all public methods of a module. + # + # mod - The module to instrument. + def self.instrument_methods(mod) + mod.public_methods(false).each do |name| + instrument_method(mod, name) + end + end + + # Instruments all public instance methods of a module. + # + # mod - The module to instrument. + def self.instrument_instance_methods(mod) + mod.public_instance_methods(false).each do |name| + instrument_instance_method(mod, name) + end + end + + # Instruments a method. + # + # type - The type (:class or :instance) of method to instrument. + # mod - The module containing the method. + # name - The name of the method to instrument. def self.instrument(type, mod, name) return unless Metrics.enabled? diff --git a/spec/lib/gitlab/metrics/instrumentation_spec.rb b/spec/lib/gitlab/metrics/instrumentation_spec.rb index 9308fb157d8..5427bacdc94 100644 --- a/spec/lib/gitlab/metrics/instrumentation_spec.rb +++ b/spec/lib/gitlab/metrics/instrumentation_spec.rb @@ -34,7 +34,7 @@ describe Gitlab::Metrics::Instrumentation do end it 'tracks the call duration upon calling the method' do - allow(Gitlab::Metrics::Instrumentation).to receive(:transaction). + allow(described_class).to receive(:transaction). and_return(transaction) expect(transaction).to receive(:add_metric). @@ -51,7 +51,7 @@ describe Gitlab::Metrics::Instrumentation do end it 'does not instrument the method' do - Gitlab::Metrics::Instrumentation.instrument_method(@dummy, :foo) + described_class.instrument_method(@dummy, :foo) expect(@dummy).to_not respond_to(:_original_foo) end @@ -63,7 +63,7 @@ describe Gitlab::Metrics::Instrumentation do before do allow(Gitlab::Metrics).to receive(:enabled?).and_return(true) - Gitlab::Metrics::Instrumentation. + described_class. instrument_instance_method(@dummy, :bar) end @@ -76,7 +76,7 @@ describe Gitlab::Metrics::Instrumentation do end it 'tracks the call duration upon calling the method' do - allow(Gitlab::Metrics::Instrumentation).to receive(:transaction). + allow(described_class).to receive(:transaction). and_return(transaction) expect(transaction).to receive(:add_metric). @@ -93,11 +93,35 @@ describe Gitlab::Metrics::Instrumentation do end it 'does not instrument the method' do - Gitlab::Metrics::Instrumentation. + described_class. instrument_instance_method(@dummy, :bar) expect(@dummy.method_defined?(:_original_bar)).to eq(false) end end end + + describe '.instrument_methods' do + before do + allow(Gitlab::Metrics).to receive(:enabled?).and_return(true) + end + + it 'instruments all public class methods' do + described_class.instrument_methods(@dummy) + + expect(@dummy).to respond_to(:_original_foo) + end + end + + describe '.instrument_instance_methods' do + before do + allow(Gitlab::Metrics).to receive(:enabled?).and_return(true) + end + + it 'instruments all public instance methods' do + described_class.instrument_instance_methods(@dummy) + + expect(@dummy.method_defined?(:_original_bar)).to eq(true) + end + end end -- cgit v1.2.1 From f43f3b89a633b5ceee4e71acba0c83ed5cb28963 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Thu, 10 Dec 2015 16:16:48 +0100 Subject: Added Instrumentation.configure This makes it easier to instrument multiple modules without having to type the full namespace over and over again. --- lib/gitlab/metrics/instrumentation.rb | 4 ++++ spec/lib/gitlab/metrics/instrumentation_spec.rb | 10 +++++++++- 2 files changed, 13 insertions(+), 1 deletion(-) diff --git a/lib/gitlab/metrics/instrumentation.rb b/lib/gitlab/metrics/instrumentation.rb index 12d5ede4be3..8822a907967 100644 --- a/lib/gitlab/metrics/instrumentation.rb +++ b/lib/gitlab/metrics/instrumentation.rb @@ -11,6 +11,10 @@ module Gitlab module Instrumentation SERIES = 'method_calls' + def self.configure + yield self + end + # Instruments a class method. # # mod - The module to instrument as a Module/Class. diff --git a/spec/lib/gitlab/metrics/instrumentation_spec.rb b/spec/lib/gitlab/metrics/instrumentation_spec.rb index 5427bacdc94..fdb0820b875 100644 --- a/spec/lib/gitlab/metrics/instrumentation_spec.rb +++ b/spec/lib/gitlab/metrics/instrumentation_spec.rb @@ -17,12 +17,20 @@ describe Gitlab::Metrics::Instrumentation do allow(@dummy).to receive(:name).and_return('Dummy') end + describe '.configure' do + it 'yields self' do + described_class.configure do |c| + expect(c).to eq(described_class) + end + end + end + describe '.instrument_method' do describe 'with metrics enabled' do before do allow(Gitlab::Metrics).to receive(:enabled?).and_return(true) - Gitlab::Metrics::Instrumentation.instrument_method(@dummy, :foo) + described_class.instrument_method(@dummy, :foo) end it 'renames the original method' do -- cgit v1.2.1 From 641761f1d6af5a94c0007e8d7463ee86fc047229 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Thu, 10 Dec 2015 16:25:28 +0100 Subject: Only instrument methods defined directly When using instrument_methods/instrument_instance_methods we only want to instrument methods defined directly in a class, not those included via mixins (e.g. whatever RSpec throws in during development). In case an externally included method _has_ to be instrumented we can still use the regular instrument_method/instrument_instance_method methods. --- lib/gitlab/metrics/instrumentation.rb | 10 +++++++--- spec/lib/gitlab/metrics/instrumentation_spec.rb | 26 +++++++++++++++++++++++++ 2 files changed, 33 insertions(+), 3 deletions(-) diff --git a/lib/gitlab/metrics/instrumentation.rb b/lib/gitlab/metrics/instrumentation.rb index 8822a907967..cf22aa93cdd 100644 --- a/lib/gitlab/metrics/instrumentation.rb +++ b/lib/gitlab/metrics/instrumentation.rb @@ -36,7 +36,9 @@ module Gitlab # mod - The module to instrument. def self.instrument_methods(mod) mod.public_methods(false).each do |name| - instrument_method(mod, name) + method = mod.method(name) + + instrument_method(mod, name) if method.owner == mod.singleton_class end end @@ -45,7 +47,9 @@ module Gitlab # mod - The module to instrument. def self.instrument_instance_methods(mod) mod.public_instance_methods(false).each do |name| - instrument_instance_method(mod, name) + method = mod.instance_method(name) + + instrument_instance_method(mod, name) if method.owner == mod end end @@ -77,7 +81,7 @@ module Gitlab if trans start = Time.now - retval = + retval = __send__(#{alias_name.inspect}, *args, &block) duration = (Time.now - start) * 1000.0 trans.add_metric(Gitlab::Metrics::Instrumentation::SERIES, diff --git a/spec/lib/gitlab/metrics/instrumentation_spec.rb b/spec/lib/gitlab/metrics/instrumentation_spec.rb index fdb0820b875..80dc160ebd2 100644 --- a/spec/lib/gitlab/metrics/instrumentation_spec.rb +++ b/spec/lib/gitlab/metrics/instrumentation_spec.rb @@ -119,6 +119,19 @@ describe Gitlab::Metrics::Instrumentation do expect(@dummy).to respond_to(:_original_foo) end + + it 'only instruments methods directly defined in the module' do + mod = Module.new do + def kittens + end + end + + @dummy.extend(mod) + + described_class.instrument_methods(@dummy) + + expect(@dummy).to_not respond_to(:_original_kittens) + end end describe '.instrument_instance_methods' do @@ -131,5 +144,18 @@ describe Gitlab::Metrics::Instrumentation do expect(@dummy.method_defined?(:_original_bar)).to eq(true) end + + it 'only instruments methods directly defined in the module' do + mod = Module.new do + def kittens + end + end + + @dummy.include(mod) + + described_class.instrument_instance_methods(@dummy) + + expect(@dummy.method_defined?(:_original_kittens)).to eq(false) + end end end -- cgit v1.2.1 From 6dc25ad58c7bf2218cdda6d60061111a5365affb Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Thu, 10 Dec 2015 17:09:20 +0100 Subject: Instrument Gitlab::Shel and Gitlab::Git --- config/initializers/metrics.rb | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/config/initializers/metrics.rb b/config/initializers/metrics.rb index 556e968137e..0ac4299dcba 100644 --- a/config/initializers/metrics.rb +++ b/config/initializers/metrics.rb @@ -18,6 +18,18 @@ if Gitlab::Metrics.enabled? end end + Gitlab::Metrics::Instrumentation.configure do |config| + config.instrument_instance_methods(Gitlab::Shell) + + config.instrument_methods(Gitlab::Git) + + Gitlab::Git.constants.each do |name| + const = Gitlab::Git.const_get(name) + + config.instrument_methods(const) if const.is_a?(Module) + end + end + GC::Profiler.enable Gitlab::Metrics::Sampler.new.start -- cgit v1.2.1 From 09a311568abee739fae0c2577a9cf6aa01516977 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Thu, 10 Dec 2015 17:48:14 +0100 Subject: Track object count types as tags --- lib/gitlab/metrics/sampler.rb | 4 +++- spec/lib/gitlab/metrics/sampler_spec.rb | 3 ++- 2 files changed, 5 insertions(+), 2 deletions(-) diff --git a/lib/gitlab/metrics/sampler.rb b/lib/gitlab/metrics/sampler.rb index 141953dc985..03afa6324dd 100644 --- a/lib/gitlab/metrics/sampler.rb +++ b/lib/gitlab/metrics/sampler.rb @@ -53,7 +53,9 @@ module Gitlab end def sample_objects - @metrics << Metric.new('object_counts', ObjectSpace.count_objects) + ObjectSpace.count_objects.each do |type, count| + @metrics << Metric.new('object_counts', { count: count }, type: type) + end end def sample_gc diff --git a/spec/lib/gitlab/metrics/sampler_spec.rb b/spec/lib/gitlab/metrics/sampler_spec.rb index b486d38870f..319f287178d 100644 --- a/spec/lib/gitlab/metrics/sampler_spec.rb +++ b/spec/lib/gitlab/metrics/sampler_spec.rb @@ -71,7 +71,8 @@ describe Gitlab::Metrics::Sampler do describe '#sample_objects' do it 'adds a metric containing the amount of allocated objects' do expect(Gitlab::Metrics::Metric).to receive(:new). - with('object_counts', an_instance_of(Hash)). + with('object_counts', an_instance_of(Hash), an_instance_of(Hash)). + at_least(:once). and_call_original sampler.sample_objects -- cgit v1.2.1 From f932b781a79d9b829001c39bc214372b7efd8610 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Mon, 14 Dec 2015 12:31:56 +0100 Subject: Replace double quotes when obfuscating SQL InfluxDB escapes double quotes upon output which makes it a pain to deal with. This ensures that if we're using PostgreSQL we don't store any queries containing double quotes in InfluxDB, solving the escaping problem. --- lib/gitlab/metrics/obfuscated_sql.rb | 10 +++++++++- spec/lib/gitlab/metrics/obfuscated_sql_spec.rb | 8 ++++++++ 2 files changed, 17 insertions(+), 1 deletion(-) diff --git a/lib/gitlab/metrics/obfuscated_sql.rb b/lib/gitlab/metrics/obfuscated_sql.rb index 45f2e2bc62a..7b15670aa6b 100644 --- a/lib/gitlab/metrics/obfuscated_sql.rb +++ b/lib/gitlab/metrics/obfuscated_sql.rb @@ -30,9 +30,17 @@ module Gitlab regex = Regexp.union(regex, MYSQL_REPLACEMENTS) end - @sql.gsub(regex, '?').gsub(CONSECUTIVE) do |match| + sql = @sql.gsub(regex, '?').gsub(CONSECUTIVE) do |match| "#{match.count(',') + 1} values" end + + # InfluxDB escapes double quotes upon output, so lets get rid of them + # whenever we can. + if Gitlab::Database.postgresql? + sql = sql.gsub('"', '') + end + + sql end end end diff --git a/spec/lib/gitlab/metrics/obfuscated_sql_spec.rb b/spec/lib/gitlab/metrics/obfuscated_sql_spec.rb index 6e9b62016d6..0f01ee588c9 100644 --- a/spec/lib/gitlab/metrics/obfuscated_sql_spec.rb +++ b/spec/lib/gitlab/metrics/obfuscated_sql_spec.rb @@ -75,5 +75,13 @@ describe Gitlab::Metrics::ObfuscatedSQL do expect(sql.to_s).to eq('SELECT x FROM y WHERE z IN (2 values)') end end + + if Gitlab::Database.postgresql? + it 'replaces double quotes' do + sql = described_class.new('SELECT "x" FROM "y"') + + expect(sql.to_s).to eq('SELECT x FROM y') + end + end end end -- cgit v1.2.1 From d0352e6604915a1a94fbe84252d1606f5adac57c Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Mon, 14 Dec 2015 12:32:30 +0100 Subject: Added specs for MetricsWorker --- spec/workers/metrics_worker_spec.rb | 40 +++++++++++++++++++++++++++++++++++++ 1 file changed, 40 insertions(+) create mode 100644 spec/workers/metrics_worker_spec.rb diff --git a/spec/workers/metrics_worker_spec.rb b/spec/workers/metrics_worker_spec.rb new file mode 100644 index 00000000000..0d12516c1a3 --- /dev/null +++ b/spec/workers/metrics_worker_spec.rb @@ -0,0 +1,40 @@ +require 'spec_helper' + +describe MetricsWorker do + let(:worker) { described_class.new } + + describe '#perform' do + it 'prepares and writes the metrics to InfluxDB' do + connection = double(:connection) + pool = double(:pool) + + expect(pool).to receive(:with).and_yield(connection) + expect(connection).to receive(:write_points).with(an_instance_of(Array)) + expect(Gitlab::Metrics).to receive(:pool).and_return(pool) + + worker.perform([{ 'series' => 'kittens', 'tags' => {} }]) + end + end + + describe '#prepare_metrics' do + it 'returns a Hash with the keys as Symbols' do + metrics = worker.prepare_metrics([{ 'values' => {}, 'tags' => {} }]) + + expect(metrics).to eq([{ values: {}, tags: {} }]) + end + + it 'escapes tag values' do + metrics = worker.prepare_metrics([ + { 'values' => {}, 'tags' => { 'foo' => 'bar=' } } + ]) + + expect(metrics).to eq([{ values: {}, tags: { 'foo' => 'bar\\=' } }]) + end + end + + describe '#escape_value' do + it 'escapes an equals sign' do + expect(worker.escape_value('foo=')).to eq('foo\\=') + end + end +end -- cgit v1.2.1 From 9f95ff0d90802467a04816f1d38e30770a026820 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Mon, 14 Dec 2015 16:51:38 +0100 Subject: Track location information as tags This allows the information to be displayed when using certain functions (e.g. top()) as well as making it easier to aggregate on a per file basis. --- lib/gitlab/metrics/subscribers/action_view.rb | 17 +++++++++++------ lib/gitlab/metrics/subscribers/active_record.rb | 17 +++++++++++------ spec/lib/gitlab/metrics/subscribers/action_view_spec.rb | 9 +++++++-- .../gitlab/metrics/subscribers/active_record_spec.rb | 5 +++-- 4 files changed, 32 insertions(+), 16 deletions(-) diff --git a/lib/gitlab/metrics/subscribers/action_view.rb b/lib/gitlab/metrics/subscribers/action_view.rb index 2e88e4bea6a..7e0dcf99d92 100644 --- a/lib/gitlab/metrics/subscribers/action_view.rb +++ b/lib/gitlab/metrics/subscribers/action_view.rb @@ -16,10 +16,10 @@ module Gitlab private def track(event) - path = relative_path(event.payload[:identifier]) values = values_for(event) + tags = tags_for(event) - current_transaction.add_metric(SERIES, values, path: path) + current_transaction.add_metric(SERIES, values, tags) end def relative_path(path) @@ -27,16 +27,21 @@ module Gitlab end def values_for(event) - values = { duration: event.duration } + { duration: event.duration } + end + + def tags_for(event) + path = relative_path(event.payload[:identifier]) + tags = { view: path } file, line = Metrics.last_relative_application_frame if file and line - values[:file] = file - values[:line] = line + tags[:file] = file + tags[:line] = line end - values + tags end def current_transaction diff --git a/lib/gitlab/metrics/subscribers/active_record.rb b/lib/gitlab/metrics/subscribers/active_record.rb index 3cc9b1addf6..d947c128ce2 100644 --- a/lib/gitlab/metrics/subscribers/active_record.rb +++ b/lib/gitlab/metrics/subscribers/active_record.rb @@ -13,25 +13,30 @@ module Gitlab def sql(event) return unless current_transaction - sql = ObfuscatedSQL.new(event.payload[:sql]).to_s values = values_for(event) + tags = tags_for(event) - current_transaction.add_metric(SERIES, values, sql: sql) + current_transaction.add_metric(SERIES, values, tags) end private def values_for(event) - values = { duration: event.duration } + { duration: event.duration } + end + + def tags_for(event) + sql = ObfuscatedSQL.new(event.payload[:sql]).to_s + tags = { sql: sql } file, line = Metrics.last_relative_application_frame if file and line - values[:file] = file - values[:line] = line + tags[:file] = file + tags[:line] = line end - values + tags end def current_transaction diff --git a/spec/lib/gitlab/metrics/subscribers/action_view_spec.rb b/spec/lib/gitlab/metrics/subscribers/action_view_spec.rb index 77f3e69d523..c6cd584663f 100644 --- a/spec/lib/gitlab/metrics/subscribers/action_view_spec.rb +++ b/spec/lib/gitlab/metrics/subscribers/action_view_spec.rb @@ -21,10 +21,15 @@ describe Gitlab::Metrics::Subscribers::ActionView do describe '#render_template' do it 'tracks rendering of a template' do - values = { duration: 2.1, file: 'app/views/x.html.haml', line: 4 } + values = { duration: 2.1 } + tags = { + view: 'app/views/x.html.haml', + file: 'app/views/x.html.haml', + line: 4 + } expect(transaction).to receive(:add_metric). - with(described_class::SERIES, values, path: 'app/views/x.html.haml') + with(described_class::SERIES, values, tags) subscriber.render_template(event) end diff --git a/spec/lib/gitlab/metrics/subscribers/active_record_spec.rb b/spec/lib/gitlab/metrics/subscribers/active_record_spec.rb index 58e8e84df9b..05b6cc14716 100644 --- a/spec/lib/gitlab/metrics/subscribers/active_record_spec.rb +++ b/spec/lib/gitlab/metrics/subscribers/active_record_spec.rb @@ -19,11 +19,12 @@ describe Gitlab::Metrics::Subscribers::ActiveRecord do describe '#sql' do it 'tracks the execution of a SQL query' do - values = { duration: 0.2, file: 'app/models/foo.rb', line: 4 } sql = 'SELECT * FROM users WHERE id = ?' + values = { duration: 0.2 } + tags = { sql: sql, file: 'app/models/foo.rb', line: 4 } expect(transaction).to receive(:add_metric). - with(described_class::SERIES, values, sql: sql) + with(described_class::SERIES, values, tags) subscriber.sql(event) end -- cgit v1.2.1 From 5142c61707cc4169a3f8d9e378aacb8f88760db5 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Mon, 14 Dec 2015 16:52:05 +0100 Subject: Cast values to strings before escaping them This ensures that e.g. line numbers used in tags are first casted to strings. --- app/workers/metrics_worker.rb | 2 +- spec/workers/metrics_worker_spec.rb | 4 ++++ 2 files changed, 5 insertions(+), 1 deletion(-) diff --git a/app/workers/metrics_worker.rb b/app/workers/metrics_worker.rb index 8fffe371572..90a65579382 100644 --- a/app/workers/metrics_worker.rb +++ b/app/workers/metrics_worker.rb @@ -24,6 +24,6 @@ class MetricsWorker end def escape_value(value) - value.gsub('=', '\\=') + value.to_s.gsub('=', '\\=') end end diff --git a/spec/workers/metrics_worker_spec.rb b/spec/workers/metrics_worker_spec.rb index 0d12516c1a3..f5650494c7c 100644 --- a/spec/workers/metrics_worker_spec.rb +++ b/spec/workers/metrics_worker_spec.rb @@ -36,5 +36,9 @@ describe MetricsWorker do it 'escapes an equals sign' do expect(worker.escape_value('foo=')).to eq('foo\\=') end + + it 'casts values to Strings' do + expect(worker.escape_value(10)).to eq('10') + end end end -- cgit v1.2.1 From d67e2045a02d105bfbc7abf1805fe477eb9155ca Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Mon, 14 Dec 2015 17:37:20 +0100 Subject: Drop empty tag values from metrics InfluxDB throws an error when trying to store a list of tags where one or more have an empty value. --- app/workers/metrics_worker.rb | 6 +++++- spec/workers/metrics_worker_spec.rb | 8 ++++++++ 2 files changed, 13 insertions(+), 1 deletion(-) diff --git a/app/workers/metrics_worker.rb b/app/workers/metrics_worker.rb index 90a65579382..b15dc819c5c 100644 --- a/app/workers/metrics_worker.rb +++ b/app/workers/metrics_worker.rb @@ -16,7 +16,11 @@ class MetricsWorker new_hash = hash.symbolize_keys new_hash[:tags].each do |key, value| - new_hash[:tags][key] = escape_value(value) + if value.blank? + new_hash[:tags].delete(key) + else + new_hash[:tags][key] = escape_value(value) + end end new_hash diff --git a/spec/workers/metrics_worker_spec.rb b/spec/workers/metrics_worker_spec.rb index f5650494c7c..2acd0f8ba30 100644 --- a/spec/workers/metrics_worker_spec.rb +++ b/spec/workers/metrics_worker_spec.rb @@ -30,6 +30,14 @@ describe MetricsWorker do expect(metrics).to eq([{ values: {}, tags: { 'foo' => 'bar\\=' } }]) end + + it 'drops empty tags' do + metrics = worker.prepare_metrics([ + { 'values' => {}, 'tags' => { 'cats' => '', 'dogs' => nil }} + ]) + + expect(metrics).to eq([{ values: {}, tags: {} }]) + end end describe '#escape_value' do -- cgit v1.2.1 From 13dbd663acbbe91ddac77b650a90377cd12c54b8 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Tue, 15 Dec 2015 16:31:24 +0100 Subject: Allow filtering of what methods to instrument This makes it possible to determine if a method should be instrumented or not using a block. --- lib/gitlab/metrics/instrumentation.rb | 19 +++++++++++++++++-- spec/lib/gitlab/metrics/instrumentation_spec.rb | 16 ++++++++++++++++ 2 files changed, 33 insertions(+), 2 deletions(-) diff --git a/lib/gitlab/metrics/instrumentation.rb b/lib/gitlab/metrics/instrumentation.rb index cf22aa93cdd..91e09694cd8 100644 --- a/lib/gitlab/metrics/instrumentation.rb +++ b/lib/gitlab/metrics/instrumentation.rb @@ -33,23 +33,38 @@ module Gitlab # Instruments all public methods of a module. # + # This method optionally takes a block that can be used to determine if a + # method should be instrumented or not. The block is passed the receiving + # module and an UnboundMethod. If the block returns a non truthy value the + # method is not instrumented. + # # mod - The module to instrument. def self.instrument_methods(mod) mod.public_methods(false).each do |name| method = mod.method(name) - instrument_method(mod, name) if method.owner == mod.singleton_class + if method.owner == mod.singleton_class + if !block_given? || block_given? && yield(mod, method) + instrument_method(mod, name) + end + end end end # Instruments all public instance methods of a module. # + # See `instrument_methods` for more information. + # # mod - The module to instrument. def self.instrument_instance_methods(mod) mod.public_instance_methods(false).each do |name| method = mod.instance_method(name) - instrument_instance_method(mod, name) if method.owner == mod + if method.owner == mod + if !block_given? || block_given? && yield(mod, method) + instrument_instance_method(mod, name) + end + end end end diff --git a/spec/lib/gitlab/metrics/instrumentation_spec.rb b/spec/lib/gitlab/metrics/instrumentation_spec.rb index 80dc160ebd2..5fe7a369cba 100644 --- a/spec/lib/gitlab/metrics/instrumentation_spec.rb +++ b/spec/lib/gitlab/metrics/instrumentation_spec.rb @@ -132,6 +132,14 @@ describe Gitlab::Metrics::Instrumentation do expect(@dummy).to_not respond_to(:_original_kittens) end + + it 'can take a block to determine if a method should be instrumented' do + described_class.instrument_methods(@dummy) do + false + end + + expect(@dummy).to_not respond_to(:_original_foo) + end end describe '.instrument_instance_methods' do @@ -157,5 +165,13 @@ describe Gitlab::Metrics::Instrumentation do expect(@dummy.method_defined?(:_original_kittens)).to eq(false) end + + it 'can take a block to determine if a method should be instrumented' do + described_class.instrument_instance_methods(@dummy) do + false + end + + expect(@dummy.method_defined?(:_original_bar)).to eq(false) + end end end -- cgit v1.2.1 From a41287d8989d7d49b405fd8f658d6c6e4edfd307 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Tue, 15 Dec 2015 16:38:25 +0100 Subject: Only track method calls above a certain threshold This ensures we don't end up wasting resources by tracking method calls that only take a few microseconds. By default the threshold is 10 milliseconds but this can be changed using the gitlab.yml configuration file. --- config/gitlab.yml.example | 3 +++ lib/gitlab/metrics.rb | 4 ++++ lib/gitlab/metrics/instrumentation.rb | 8 +++++--- spec/lib/gitlab/metrics/instrumentation_spec.rb | 24 ++++++++++++++++++++++++ 4 files changed, 36 insertions(+), 3 deletions(-) diff --git a/config/gitlab.yml.example b/config/gitlab.yml.example index 38b0920890f..24f3f6f02dc 100644 --- a/config/gitlab.yml.example +++ b/config/gitlab.yml.example @@ -432,6 +432,9 @@ production: &base # pool_size: 16 # The timeout of a connection in seconds. # timeout: 10 + # The minimum amount of milliseconds a method call has to take before it's + # tracked. Defaults to 10. + # method_call_threshold: 10 development: <<: *base diff --git a/lib/gitlab/metrics.rb b/lib/gitlab/metrics.rb index 007429fa194..4b92c3244fa 100644 --- a/lib/gitlab/metrics.rb +++ b/lib/gitlab/metrics.rb @@ -16,6 +16,10 @@ module Gitlab !!Settings.metrics['enabled'] end + def self.method_call_threshold + Settings.metrics['method_call_threshold'] || 10 + end + def self.pool @pool end diff --git a/lib/gitlab/metrics/instrumentation.rb b/lib/gitlab/metrics/instrumentation.rb index 91e09694cd8..ca2dffbc46a 100644 --- a/lib/gitlab/metrics/instrumentation.rb +++ b/lib/gitlab/metrics/instrumentation.rb @@ -99,9 +99,11 @@ module Gitlab retval = __send__(#{alias_name.inspect}, *args, &block) duration = (Time.now - start) * 1000.0 - trans.add_metric(Gitlab::Metrics::Instrumentation::SERIES, - { duration: duration }, - method: #{label.inspect}) + if duration >= Gitlab::Metrics.method_call_threshold + trans.add_metric(Gitlab::Metrics::Instrumentation::SERIES, + { duration: duration }, + method: #{label.inspect}) + end retval else diff --git a/spec/lib/gitlab/metrics/instrumentation_spec.rb b/spec/lib/gitlab/metrics/instrumentation_spec.rb index 5fe7a369cba..71d7209db0f 100644 --- a/spec/lib/gitlab/metrics/instrumentation_spec.rb +++ b/spec/lib/gitlab/metrics/instrumentation_spec.rb @@ -42,6 +42,9 @@ describe Gitlab::Metrics::Instrumentation do end it 'tracks the call duration upon calling the method' do + allow(Gitlab::Metrics).to receive(:method_call_threshold). + and_return(0) + allow(described_class).to receive(:transaction). and_return(transaction) @@ -51,6 +54,15 @@ describe Gitlab::Metrics::Instrumentation do @dummy.foo end + + it 'does not track method calls below a given duration threshold' do + allow(Gitlab::Metrics).to receive(:method_call_threshold). + and_return(100) + + expect(transaction).to_not receive(:add_metric) + + @dummy.foo + end end describe 'with metrics disabled' do @@ -84,6 +96,9 @@ describe Gitlab::Metrics::Instrumentation do end it 'tracks the call duration upon calling the method' do + allow(Gitlab::Metrics).to receive(:method_call_threshold). + and_return(0) + allow(described_class).to receive(:transaction). and_return(transaction) @@ -93,6 +108,15 @@ describe Gitlab::Metrics::Instrumentation do @dummy.new.bar end + + it 'does not track method calls below a given duration threshold' do + allow(Gitlab::Metrics).to receive(:method_call_threshold). + and_return(100) + + expect(transaction).to_not receive(:add_metric) + + @dummy.new.bar + end end describe 'with metrics disabled' do -- cgit v1.2.1 From a93a32a290c8e134763188ebd2b62935f5698e6c Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Tue, 15 Dec 2015 17:22:46 +0100 Subject: Support for instrumenting class hierarchies This will be used to (for example) instrument all ActiveRecord models. --- lib/gitlab/metrics/instrumentation.rb | 23 +++++++++++++++++ spec/lib/gitlab/metrics/instrumentation_spec.rb | 33 +++++++++++++++++++++++++ 2 files changed, 56 insertions(+) diff --git a/lib/gitlab/metrics/instrumentation.rb b/lib/gitlab/metrics/instrumentation.rb index ca2dffbc46a..06fc2f25948 100644 --- a/lib/gitlab/metrics/instrumentation.rb +++ b/lib/gitlab/metrics/instrumentation.rb @@ -31,6 +31,29 @@ module Gitlab instrument(:instance, mod, name) end + # Recursively instruments all subclasses of the given root module. + # + # This can be used to for example instrument all ActiveRecord models (as + # these all inherit from ActiveRecord::Base). + # + # This method can optionally take a block to pass to `instrument_methods` + # and `instrument_instance_methods`. + # + # root - The root module for which to instrument subclasses. The root + # module itself is not instrumented. + def self.instrument_class_hierarchy(root, &block) + visit = root.subclasses + + until visit.empty? + klass = visit.pop + + instrument_methods(klass, &block) + instrument_instance_methods(klass, &block) + + klass.subclasses.each { |c| visit << c } + end + end + # Instruments all public methods of a module. # # This method optionally takes a block that can be used to determine if a diff --git a/spec/lib/gitlab/metrics/instrumentation_spec.rb b/spec/lib/gitlab/metrics/instrumentation_spec.rb index 71d7209db0f..a7eab9d11cc 100644 --- a/spec/lib/gitlab/metrics/instrumentation_spec.rb +++ b/spec/lib/gitlab/metrics/instrumentation_spec.rb @@ -133,6 +133,39 @@ describe Gitlab::Metrics::Instrumentation do end end + describe '.instrument_class_hierarchy' do + before do + allow(Gitlab::Metrics).to receive(:enabled?).and_return(true) + + @child1 = Class.new(@dummy) do + def self.child1_foo; end + def child1_bar; end + end + + @child2 = Class.new(@child1) do + def self.child2_foo; end + def child2_bar; end + end + end + + it 'recursively instruments a class hierarchy' do + described_class.instrument_class_hierarchy(@dummy) + + expect(@child1).to respond_to(:_original_child1_foo) + expect(@child2).to respond_to(:_original_child2_foo) + + expect(@child1.method_defined?(:_original_child1_bar)).to eq(true) + expect(@child2.method_defined?(:_original_child2_bar)).to eq(true) + end + + it 'does not instrument the root module' do + described_class.instrument_class_hierarchy(@dummy) + + expect(@dummy).to_not respond_to(:_original_foo) + expect(@dummy.method_defined?(:_original_bar)).to eq(false) + end + end + describe '.instrument_methods' do before do allow(Gitlab::Metrics).to receive(:enabled?).and_return(true) -- cgit v1.2.1 From bcee44ad33d8a84822a8df068d47812594c445a3 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Tue, 15 Dec 2015 17:23:23 +0100 Subject: Instrument all ActiveRecord model methods This works by searching the raw source code for any references to commonly used ActiveRecord methods. While not bulletproof it saves us from having to list hundreds of methods by hand. It also ensures that (most) newly added methods are instrumented automatically. This _only_ instruments models defined in app/models, should a model reside somewhere else (e.g. somewhere in lib/) it _won't_ be instrumented. --- Gemfile | 1 + Gemfile.lock | 1 + config/initializers/metrics.rb | 21 +++++++++++++++++++++ 3 files changed, 23 insertions(+) diff --git a/Gemfile b/Gemfile index 90db2c43006..e9e5c7df075 100644 --- a/Gemfile +++ b/Gemfile @@ -210,6 +210,7 @@ gem 'net-ssh', '~> 3.0.1' # Metrics group :metrics do + gem 'method_source', '~> 0.8', require: false gem 'influxdb', '~> 0.2', require: false gem 'connection_pool', '~> 2.0', require: false end diff --git a/Gemfile.lock b/Gemfile.lock index 7d592ba93a7..3f301111224 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -887,6 +887,7 @@ DEPENDENCIES kaminari (~> 0.16.3) letter_opener (~> 1.1.2) mail_room (~> 0.6.1) + method_source (~> 0.8) minitest (~> 5.7.0) mousetrap-rails (~> 1.4.6) mysql2 (~> 0.3.16) diff --git a/config/initializers/metrics.rb b/config/initializers/metrics.rb index 0ac4299dcba..a47d2bf59a6 100644 --- a/config/initializers/metrics.rb +++ b/config/initializers/metrics.rb @@ -2,6 +2,7 @@ if Gitlab::Metrics.enabled? require 'influxdb' require 'socket' require 'connection_pool' + require 'method_source' # These are manually require'd so the classes are registered properly with # ActiveSupport. @@ -18,6 +19,26 @@ if Gitlab::Metrics.enabled? end end + # This instruments all methods residing in app/models that (appear to) use any + # of the ActiveRecord methods. This has to take place _after_ initializing as + # for some unknown reason calling eager_load! earlier breaks Devise. + Gitlab::Application.config.after_initialize do + Rails.application.eager_load! + + models = Rails.root.join('app', 'models').to_s + + regex = Regexp.union( + ActiveRecord::Querying.public_instance_methods(false).map(&:to_s) + ) + + Gitlab::Metrics::Instrumentation. + instrument_class_hierarchy(ActiveRecord::Base) do |_, method| + loc = method.source_location + + loc && loc[0].start_with?(models) && method.source =~ regex + end + end + Gitlab::Metrics::Instrumentation.configure do |config| config.instrument_instance_methods(Gitlab::Shell) -- cgit v1.2.1 From f181f05e8abd7b1066c11578193f6d7170764bf5 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Thu, 17 Dec 2015 17:17:18 +0100 Subject: Track object counts using the "allocations" Gem This allows us to track the counts of actual classes instead of "T_XXX" nodes. This is only enabled on CRuby as it uses CRuby specific APIs. --- Gemfile | 1 + Gemfile.lock | 2 ++ lib/gitlab/metrics.rb | 4 ++++ lib/gitlab/metrics/sampler.rb | 25 ++++++++++++++++++++++--- spec/lib/gitlab/metrics/sampler_spec.rb | 4 ++++ 5 files changed, 33 insertions(+), 3 deletions(-) diff --git a/Gemfile b/Gemfile index e9e5c7df075..94660ab5217 100644 --- a/Gemfile +++ b/Gemfile @@ -210,6 +210,7 @@ gem 'net-ssh', '~> 3.0.1' # Metrics group :metrics do + gem 'allocations', '~> 1.0', require: false, platform: :mri gem 'method_source', '~> 0.8', require: false gem 'influxdb', '~> 0.2', require: false gem 'connection_pool', '~> 2.0', require: false diff --git a/Gemfile.lock b/Gemfile.lock index 3f301111224..13e8168ee8a 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -49,6 +49,7 @@ GEM addressable (2.3.8) after_commit_queue (1.3.0) activerecord (>= 3.0) + allocations (1.0.1) annotate (2.6.10) activerecord (>= 3.2, <= 4.3) rake (~> 10.4) @@ -818,6 +819,7 @@ DEPENDENCIES acts-as-taggable-on (~> 3.4) addressable (~> 2.3.8) after_commit_queue + allocations (~> 1.0) annotate (~> 2.6.0) asana (~> 0.4.0) asciidoctor (~> 1.5.2) diff --git a/lib/gitlab/metrics.rb b/lib/gitlab/metrics.rb index 4b92c3244fa..ce89be636d3 100644 --- a/lib/gitlab/metrics.rb +++ b/lib/gitlab/metrics.rb @@ -16,6 +16,10 @@ module Gitlab !!Settings.metrics['enabled'] end + def self.mri? + RUBY_ENGINE == 'ruby' + end + def self.method_call_threshold Settings.metrics['method_call_threshold'] || 10 end diff --git a/lib/gitlab/metrics/sampler.rb b/lib/gitlab/metrics/sampler.rb index 03afa6324dd..828ee1f8c62 100644 --- a/lib/gitlab/metrics/sampler.rb +++ b/lib/gitlab/metrics/sampler.rb @@ -13,6 +13,12 @@ module Gitlab @last_minor_gc = Delta.new(GC.stat[:minor_gc_count]) @last_major_gc = Delta.new(GC.stat[:major_gc_count]) + + if Gitlab::Metrics.mri? + require 'allocations' + + Allocations.start + end end def start @@ -52,9 +58,22 @@ module Gitlab new('file_descriptors', value: System.file_descriptor_count) end - def sample_objects - ObjectSpace.count_objects.each do |type, count| - @metrics << Metric.new('object_counts', { count: count }, type: type) + if Metrics.mri? + def sample_objects + sample = Allocations.to_hash + counts = sample.each_with_object({}) do |(klass, count), hash| + hash[klass.name] = count + end + + # Symbols aren't allocated so we'll need to add those manually. + counts['Symbol'] = Symbol.all_symbols.length + + counts.each do |name, count| + @metrics << Metric.new('object_counts', { count: count }, type: name) + end + end + else + def sample_objects end end diff --git a/spec/lib/gitlab/metrics/sampler_spec.rb b/spec/lib/gitlab/metrics/sampler_spec.rb index 319f287178d..69376c0b79b 100644 --- a/spec/lib/gitlab/metrics/sampler_spec.rb +++ b/spec/lib/gitlab/metrics/sampler_spec.rb @@ -3,6 +3,10 @@ require 'spec_helper' describe Gitlab::Metrics::Sampler do let(:sampler) { described_class.new(5) } + after do + Allocations.stop if Gitlab::Metrics.mri? + end + describe '#start' do it 'gathers a sample at a given interval' do expect(sampler).to receive(:sleep).with(5) -- cgit v1.2.1 From ddca57d3f25e52e5e4061dd3610f1269efe2400d Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Mon, 28 Dec 2015 11:33:40 +0100 Subject: Use String#delete for removing double quotes --- lib/gitlab/metrics/obfuscated_sql.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/gitlab/metrics/obfuscated_sql.rb b/lib/gitlab/metrics/obfuscated_sql.rb index 7b15670aa6b..481aca56efb 100644 --- a/lib/gitlab/metrics/obfuscated_sql.rb +++ b/lib/gitlab/metrics/obfuscated_sql.rb @@ -37,7 +37,7 @@ module Gitlab # InfluxDB escapes double quotes upon output, so lets get rid of them # whenever we can. if Gitlab::Database.postgresql? - sql = sql.gsub('"', '') + sql = sql.delete('"') end sql -- cgit v1.2.1 From db7bbadf95d9f2266a055ee50a67fa895b0f21a9 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Mon, 28 Dec 2015 11:34:11 +0100 Subject: Fixed styling of MetricsWorker specs --- spec/workers/metrics_worker_spec.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/spec/workers/metrics_worker_spec.rb b/spec/workers/metrics_worker_spec.rb index 2acd0f8ba30..18260ea0c24 100644 --- a/spec/workers/metrics_worker_spec.rb +++ b/spec/workers/metrics_worker_spec.rb @@ -33,7 +33,7 @@ describe MetricsWorker do it 'drops empty tags' do metrics = worker.prepare_metrics([ - { 'values' => {}, 'tags' => { 'cats' => '', 'dogs' => nil }} + { 'values' => {}, 'tags' => { 'cats' => '', 'dogs' => nil } } ]) expect(metrics).to eq([{ values: {}, tags: {} }]) -- cgit v1.2.1 From 1be5668ae0e663015d384ea7d8b404f9eeb5b478 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Mon, 28 Dec 2015 13:14:48 +0100 Subject: Added host option for InfluxDB --- config/gitlab.yml.example | 1 + lib/gitlab/metrics.rb | 3 ++- 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/config/gitlab.yml.example b/config/gitlab.yml.example index 24f3f6f02dc..acfc86bf4d1 100644 --- a/config/gitlab.yml.example +++ b/config/gitlab.yml.example @@ -422,6 +422,7 @@ production: &base # Ban an IP for one hour (3600s) after too many auth attempts # bantime: 3600 metrics: + host: localhost enabled: false # The name of the InfluxDB database to store metrics in. database: gitlab diff --git a/lib/gitlab/metrics.rb b/lib/gitlab/metrics.rb index ce89be636d3..d6f60732455 100644 --- a/lib/gitlab/metrics.rb +++ b/lib/gitlab/metrics.rb @@ -52,11 +52,12 @@ module Gitlab # "@foo ||= bar" is _not_ thread-safe. if enabled? @pool = ConnectionPool.new(size: pool_size, timeout: timeout) do + host = Settings.metrics['host'] db = Settings.metrics['database'] user = Settings.metrics['username'] pw = Settings.metrics['password'] - InfluxDB::Client.new(db, username: user, password: pw) + InfluxDB::Client.new(db, host: host, username: user, password: pw) end end end -- cgit v1.2.1