diff options
Diffstat (limited to 'lib/gitlab/metrics')
20 files changed, 664 insertions, 350 deletions
diff --git a/lib/gitlab/metrics/background_transaction.rb b/lib/gitlab/metrics/background_transaction.rb new file mode 100644 index 00000000000..5919ebb1493 --- /dev/null +++ b/lib/gitlab/metrics/background_transaction.rb @@ -0,0 +1,14 @@ +module Gitlab + module Metrics + class BackgroundTransaction < Transaction + def initialize(worker_class) + super() + @worker_class = worker_class + end + + def labels + { controller: @worker_class.name, action: 'perform' } + end + end + end +end diff --git a/lib/gitlab/metrics/base_sampler.rb b/lib/gitlab/metrics/base_sampler.rb deleted file mode 100644 index 716d20bb91a..00000000000 --- a/lib/gitlab/metrics/base_sampler.rb +++ /dev/null @@ -1,63 +0,0 @@ -require 'logger' -module Gitlab - module Metrics - class BaseSampler < Daemon - # interval - The sampling interval in seconds. - def initialize(interval) - interval_half = interval.to_f / 2 - - @interval = interval - @interval_steps = (-interval_half..interval_half).step(0.1).to_a - - super() - end - - def safe_sample - sample - rescue => e - Rails.logger.warn("#{self.class}: #{e}, stopping") - stop - end - - def sample - raise NotImplementedError - end - - # Returns the sleep interval with a random adjustment. - # - # The random adjustment is put in place to ensure we: - # - # 1. Don't generate samples at the exact same interval every time (thus - # potentially missing anything that happens in between samples). - # 2. Don't sample data at the same interval two times in a row. - def sleep_interval - while (step = @interval_steps.sample) - if step != @last_step - @last_step = step - - return @interval + @last_step - end - end - end - - private - - attr_reader :running - - def start_working - @running = true - sleep(sleep_interval) - - while running - safe_sample - - sleep(sleep_interval) - end - end - - def stop_working - @running = false - end - end - end -end diff --git a/lib/gitlab/metrics/influx_db.rb b/lib/gitlab/metrics/influx_db.rb index 7b06bb953aa..bdf7910b7c7 100644 --- a/lib/gitlab/metrics/influx_db.rb +++ b/lib/gitlab/metrics/influx_db.rb @@ -11,6 +11,8 @@ module Gitlab settings[:enabled] || false end + # Prometheus histogram buckets used for arbitrary code measurements + EXECUTION_MEASUREMENT_BUCKETS = [0.001, 0.002, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1].freeze RAILS_ROOT = Rails.root.to_s METRICS_ROOT = Rails.root.join('lib', 'gitlab', 'metrics').to_s PATH_REGEX = /^#{RAILS_ROOT}\/?/ @@ -99,24 +101,27 @@ module Gitlab cpu_stop = System.cpu_time real_stop = Time.now.to_f - real_time = (real_stop - real_start) * 1000.0 + real_time = (real_stop - real_start) cpu_time = cpu_stop - cpu_start - trans.increment("#{name}_real_time", real_time) - trans.increment("#{name}_cpu_time", cpu_time) - trans.increment("#{name}_call_count", 1) + Gitlab::Metrics.histogram("gitlab_#{name}_real_duration_seconds".to_sym, + "Measure #{name}", + Transaction::BASE_LABELS, + EXECUTION_MEASUREMENT_BUCKETS) + .observe(trans.labels, real_time) - retval - end + Gitlab::Metrics.histogram("gitlab_#{name}_cpu_duration_seconds".to_sym, + "Measure #{name}", + Transaction::BASE_LABELS, + EXECUTION_MEASUREMENT_BUCKETS) + .observe(trans.labels, cpu_time / 1000.0) - # Adds a tag to the current transaction (if any) - # - # name - The name of the tag to add. - # value - The value of the tag. - def tag_transaction(name, value) - trans = current_transaction + # InfluxDB stores the _real_time time values as milliseconds + trans.increment("#{name}_real_time", real_time * 1000, false) + trans.increment("#{name}_cpu_time", cpu_time, false) + trans.increment("#{name}_call_count", 1, false) - trans&.add_tag(name, value) + retval end # Sets the action of the current transaction (if any) diff --git a/lib/gitlab/metrics/influx_sampler.rb b/lib/gitlab/metrics/influx_sampler.rb deleted file mode 100644 index 6db1dd755b7..00000000000 --- a/lib/gitlab/metrics/influx_sampler.rb +++ /dev/null @@ -1,101 +0,0 @@ -module Gitlab - module Metrics - # Class that sends certain metrics to InfluxDB at a specific interval. - # - # This class is used to gather statistics that can't be directly associated - # with a transaction such as system memory usage, garbage collection - # statistics, etc. - class InfluxSampler < BaseSampler - # interval - The sampling interval in seconds. - def initialize(interval = Metrics.settings[:sample_interval]) - super(interval) - @last_step = nil - - @metrics = [] - - @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 sample - sample_memory_usage - sample_file_descriptors - sample_objects - sample_gc - - flush - ensure - GC::Profiler.clear - @metrics.clear - end - - def flush - Metrics.submit_metrics(@metrics.map(&:to_hash)) - end - - def sample_memory_usage - add_metric('memory_usage', value: System.memory_usage) - end - - def sample_file_descriptors - add_metric('file_descriptors', value: System.file_descriptor_count) - end - - if Metrics.mri? - def sample_objects - sample = Allocations.to_hash - counts = sample.each_with_object({}) do |(klass, count), hash| - name = klass.name - - next unless name - - hash[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| - add_metric('object_counts', { count: count }, type: name) - end - end - else - def sample_objects - end - end - - def sample_gc - time = GC::Profiler.total_time * 1000.0 - stats = GC.stat.merge(total_time: time) - - # We want the difference of GC runs compared to the last sample, not the - # total amount since the process started. - stats[:minor_gc_count] = - @last_minor_gc.compared_with(stats[:minor_gc_count]) - - stats[:major_gc_count] = - @last_major_gc.compared_with(stats[:major_gc_count]) - - stats[:count] = stats[:minor_gc_count] + stats[:major_gc_count] - - add_metric('gc_statistics', stats) - end - - def add_metric(series, values, tags = {}) - prefix = sidekiq? ? 'sidekiq_' : 'rails_' - - @metrics << Metric.new("#{prefix}#{series}", values, tags) - end - - def sidekiq? - Sidekiq.server? - end - end - end -end diff --git a/lib/gitlab/metrics/instrumentation.rb b/lib/gitlab/metrics/instrumentation.rb index 6aa38542cb4..023e9963493 100644 --- a/lib/gitlab/metrics/instrumentation.rb +++ b/lib/gitlab/metrics/instrumentation.rb @@ -118,19 +118,21 @@ module Gitlab def self.instrument(type, mod, name) return unless Metrics.enabled? - name = name.to_sym + name = name.to_sym target = type == :instance ? mod : mod.singleton_class if type == :instance target = mod - label = "#{mod.name}##{name}" + method_name = "##{name}" method = mod.instance_method(name) else target = mod.singleton_class - label = "#{mod.name}.#{name}" + method_name = ".#{name}" method = mod.method(name) end + label = "#{mod.name}#{method_name}" + unless instrumented?(target) target.instance_variable_set(PROXY_IVAR, Module.new) end @@ -153,7 +155,8 @@ module Gitlab proxy_module.class_eval <<-EOF, __FILE__, __LINE__ + 1 def #{name}(#{args_signature}) if trans = Gitlab::Metrics::Instrumentation.transaction - trans.method_call_for(#{label.to_sym.inspect}).measure { super } + trans.method_call_for(#{label.to_sym.inspect}, #{mod.name.inspect}, "#{method_name}") + .measure { super } else super end diff --git a/lib/gitlab/metrics/method_call.rb b/lib/gitlab/metrics/method_call.rb index d3465e5ec19..65d55576ac2 100644 --- a/lib/gitlab/metrics/method_call.rb +++ b/lib/gitlab/metrics/method_call.rb @@ -2,15 +2,31 @@ module Gitlab module Metrics # Class for tracking timing information about method calls class MethodCall - attr_reader :real_time, :cpu_time, :call_count + MUTEX = Mutex.new + BASE_LABELS = { module: nil, method: nil }.freeze + attr_reader :real_time, :cpu_time, :call_count, :labels + + def self.call_duration_histogram + return @call_duration_histogram if @call_duration_histogram + + MUTEX.synchronize do + @call_duration_histogram ||= Gitlab::Metrics.histogram( + :gitlab_method_call_duration_seconds, + 'Method calls real duration', + Transaction::BASE_LABELS.merge(BASE_LABELS), + [0.01, 0.05, 0.1, 0.5, 1]) + end + end # name - The full name of the method (including namespace) such as # `User#sign_in`. # - # series - The series to use for storing the data. - def initialize(name, series) + def initialize(name, module_name, method_name, transaction) + @module_name = module_name + @method_name = method_name + @transaction = transaction @name = name - @series = series + @labels = { module: @module_name, method: @method_name } @real_time = 0 @cpu_time = 0 @call_count = 0 @@ -22,21 +38,28 @@ module Gitlab start_cpu = System.cpu_time retval = yield - @real_time += System.monotonic_time - start_real - @cpu_time += System.cpu_time - start_cpu + real_time = System.monotonic_time - start_real + cpu_time = System.cpu_time - start_cpu + + @real_time += real_time + @cpu_time += cpu_time @call_count += 1 + if call_measurement_enabled? && above_threshold? + self.class.call_duration_histogram.observe(@transaction.labels.merge(labels), real_time / 1000.0) + end + retval end # Returns a Metric instance of the current method call. def to_metric Metric.new( - @series, + Instrumentation.series, { - duration: real_time, + duration: real_time, cpu_duration: cpu_time, - call_count: call_count + call_count: call_count }, method: @name ) @@ -47,6 +70,10 @@ module Gitlab def above_threshold? real_time >= Metrics.method_call_threshold end + + def call_measurement_enabled? + Feature.get(:prometheus_metrics_method_instrumentation).enabled? + end end end end diff --git a/lib/gitlab/metrics/prometheus.rb b/lib/gitlab/metrics/prometheus.rb index 460dab47276..09103b4ca2d 100644 --- a/lib/gitlab/metrics/prometheus.rb +++ b/lib/gitlab/metrics/prometheus.rb @@ -5,6 +5,9 @@ module Gitlab module Prometheus include Gitlab::CurrentSettings + REGISTRY_MUTEX = Mutex.new + PROVIDER_MUTEX = Mutex.new + def metrics_folder_present? multiprocess_files_dir = ::Prometheus::Client.configuration.multiprocess_files_dir @@ -20,23 +23,38 @@ module Gitlab end def registry - @registry ||= ::Prometheus::Client.registry + return @registry if @registry + + REGISTRY_MUTEX.synchronize do + @registry ||= ::Prometheus::Client.registry + end end def counter(name, docstring, base_labels = {}) - provide_metric(name) || registry.counter(name, docstring, base_labels) + safe_provide_metric(:counter, name, docstring, base_labels) end def summary(name, docstring, base_labels = {}) - provide_metric(name) || registry.summary(name, docstring, base_labels) + safe_provide_metric(:summary, name, docstring, base_labels) end def gauge(name, docstring, base_labels = {}, multiprocess_mode = :all) - provide_metric(name) || registry.gauge(name, docstring, base_labels, multiprocess_mode) + safe_provide_metric(:gauge, name, docstring, base_labels, multiprocess_mode) end def histogram(name, docstring, base_labels = {}, buckets = ::Prometheus::Client::Histogram::DEFAULT_BUCKETS) - provide_metric(name) || registry.histogram(name, docstring, base_labels, buckets) + safe_provide_metric(:histogram, name, docstring, base_labels, buckets) + end + + private + + def safe_provide_metric(method, name, *args) + metric = provide_metric(name) + return metric if metric + + PROVIDER_MUTEX.synchronize do + provide_metric(name) || registry.method(method).call(name, *args) + end end def provide_metric(name) @@ -47,8 +65,6 @@ module Gitlab end end - private - def prometheus_metrics_enabled_unmemoized metrics_folder_present? && current_application_settings[:prometheus_metrics_enabled] || false end diff --git a/lib/gitlab/metrics/rack_middleware.rb b/lib/gitlab/metrics/rack_middleware.rb index adc0db1a874..2d45765df3f 100644 --- a/lib/gitlab/metrics/rack_middleware.rb +++ b/lib/gitlab/metrics/rack_middleware.rb @@ -2,20 +2,6 @@ module Gitlab module Metrics # Rack middleware for tracking Rails and Grape requests. class RackMiddleware - CONTROLLER_KEY = 'action_controller.instance'.freeze - ENDPOINT_KEY = 'api.endpoint'.freeze - CONTENT_TYPES = { - 'text/html' => :html, - 'text/plain' => :txt, - 'application/json' => :json, - 'text/js' => :js, - 'application/atom+xml' => :atom, - 'image/png' => :png, - 'image/jpeg' => :jpeg, - 'image/gif' => :gif, - 'image/svg+xml' => :svg - }.freeze - def initialize(app) @app = app end @@ -35,12 +21,6 @@ module Gitlab # Even in the event of an error we want to submit any metrics we # might've gathered up to this point. ensure - if env[CONTROLLER_KEY] - tag_controller(trans, env) - elsif env[ENDPOINT_KEY] - tag_endpoint(trans, env) - end - trans.finish end @@ -48,60 +28,19 @@ module Gitlab end def transaction_from_env(env) - trans = Transaction.new + trans = WebTransaction.new(env) - trans.set(:request_uri, filtered_path(env)) - trans.set(:request_method, env['REQUEST_METHOD']) + trans.set(:request_uri, filtered_path(env), false) + trans.set(:request_method, env['REQUEST_METHOD'], false) trans end - def tag_controller(trans, env) - controller = env[CONTROLLER_KEY] - action = "#{controller.class.name}##{controller.action_name}" - suffix = CONTENT_TYPES[controller.content_type] - - if suffix && suffix != :html - action += ".#{suffix}" - end - - trans.action = action - end - - def tag_endpoint(trans, env) - endpoint = env[ENDPOINT_KEY] - - begin - route = endpoint.route - rescue - # endpoint.route is calling env[Grape::Env::GRAPE_ROUTING_ARGS][:route_info] - # but env[Grape::Env::GRAPE_ROUTING_ARGS] is nil in the case of a 405 response - # so we're rescuing exceptions and bailing out - end - - if route - path = endpoint_paths_cache[route.request_method][route.path] - trans.action = "Grape##{route.request_method} #{path}" - end - end - private def filtered_path(env) ActionDispatch::Request.new(env).filtered_path.presence || env['REQUEST_URI'] end - - def endpoint_paths_cache - @endpoint_paths_cache ||= Hash.new do |hash, http_method| - hash[http_method] = Hash.new do |inner_hash, raw_path| - inner_hash[raw_path] = endpoint_instrumentable_path(raw_path) - end - end - end - - def endpoint_instrumentable_path(raw_path) - raw_path.sub('(.:format)', '').sub('/:version', '') - end end end end diff --git a/lib/gitlab/metrics/samplers/base_sampler.rb b/lib/gitlab/metrics/samplers/base_sampler.rb new file mode 100644 index 00000000000..37f90c4673d --- /dev/null +++ b/lib/gitlab/metrics/samplers/base_sampler.rb @@ -0,0 +1,64 @@ +require 'logger' + +module Gitlab + module Metrics + module Samplers + class BaseSampler < Daemon + # interval - The sampling interval in seconds. + def initialize(interval) + interval_half = interval.to_f / 2 + + @interval = interval + @interval_steps = (-interval_half..interval_half).step(0.1).to_a + + super() + end + + def safe_sample + sample + rescue => e + Rails.logger.warn("#{self.class}: #{e}, stopping") + stop + end + + def sample + raise NotImplementedError + end + + # Returns the sleep interval with a random adjustment. + # + # The random adjustment is put in place to ensure we: + # + # 1. Don't generate samples at the exact same interval every time (thus + # potentially missing anything that happens in between samples). + # 2. Don't sample data at the same interval two times in a row. + def sleep_interval + while step = @interval_steps.sample + if step != @last_step + @last_step = step + + return @interval + @last_step + end + end + end + + private + + attr_reader :running + + def start_working + @running = true + sleep(sleep_interval) + while running + safe_sample + sleep(sleep_interval) + end + end + + def stop_working + @running = false + end + end + end + end +end diff --git a/lib/gitlab/metrics/samplers/influx_sampler.rb b/lib/gitlab/metrics/samplers/influx_sampler.rb new file mode 100644 index 00000000000..f4f9b5ca792 --- /dev/null +++ b/lib/gitlab/metrics/samplers/influx_sampler.rb @@ -0,0 +1,103 @@ +module Gitlab + module Metrics + module Samplers + # Class that sends certain metrics to InfluxDB at a specific interval. + # + # This class is used to gather statistics that can't be directly associated + # with a transaction such as system memory usage, garbage collection + # statistics, etc. + class InfluxSampler < BaseSampler + # interval - The sampling interval in seconds. + def initialize(interval = Metrics.settings[:sample_interval]) + super(interval) + @last_step = nil + + @metrics = [] + + @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 sample + sample_memory_usage + sample_file_descriptors + sample_objects + sample_gc + + flush + ensure + GC::Profiler.clear + @metrics.clear + end + + def flush + Metrics.submit_metrics(@metrics.map(&:to_hash)) + end + + def sample_memory_usage + add_metric('memory_usage', value: System.memory_usage) + end + + def sample_file_descriptors + add_metric('file_descriptors', value: System.file_descriptor_count) + end + + if Metrics.mri? + def sample_objects + sample = Allocations.to_hash + counts = sample.each_with_object({}) do |(klass, count), hash| + name = klass.name + + next unless name + + hash[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| + add_metric('object_counts', { count: count }, type: name) + end + end + else + def sample_objects + end + end + + def sample_gc + time = GC::Profiler.total_time * 1000.0 + stats = GC.stat.merge(total_time: time) + + # We want the difference of GC runs compared to the last sample, not the + # total amount since the process started. + stats[:minor_gc_count] = + @last_minor_gc.compared_with(stats[:minor_gc_count]) + + stats[:major_gc_count] = + @last_major_gc.compared_with(stats[:major_gc_count]) + + stats[:count] = stats[:minor_gc_count] + stats[:major_gc_count] + + add_metric('gc_statistics', stats) + end + + def add_metric(series, values, tags = {}) + prefix = sidekiq? ? 'sidekiq_' : 'rails_' + + @metrics << Metric.new("#{prefix}#{series}", values, tags) + end + + def sidekiq? + Sidekiq.server? + end + end + end + end +end diff --git a/lib/gitlab/metrics/samplers/ruby_sampler.rb b/lib/gitlab/metrics/samplers/ruby_sampler.rb new file mode 100644 index 00000000000..436a9e9550d --- /dev/null +++ b/lib/gitlab/metrics/samplers/ruby_sampler.rb @@ -0,0 +1,111 @@ +require 'prometheus/client/support/unicorn' + +module Gitlab + module Metrics + module Samplers + class RubySampler < BaseSampler + def metrics + @metrics ||= init_metrics + end + + def with_prefix(prefix, name) + "ruby_#{prefix}_#{name}".to_sym + end + + def to_doc_string(name) + name.to_s.humanize + end + + def labels + {} + end + + def initialize(interval) + super(interval) + + if Metrics.mri? + require 'allocations' + + Allocations.start + end + end + + def init_metrics + metrics = {} + metrics[:sampler_duration] = Metrics.histogram(with_prefix(:sampler_duration, :seconds), 'Sampler time', {}) + metrics[:total_time] = Metrics.gauge(with_prefix(:gc, :time_total), 'Total GC time', labels, :livesum) + GC.stat.keys.each do |key| + metrics[key] = Metrics.gauge(with_prefix(:gc, key), to_doc_string(key), labels, :livesum) + end + + metrics[:objects_total] = Metrics.gauge(with_prefix(:objects, :total), 'Objects total', labels.merge(class: nil), :livesum) + metrics[:memory_usage] = Metrics.gauge(with_prefix(:memory, :usage_total), 'Memory used total', labels, :livesum) + metrics[:file_descriptors] = Metrics.gauge(with_prefix(:file, :descriptors_total), 'File descriptors total', labels, :livesum) + + metrics + end + + def sample + start_time = System.monotonic_time + sample_gc + sample_objects + + metrics[:memory_usage].set(labels, System.memory_usage) + metrics[:file_descriptors].set(labels, System.file_descriptor_count) + + metrics[:sampler_duration].observe(labels.merge(worker_label), (System.monotonic_time - start_time) / 1000.0) + ensure + GC::Profiler.clear + end + + private + + def sample_gc + metrics[:total_time].set(labels, GC::Profiler.total_time * 1000) + + GC.stat.each do |key, value| + metrics[key].set(labels, value) + end + end + + def sample_objects + list_objects.each do |name, count| + metrics[:objects_total].set(labels.merge(class: name), count) + end + end + + if Metrics.mri? + def list_objects + sample = Allocations.to_hash + counts = sample.each_with_object({}) do |(klass, count), hash| + name = klass.name + + next unless name + + hash[name] = count + end + + # Symbols aren't allocated so we'll need to add those manually. + counts['Symbol'] = Symbol.all_symbols.length + counts + end + else + def list_objects + end + end + + def worker_label + return {} unless defined?(Unicorn::Worker) + + worker_no = ::Prometheus::Client::Support::Unicorn.worker_id + + if worker_no + { unicorn: worker_no } + else + { unicorn: 'master' } + end + end + end + end + end +end diff --git a/lib/gitlab/metrics/samplers/unicorn_sampler.rb b/lib/gitlab/metrics/samplers/unicorn_sampler.rb new file mode 100644 index 00000000000..ea325651fbb --- /dev/null +++ b/lib/gitlab/metrics/samplers/unicorn_sampler.rb @@ -0,0 +1,50 @@ +module Gitlab + module Metrics + module Samplers + class UnicornSampler < BaseSampler + def initialize(interval) + super(interval) + end + + def unicorn_active_connections + @unicorn_active_connections ||= Gitlab::Metrics.gauge(:unicorn_active_connections, 'Unicorn active connections', {}, :max) + end + + def unicorn_queued_connections + @unicorn_queued_connections ||= Gitlab::Metrics.gauge(:unicorn_queued_connections, 'Unicorn queued connections', {}, :max) + end + + def enabled? + # Raindrops::Linux.tcp_listener_stats is only present on Linux + unicorn_with_listeners? && Raindrops::Linux.respond_to?(:tcp_listener_stats) + end + + def sample + Raindrops::Linux.tcp_listener_stats(tcp_listeners).each do |addr, stats| + unicorn_active_connections.set({ type: 'tcp', address: addr }, stats.active) + unicorn_queued_connections.set({ type: 'tcp', address: addr }, stats.queued) + end + + Raindrops::Linux.unix_listener_stats(unix_listeners).each do |addr, stats| + unicorn_active_connections.set({ type: 'unix', address: addr }, stats.active) + unicorn_queued_connections.set({ type: 'unix', address: addr }, stats.queued) + end + end + + private + + def tcp_listeners + @tcp_listeners ||= Unicorn.listener_names.grep(%r{\A[^/]+:\d+\z}) + end + + def unix_listeners + @unix_listeners ||= Unicorn.listener_names - tcp_listeners + end + + def unicorn_with_listeners? + defined?(Unicorn) && Unicorn.listener_names.any? + end + end + end + end +end diff --git a/lib/gitlab/metrics/sidekiq_middleware.rb b/lib/gitlab/metrics/sidekiq_middleware.rb index f9dd8e41912..df4bdf16847 100644 --- a/lib/gitlab/metrics/sidekiq_middleware.rb +++ b/lib/gitlab/metrics/sidekiq_middleware.rb @@ -5,7 +5,7 @@ module Gitlab # This middleware is intended to be used as a server-side middleware. class SidekiqMiddleware def call(worker, message, queue) - trans = Transaction.new("#{worker.class.name}#perform") + trans = BackgroundTransaction.new(worker.class) begin # Old gitlad-shell messages don't provide enqueued_at/created_at attributes diff --git a/lib/gitlab/metrics/subscribers/action_view.rb b/lib/gitlab/metrics/subscribers/action_view.rb index d435a33e9c7..3da474fc1ec 100644 --- a/lib/gitlab/metrics/subscribers/action_view.rb +++ b/lib/gitlab/metrics/subscribers/action_view.rb @@ -15,10 +15,24 @@ module Gitlab private + def metric_view_rendering_duration_seconds + @metric_view_rendering_duration_seconds ||= Gitlab::Metrics.histogram( + :gitlab_view_rendering_duration_seconds, + 'View rendering time', + Transaction::BASE_LABELS.merge({ path: nil }), + [0.001, 0.002, 0.005, 0.01, 0.02, 0.05, 0.1, 0.500, 2.0, 10.0] + ) + end + def track(event) values = values_for(event) tags = tags_for(event) + metric_view_rendering_duration_seconds.observe( + current_transaction.labels.merge(tags), + event.duration + ) + current_transaction.increment(:view_duration, event.duration) current_transaction.add_metric(SERIES, values, tags) end diff --git a/lib/gitlab/metrics/subscribers/active_record.rb b/lib/gitlab/metrics/subscribers/active_record.rb index 96cad941d5c..ead1acb8d44 100644 --- a/lib/gitlab/metrics/subscribers/active_record.rb +++ b/lib/gitlab/metrics/subscribers/active_record.rb @@ -8,8 +8,10 @@ module Gitlab def sql(event) return unless current_transaction - current_transaction.increment(:sql_duration, event.duration) - current_transaction.increment(:sql_count, 1) + metric_sql_duration_seconds.observe(current_transaction.labels, event.duration / 1000.0) + + current_transaction.increment(:sql_duration, event.duration, false) + current_transaction.increment(:sql_count, 1, false) end private @@ -17,6 +19,15 @@ module Gitlab def current_transaction Transaction.current end + + def metric_sql_duration_seconds + @metric_sql_duration_seconds ||= Gitlab::Metrics.histogram( + :gitlab_sql_duration_seconds, + 'SQL time', + Transaction::BASE_LABELS, + [0.001, 0.002, 0.005, 0.01, 0.02, 0.05, 0.1, 0.500, 2.0, 10.0] + ) + end end end end diff --git a/lib/gitlab/metrics/subscribers/rails_cache.rb b/lib/gitlab/metrics/subscribers/rails_cache.rb index aaed2184f44..efd3c9daf79 100644 --- a/lib/gitlab/metrics/subscribers/rails_cache.rb +++ b/lib/gitlab/metrics/subscribers/rails_cache.rb @@ -7,28 +7,29 @@ module Gitlab attach_to :active_support def cache_read(event) - increment(:cache_read, event.duration) + observe(:read, event.duration) return unless current_transaction return if event.payload[:super_operation] == :fetch if event.payload[:hit] - current_transaction.increment(:cache_read_hit_count, 1) + current_transaction.increment(:cache_read_hit_count, 1, false) else - current_transaction.increment(:cache_read_miss_count, 1) + metric_cache_misses_total.increment(current_transaction.labels) + current_transaction.increment(:cache_read_miss_count, 1, false) end end def cache_write(event) - increment(:cache_write, event.duration) + observe(:write, event.duration) end def cache_delete(event) - increment(:cache_delete, event.duration) + observe(:delete, event.duration) end def cache_exist?(event) - increment(:cache_exists, event.duration) + observe(:exists, event.duration) end def cache_fetch_hit(event) @@ -40,16 +41,18 @@ module Gitlab def cache_generate(event) return unless current_transaction + metric_cache_misses_total.increment(current_transaction.labels) current_transaction.increment(:cache_read_miss_count, 1) end - def increment(key, duration) + def observe(key, duration) return unless current_transaction - current_transaction.increment(:cache_duration, duration) - current_transaction.increment(:cache_count, 1) - current_transaction.increment("#{key}_duration".to_sym, duration) - current_transaction.increment("#{key}_count".to_sym, 1) + metric_cache_operation_duration_seconds.observe(current_transaction.labels.merge({ operation: key }), duration / 1000.0) + current_transaction.increment(:cache_duration, duration, false) + current_transaction.increment(:cache_count, 1, false) + current_transaction.increment("cache_#{key}_duration".to_sym, duration, false) + current_transaction.increment("cache_#{key}_count".to_sym, 1, false) end private @@ -57,6 +60,23 @@ module Gitlab def current_transaction Transaction.current end + + def metric_cache_operation_duration_seconds + @metric_cache_operation_duration_seconds ||= Gitlab::Metrics.histogram( + :gitlab_cache_operation_duration_seconds, + 'Cache access time', + Transaction::BASE_LABELS.merge({ action: nil }), + [0.001, 0.002, 0.005, 0.01, 0.02, 0.05, 0.1, 0.500, 2.0, 10.0] + ) + end + + def metric_cache_misses_total + @metric_cache_misses_total ||= Gitlab::Metrics.counter( + :gitlab_cache_misses_total, + 'Cache read miss', + Transaction::BASE_LABELS + ) + end end end end diff --git a/lib/gitlab/metrics/system.rb b/lib/gitlab/metrics/system.rb index aba3e0df382..c2cbd3c16a1 100644 --- a/lib/gitlab/metrics/system.rb +++ b/lib/gitlab/metrics/system.rb @@ -46,14 +46,14 @@ module Gitlab # Returns the current real time in a given precision. # - # Returns the time as a Float. + # Returns the time as a Fixnum. def self.real_time(precision = :millisecond) Process.clock_gettime(Process::CLOCK_REALTIME, precision) end # Returns the current monotonic clock time in a given precision. # - # Returns the time as a Float. + # Returns the time as a Fixnum. def self.monotonic_time(precision = :millisecond) Process.clock_gettime(Process::CLOCK_MONOTONIC, precision) end diff --git a/lib/gitlab/metrics/transaction.rb b/lib/gitlab/metrics/transaction.rb index 4f9fb1c7853..ee3afc5ffdb 100644 --- a/lib/gitlab/metrics/transaction.rb +++ b/lib/gitlab/metrics/transaction.rb @@ -2,34 +2,33 @@ module Gitlab module Metrics # Class for storing metrics information of a single transaction. class Transaction + # base labels shared among all transactions + BASE_LABELS = { controller: nil, action: nil }.freeze + THREAD_KEY = :_gitlab_metrics_transaction + METRICS_MUTEX = Mutex.new # The series to store events (e.g. Git pushes) in. EVENT_SERIES = 'events'.freeze attr_reader :tags, :values, :method, :metrics - attr_accessor :action - def self.current Thread.current[THREAD_KEY] end - # action - A String describing the action performed, usually the class - # plus method name. - def initialize(action = nil) + def initialize @metrics = [] @methods = {} - @started_at = nil + @started_at = nil @finished_at = nil @values = Hash.new(0) - @tags = {} - @action = action + @tags = {} @memory_before = 0 - @memory_after = 0 + @memory_after = 0 end def duration @@ -44,12 +43,15 @@ module Gitlab Thread.current[THREAD_KEY] = self @memory_before = System.memory_usage - @started_at = System.monotonic_time + @started_at = System.monotonic_time yield ensure @memory_after = System.memory_usage - @finished_at = System.monotonic_time + @finished_at = System.monotonic_time + + self.class.metric_transaction_duration_seconds.observe(labels, duration * 1000) + self.class.metric_transaction_allocated_memory_bytes.observe(labels, allocated_memory * 1024.0) Thread.current[THREAD_KEY] = nil end @@ -66,33 +68,29 @@ module Gitlab # event_name - The name of the event (e.g. "git_push"). # tags - A set of tags to attach to the event. def add_event(event_name, tags = {}) - @metrics << Metric.new(EVENT_SERIES, - { count: 1 }, - { event: event_name }.merge(tags), - :event) + self.class.metric_event_counter(event_name, tags).increment(tags.merge(labels)) + @metrics << Metric.new(EVENT_SERIES, { count: 1 }, tags.merge(event: event_name), :event) end # Returns a MethodCall object for the given name. - def method_call_for(name) + def method_call_for(name, module_name, method_name) unless method = @methods[name] - @methods[name] = method = MethodCall.new(name, Instrumentation.series) + @methods[name] = method = MethodCall.new(name, module_name, method_name, self) end method end - def increment(name, value) + def increment(name, value, use_prometheus = true) + self.class.metric_transaction_counter(name).increment(labels, value) if use_prometheus @values[name] += value end - def set(name, value) + def set(name, value, use_prometheus = true) + self.class.metric_transaction_gauge(name).set(labels, value) if use_prometheus @values[name] = value end - def add_tag(key, value) - @tags[key] = value - end - def finish track_self submit @@ -117,14 +115,83 @@ module Gitlab submit_hashes = submit.map do |metric| hash = metric.to_hash - - hash[:tags][:action] ||= @action if @action && !metric.event? + hash[:tags][:action] ||= action if action && !metric.event? hash end Metrics.submit_metrics(submit_hashes) end + + def labels + BASE_LABELS + end + + # returns string describing the action performed, usually the class plus method name. + def action + "#{labels[:controller]}##{labels[:action]}" if labels && !labels.empty? + end + + def self.metric_transaction_duration_seconds + return @metric_transaction_duration_seconds if @metric_transaction_duration_seconds + + METRICS_MUTEX.synchronize do + @metric_transaction_duration_seconds ||= Gitlab::Metrics.histogram( + :gitlab_transaction_duration_seconds, + 'Transaction duration', + BASE_LABELS, + [0.001, 0.002, 0.005, 0.01, 0.02, 0.05, 0.1, 0.500, 2.0, 10.0] + ) + end + end + + def self.metric_transaction_allocated_memory_bytes + return @metric_transaction_allocated_memory_bytes if @metric_transaction_allocated_memory_bytes + + METRICS_MUTEX.synchronize do + @metric_transaction_allocated_memory_bytes ||= Gitlab::Metrics.histogram( + :gitlab_transaction_allocated_memory_bytes, + 'Transaction allocated memory bytes', + BASE_LABELS, + [1000, 10000, 20000, 500000, 1000000, 2000000, 5000000, 10000000, 20000000, 100000000] + ) + end + end + + def self.metric_event_counter(event_name, tags) + return @metric_event_counters[event_name] if @metric_event_counters&.has_key?(event_name) + + METRICS_MUTEX.synchronize do + @metric_event_counters ||= {} + @metric_event_counters[event_name] ||= Gitlab::Metrics.counter( + "gitlab_transaction_event_#{event_name}_total".to_sym, + "Transaction event #{event_name} counter", + tags.merge(BASE_LABELS) + ) + end + end + + def self.metric_transaction_counter(name) + return @metric_transaction_counters[name] if @metric_transaction_counters&.has_key?(name) + + METRICS_MUTEX.synchronize do + @metric_transaction_counters ||= {} + @metric_transaction_counters[name] ||= Gitlab::Metrics.counter( + "gitlab_transaction_#{name}_total".to_sym, "Transaction #{name} counter", BASE_LABELS + ) + end + end + + def self.metric_transaction_gauge(name) + return @metric_transaction_gauges[name] if @metric_transaction_gauges&.has_key?(name) + + METRICS_MUTEX.synchronize do + @metric_transaction_gauges ||= {} + @metric_transaction_gauges[name] ||= Gitlab::Metrics.gauge( + "gitlab_transaction_#{name}".to_sym, "Transaction gauge #{name}", BASE_LABELS, :livesum + ) + end + end end end end diff --git a/lib/gitlab/metrics/unicorn_sampler.rb b/lib/gitlab/metrics/unicorn_sampler.rb deleted file mode 100644 index f6987252039..00000000000 --- a/lib/gitlab/metrics/unicorn_sampler.rb +++ /dev/null @@ -1,48 +0,0 @@ -module Gitlab - module Metrics - class UnicornSampler < BaseSampler - def initialize(interval) - super(interval) - end - - def unicorn_active_connections - @unicorn_active_connections ||= Gitlab::Metrics.gauge(:unicorn_active_connections, 'Unicorn active connections', {}, :max) - end - - def unicorn_queued_connections - @unicorn_queued_connections ||= Gitlab::Metrics.gauge(:unicorn_queued_connections, 'Unicorn queued connections', {}, :max) - end - - def enabled? - # Raindrops::Linux.tcp_listener_stats is only present on Linux - unicorn_with_listeners? && Raindrops::Linux.respond_to?(:tcp_listener_stats) - end - - def sample - Raindrops::Linux.tcp_listener_stats(tcp_listeners).each do |addr, stats| - unicorn_active_connections.set({ type: 'tcp', address: addr }, stats.active) - unicorn_queued_connections.set({ type: 'tcp', address: addr }, stats.queued) - end - - Raindrops::Linux.unix_listener_stats(unix_listeners).each do |addr, stats| - unicorn_active_connections.set({ type: 'unix', address: addr }, stats.active) - unicorn_queued_connections.set({ type: 'unix', address: addr }, stats.queued) - end - end - - private - - def tcp_listeners - @tcp_listeners ||= Unicorn.listener_names.grep(%r{\A[^/]+:\d+\z}) - end - - def unix_listeners - @unix_listeners ||= Unicorn.listener_names - tcp_listeners - end - - def unicorn_with_listeners? - defined?(Unicorn) && Unicorn.listener_names.any? - end - end - end -end diff --git a/lib/gitlab/metrics/web_transaction.rb b/lib/gitlab/metrics/web_transaction.rb new file mode 100644 index 00000000000..89ff02a96d6 --- /dev/null +++ b/lib/gitlab/metrics/web_transaction.rb @@ -0,0 +1,82 @@ +module Gitlab + module Metrics + class WebTransaction < Transaction + CONTROLLER_KEY = 'action_controller.instance'.freeze + ENDPOINT_KEY = 'api.endpoint'.freeze + + CONTENT_TYPES = { + 'text/html' => :html, + 'text/plain' => :txt, + 'application/json' => :json, + 'text/js' => :js, + 'application/atom+xml' => :atom, + 'image/png' => :png, + 'image/jpeg' => :jpeg, + 'image/gif' => :gif, + 'image/svg+xml' => :svg + }.freeze + + def initialize(env) + super() + @env = env + end + + def labels + return @labels if @labels + + # memoize transaction labels only source env variables were present + @labels = if @env[CONTROLLER_KEY] + labels_from_controller || {} + elsif @env[ENDPOINT_KEY] + labels_from_endpoint || {} + end + + @labels || {} + end + + private + + def labels_from_controller + controller = @env[CONTROLLER_KEY] + + action = "#{controller.action_name}" + suffix = CONTENT_TYPES[controller.content_type] + + if suffix && suffix != :html + action += ".#{suffix}" + end + + { controller: controller.class.name, action: action } + end + + def labels_from_endpoint + endpoint = @env[ENDPOINT_KEY] + + begin + route = endpoint.route + rescue + # endpoint.route is calling env[Grape::Env::GRAPE_ROUTING_ARGS][:route_info] + # but env[Grape::Env::GRAPE_ROUTING_ARGS] is nil in the case of a 405 response + # so we're rescuing exceptions and bailing out + end + + if route + path = endpoint_paths_cache[route.request_method][route.path] + { controller: 'Grape', action: "#{route.request_method} #{path}" } + end + end + + def endpoint_paths_cache + @endpoint_paths_cache ||= Hash.new do |hash, http_method| + hash[http_method] = Hash.new do |inner_hash, raw_path| + inner_hash[raw_path] = endpoint_instrumentable_path(raw_path) + end + end + end + + def endpoint_instrumentable_path(raw_path) + raw_path.sub('(.:format)', '').sub('/:version', '') + end + end + end +end |