From 9dd59df6991b9d82bcbb95bf406194aab8ecf743 Mon Sep 17 00:00:00 2001 From: Stan Hu Date: Wed, 17 Jul 2019 12:33:49 -0700 Subject: Fix inconsistency in Redis performance bar stats peek-redis resets its counters at the start of an ActionController notification (`start_processing.action_controller`), which causes it to miss some Redis queries that precede it, such as the database load balancer and Rack Attack queries. This produces inconsistencies in the performance bar between the number of calls and their durations with the actual calls in the detailed view. We fix this by getting rid of peek-redis in favor of consolidating all logic into the `RedisDetailed` view, which tracks Redis queries using `RequestStore`. This has the nice property of removing thread-specific counters as well. Closes https://gitlab.com/gitlab-org/gitlab-ce/issues/64707 --- Gemfile | 1 - Gemfile.lock | 6 -- config/initializers/peek.rb | 2 +- lib/peek/views/redis.rb | 86 ------------------------ lib/peek/views/redis_detailed.rb | 104 +++++++++++++++++++++++++++++ spec/lib/peek/views/redis_detailed_spec.rb | 25 ++++--- 6 files changed, 119 insertions(+), 105 deletions(-) delete mode 100644 lib/peek/views/redis.rb create mode 100644 lib/peek/views/redis_detailed.rb diff --git a/Gemfile b/Gemfile index 8bffc2a973d..de1f44642f2 100644 --- a/Gemfile +++ b/Gemfile @@ -299,7 +299,6 @@ gem 'peek-gc', '~> 0.0.2' gem 'peek-mysql2', '~> 1.2.0', group: :mysql gem 'peek-pg', '~> 1.3.0', group: :postgres gem 'peek-rblineprof', '~> 0.2.0' -gem 'peek-redis', '~> 1.2.0' # Memory benchmarks gem 'derailed_benchmarks', require: false diff --git a/Gemfile.lock b/Gemfile.lock index 60939ae918c..2bcc3527de4 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -76,7 +76,6 @@ GEM asciidoctor-plantuml (0.0.9) asciidoctor (>= 1.5.6, < 3.0.0) ast (2.4.0) - atomic (1.1.99) attr_encrypted (3.1.0) encryptor (~> 3.0.0) attr_required (1.0.1) @@ -658,10 +657,6 @@ GEM peek-rblineprof (0.2.0) peek rblineprof - peek-redis (1.2.0) - atomic (>= 1.0.0) - peek - redis pg (1.1.4) po_to_json (1.0.1) json (>= 1.6.0) @@ -1199,7 +1194,6 @@ DEPENDENCIES peek-mysql2 (~> 1.2.0) peek-pg (~> 1.3.0) peek-rblineprof (~> 0.2.0) - peek-redis (~> 1.2.0) pg (~> 1.1) premailer-rails (~> 1.9.7) prometheus-client-mmap (~> 0.9.8) diff --git a/config/initializers/peek.rb b/config/initializers/peek.rb index d492b60705d..2aec32e878c 100644 --- a/config/initializers/peek.rb +++ b/config/initializers/peek.rb @@ -29,7 +29,7 @@ end Peek.into PEEK_DB_VIEW Peek.into Peek::Views::Gitaly Peek.into Peek::Views::Rblineprof -Peek.into Peek::Views::Redis +Peek.into Peek::Views::RedisDetailed Peek.into Peek::Views::GC Peek.into Peek::Views::Tracing if Labkit::Tracing.tracing_url_enabled? diff --git a/lib/peek/views/redis.rb b/lib/peek/views/redis.rb deleted file mode 100644 index 73de8672fa4..00000000000 --- a/lib/peek/views/redis.rb +++ /dev/null @@ -1,86 +0,0 @@ -# frozen_string_literal: true - -require 'redis' -require 'peek-redis' - -module Gitlab - module Peek - module RedisInstrumented - def call(*args, &block) - start = Time.now - super(*args, &block) - ensure - duration = (Time.now - start) - add_call_details(duration, args) - end - - private - - def add_call_details(duration, args) - # redis-rb passes an array (e.g. [:get, key]) - return unless args.length == 1 - - detail_store << { - cmd: args.first, - duration: duration, - backtrace: Gitlab::Profiler.clean_backtrace(caller) - } - end - - def detail_store - ::Gitlab::SafeRequestStore['redis_call_details'] ||= [] - end - end - end -end - -module Peek - module Views - module RedisDetailed - REDACTED_MARKER = "" - - def results - super.merge(details: details) - end - - def details - detail_store - .sort { |a, b| b[:duration] <=> a[:duration] } - .map(&method(:format_call_details)) - end - - def detail_store - ::Gitlab::SafeRequestStore['redis_call_details'] ||= [] - end - - def format_call_details(call) - call.merge(cmd: format_command(call[:cmd]), - duration: (call[:duration] * 1000).round(3)) - end - - def format_command(cmd) - if cmd.length >= 2 && cmd.first =~ /^auth$/i - cmd[-1] = REDACTED_MARKER - # Scrub out the value of the SET calls to avoid binary - # data or large data from spilling into the view - elsif cmd.length >= 3 && cmd.first =~ /set/i - cmd[2..-1] = REDACTED_MARKER - end - - cmd.join(' ') - end - end - end -end - -class Redis::Client - prepend Gitlab::Peek::RedisInstrumented -end - -module Peek - module Views - class Redis < View - prepend Peek::Views::RedisDetailed - end - end -end diff --git a/lib/peek/views/redis_detailed.rb b/lib/peek/views/redis_detailed.rb new file mode 100644 index 00000000000..12760c9b75e --- /dev/null +++ b/lib/peek/views/redis_detailed.rb @@ -0,0 +1,104 @@ +# frozen_string_literal: true + +require 'redis' + +module Gitlab + module Peek + module RedisInstrumented + def call(*args, &block) + start = Time.now + super(*args, &block) + ensure + duration = (Time.now - start) + add_call_details(duration, args) + end + + private + + def add_call_details(duration, args) + # redis-rb passes an array (e.g. [:get, key]) + return unless args.length == 1 + + detail_store << { + cmd: args.first, + duration: duration, + backtrace: Gitlab::Profiler.clean_backtrace(caller) + } + end + + def detail_store + ::Gitlab::SafeRequestStore['redis_call_details'] ||= [] + end + end + end +end + +module Peek + module Views + class RedisDetailed < View + REDACTED_MARKER = "" + + def key + 'redis' + end + + def results + { + calls: calls, + duration: formatted_duration, + details: details + } + end + + def detail_store + ::Gitlab::SafeRequestStore['redis_call_details'] ||= [] + end + + private + + def formatted_duration + ms = duration * 1000 + if ms >= 1000 + "%.2fms" % ms + else + "%.0fms" % ms + end + end + + def duration + detail_store.map { |entry| entry[:duration] }.sum # rubocop:disable CodeReuse/ActiveRecord + end + + def calls + detail_store.count + end + + def details + detail_store + .sort { |a, b| b[:duration] <=> a[:duration] } + .map(&method(:format_call_details)) + end + + def format_call_details(call) + call.merge(cmd: format_command(call[:cmd]), + duration: (call[:duration] * 1000).round(3)) + end + + def format_command(cmd) + if cmd.length >= 2 && cmd.first =~ /^auth$/i + cmd[-1] = REDACTED_MARKER + # Scrub out the value of the SET calls to avoid binary + # data or large data from spilling into the view + elsif cmd.length >= 3 && cmd.first =~ /set/i + cmd[2..-1] = REDACTED_MARKER + end + + cmd.join(' ') + end + end + end +end + +class Redis::Client + prepend Gitlab::Peek::RedisInstrumented +end diff --git a/spec/lib/peek/views/redis_detailed_spec.rb b/spec/lib/peek/views/redis_detailed_spec.rb index da13b6df53b..61096e6c69e 100644 --- a/spec/lib/peek/views/redis_detailed_spec.rb +++ b/spec/lib/peek/views/redis_detailed_spec.rb @@ -2,14 +2,8 @@ require 'spec_helper' -describe Peek::Views::RedisDetailed do - let(:redis_detailed_class) do - Class.new do - include Peek::Views::RedisDetailed - end - end - - subject { redis_detailed_class.new } +describe Peek::Views::RedisDetailed, :request_store do + subject { described_class.new } using RSpec::Parameterized::TableSyntax @@ -22,15 +16,24 @@ describe Peek::Views::RedisDetailed do end with_them do - it 'scrubs Redis commands', :request_store do + it 'scrubs Redis commands' do subject.detail_store << { cmd: cmd, duration: 1.second } - expect(subject.details.count).to eq(1) - expect(subject.details.first) + expect(subject.results[:details].count).to eq(1) + expect(subject.results[:details].first) .to eq({ cmd: expected, duration: 1000 }) end end + + it 'returns aggregated results' do + subject.detail_store << { cmd: [:get, 'test'], duration: 0.001 } + subject.detail_store << { cmd: [:get, 'test'], duration: 1.second } + + expect(subject.results[:calls]).to eq(2) + expect(subject.results[:duration]).to eq('1001.00ms') + expect(subject.results[:details].count).to eq(2) + end end -- cgit v1.2.1