From ae7c4868e7cb36ef898fd37f2978febbb1da3a9b Mon Sep 17 00:00:00 2001 From: Jason Madsen Date: Fri, 27 Mar 2015 14:46:06 -0600 Subject: [PATCH] report num SQL read, write, cache calls to statsd closes CNVS-19588 test plan: - enable statsd in config/statsd.yml - visit several various pages in canvas - create some things, update some things - reload a page or two - canvas should continue to function as expected - statsd request keys for controller actions should now have: - sql.read - sql.write - sql.cache Change-Id: Ia71dc4db6ab6d4c99ecf375ad708e54553d59ed5 Reviewed-on: https://gerrit.instructure.com/51157 Reviewed-by: Ethan Vizitei Tested-by: Jenkins QA-Review: Jeremy Putnam Product-Review: Ethan Vizitei --- config/initializers/statsd_timing.rb | 10 ++- .../lib/canvas_statsd/request_stat.rb | 19 +++-- .../spec/canvas_statsd/request_stat_spec.rb | 54 ++++++++++--- lib/sql_metrics/tracker.rb | 58 ++++++++++++++ spec/integration/track_memory_and_cpu_spec.rb | 4 +- spec/lib/sql_metrics/tracker_spec.rb | 75 +++++++++++++++++++ 6 files changed, 196 insertions(+), 24 deletions(-) create mode 100644 lib/sql_metrics/tracker.rb create mode 100644 spec/lib/sql_metrics/tracker_spec.rb diff --git a/config/initializers/statsd_timing.rb b/config/initializers/statsd_timing.rb index c3919156cd0..f95a72647e1 100644 --- a/config/initializers/statsd_timing.rb +++ b/config/initializers/statsd_timing.rb @@ -1,15 +1,15 @@ Aroi::Instrumentation.instrument_creation! -sql_counter = CanvasStatsd::Counter.new('sql_counter', ['SCHEMA']) ar_counter = CanvasStatsd::Counter.new('ar_counter') +sql_tracker = SqlMetrics::Tracker.new(blocked_names: ['SCHEMA']) ActiveSupport::Notifications.subscribe(/start_processing.action_controller/) do |*args| - sql_counter.start + sql_tracker.start ar_counter.start end ActiveSupport::Notifications.subscribe(/sql.active_record/) do |name, start, finish, id, payload| - sql_counter.track payload.fetch(:name) + sql_tracker.track payload.fetch(:name), payload.fetch(:sql) end ActiveSupport::Notifications.subscribe(/instance.active_record/) do |name, start, finish, id, payload| @@ -18,7 +18,9 @@ end ActiveSupport::Notifications.subscribe(/process_action.action_controller/) do |*args| request_stat = CanvasStatsd::RequestStat.new(*args) - request_stat.sql_count = sql_counter.finalize_count request_stat.ar_count = ar_counter.finalize_count + request_stat.sql_read_count = sql_tracker.num_reads + request_stat.sql_write_count = sql_tracker.num_writes + request_stat.sql_cache_count = sql_tracker.num_caches request_stat.report end diff --git a/gems/canvas_statsd/lib/canvas_statsd/request_stat.rb b/gems/canvas_statsd/lib/canvas_statsd/request_stat.rb index 35b4d4e4e4b..92c7465a756 100644 --- a/gems/canvas_statsd/lib/canvas_statsd/request_stat.rb +++ b/gems/canvas_statsd/lib/canvas_statsd/request_stat.rb @@ -1,7 +1,9 @@ module CanvasStatsd class RequestStat - attr_accessor :sql_count + attr_accessor :sql_read_count + attr_accessor :sql_write_count + attr_accessor :sql_cache_count attr_accessor :ar_count def initialize(name, start, finish, id, payload, statsd=CanvasStatsd::Statsd) @@ -15,11 +17,14 @@ module CanvasStatsd def report if controller && action - @statsd.timing("request.#{controller}.#{action}.total", ms) - @statsd.timing("request.#{controller}.#{action}.view", view_runtime) if view_runtime - @statsd.timing("request.#{controller}.#{action}.db", db_runtime) if db_runtime - @statsd.timing("request.#{controller}.#{action}.sql", sql_count) if sql_count - @statsd.timing("request.#{controller}.#{action}.active_record", ar_count) if ar_count + common_key = "request.#{controller}.#{action}" + @statsd.timing("#{common_key}.total", ms) + @statsd.timing("#{common_key}.view", view_runtime) if view_runtime + @statsd.timing("#{common_key}.db", db_runtime) if db_runtime + @statsd.timing("#{common_key}.sql.read", sql_read_count) if sql_read_count + @statsd.timing("#{common_key}.sql.write", sql_write_count) if sql_write_count + @statsd.timing("#{common_key}.sql.cache", sql_cache_count) if sql_cache_count + @statsd.timing("#{common_key}.active_record", ar_count) if ar_count end end @@ -32,7 +37,7 @@ module CanvasStatsd end def controller - @payload.fetch(:params, {})['controller'] + @payload.fetch(:params, {})['controller'] end def action diff --git a/gems/canvas_statsd/spec/canvas_statsd/request_stat_spec.rb b/gems/canvas_statsd/spec/canvas_statsd/request_stat_spec.rb index 93c0896d5a2..abe81bd2bb5 100644 --- a/gems/canvas_statsd/spec/canvas_statsd/request_stat_spec.rb +++ b/gems/canvas_statsd/spec/canvas_statsd/request_stat_spec.rb @@ -121,20 +121,50 @@ describe CanvasStatsd::RequestStat do rs.report end - it 'sends sql_count when present' do - statsd = double - payload = { - params: { - 'controller' => 'foo', - 'action' => 'index' + describe 'sql stats' do + + before :each do + @statsd = double + payload = { + params: { + 'controller' => 'foo', + 'action' => 'index' + } } - } - rs = create_subject(payload, statsd) - rs.sql_count = 10 - allow(statsd).to receive(:timing).with('request.foo.index.total', 1000) - expect(statsd).to receive(:timing).with('request.foo.index.sql', 10) - rs.report + @rs = create_subject(payload, @statsd) + end + + it 'doesnt send sql stats when they dont exist' do + allow(@statsd).to receive(:timing).with('request.foo.index.total', 1000) + expect(@statsd).to_not receive(:timing).with('request.foo.index.sql.read', kind_of(Numeric)) + expect(@statsd).to_not receive(:timing).with('request.foo.index.sql.write', kind_of(Numeric)) + expect(@statsd).to_not receive(:timing).with('request.foo.index.sql.cache', kind_of(Numeric)) + @rs.report + end + + it 'sends sql_read_count when present' do + @rs.sql_read_count = 10 + allow(@statsd).to receive(:timing).with('request.foo.index.total', 1000) + expect(@statsd).to receive(:timing).with('request.foo.index.sql.read', 10) + @rs.report + end + + it 'sends sql_read_count when present' do + @rs.sql_write_count = 3 + allow(@statsd).to receive(:timing).with('request.foo.index.total', 1000) + expect(@statsd).to receive(:timing).with('request.foo.index.sql.write', 3) + @rs.report + end + + it 'sends sql_cache_count when present' do + @rs.sql_cache_count = 1 + allow(@statsd).to receive(:timing).with('request.foo.index.total', 1000) + expect(@statsd).to receive(:timing).with('request.foo.index.sql.cache', 1) + @rs.report + end + end + end end diff --git a/lib/sql_metrics/tracker.rb b/lib/sql_metrics/tracker.rb new file mode 100644 index 00000000000..9d1fce976de --- /dev/null +++ b/lib/sql_metrics/tracker.rb @@ -0,0 +1,58 @@ +module SqlMetrics + class Tracker + + attr_reader :blocked_names + + attr_reader :read_counts + attr_reader :write_counts + attr_reader :cache_counts + + def initialize(opts=nil) + opts ||= {} + @blocked_names = opts.fetch(:blocked_names, []) + @read_counts = opts.fetch(:read_counter, CanvasStatsd::Counter.new('sql_read_counter')) + @write_counts = opts.fetch(:write_counter, CanvasStatsd::Counter.new('sql_write_counter')) + @cache_counts = opts.fetch(:cache_counter, CanvasStatsd::Counter.new('sql_cache_counter')) + end + + def start + [read_counts, write_counts, cache_counts].each(&:start) + end + + def track name, sql + return unless sql && accepted_name?(name) + + if name.match(/CACHE/) + cache_counts.track name + elsif truncate(sql).match(/SELECT/) || name.match(/LOAD/) + read_counts.track(sql) + else + write_counts.track(sql) + end + end + + def num_reads + read_counts.finalize_count + end + + def num_writes + write_counts.finalize_count + end + + def num_caches + cache_counts.finalize_count + end + + private + + def accepted_name?(name) + !!(name && !blocked_names.include?(name)) + end + + def truncate(sql) + sql ||= '' + sql.strip[0..15] + end + + end +end diff --git a/spec/integration/track_memory_and_cpu_spec.rb b/spec/integration/track_memory_and_cpu_spec.rb index f032f949090..776fc1bb9bf 100644 --- a/spec/integration/track_memory_and_cpu_spec.rb +++ b/spec/integration/track_memory_and_cpu_spec.rb @@ -16,8 +16,10 @@ describe "memory and cpu tracking", type: :request do CanvasStatsd::Statsd.expects(:timing).with('request.users.user_dashboard.total', kind_of(Numeric)) # user_dashboard_view doesn't get populated here as there is no view_runtime to populate CanvasStatsd::Statsd.expects(:timing).with('request.users.user_dashboard.db', kind_of(Numeric)) - CanvasStatsd::Statsd.expects(:timing).with('request.users.user_dashboard.sql', kind_of(Numeric)) CanvasStatsd::Statsd.expects(:timing).with('request.users.user_dashboard.active_record', kind_of(Numeric)) + CanvasStatsd::Statsd.expects(:timing).with('request.users.user_dashboard.sql.read', kind_of(Numeric)) + CanvasStatsd::Statsd.expects(:timing).with('request.users.user_dashboard.sql.write', kind_of(Numeric)) + CanvasStatsd::Statsd.expects(:timing).with('request.users.user_dashboard.sql.cache', kind_of(Numeric)) get "/" end end diff --git a/spec/lib/sql_metrics/tracker_spec.rb b/spec/lib/sql_metrics/tracker_spec.rb new file mode 100644 index 00000000000..29f9965ecd4 --- /dev/null +++ b/spec/lib/sql_metrics/tracker_spec.rb @@ -0,0 +1,75 @@ +require_relative '../../spec_helper' + +module SqlMetrics + describe Tracker do + + describe '#start' do + it 'resets values to zero' do + subject = Tracker.new + subject.start + subject.track 'CACHE', 'SELECT * FROM some_table' + subject.start + expect(subject.num_caches).to eq(0) + expect(subject.num_reads).to eq(0) + expect(subject.num_writes).to eq(0) + end + end + + describe '#track' do + before :each do + @subject = Tracker.new + @subject.start + end + + it 'considers CACHE above all' do + @subject.track 'CACHE', 'SELECT * FROM some_table' + expect(@subject.num_caches).to eq(1) + expect(@subject.num_reads).to eq(0) + end + + it 'marks as read when select is in the first 15 chars of the sql' do + @subject.track 'LOAD', ' SELECT "context_external_tools".* FROM' + expect(@subject.num_reads).to eq(1) + expect(@subject.num_writes).to eq(0) + end + + it 'marks as read with no select, but a LOAD name' do + @subject.track 'LOAD', 'WITH RECURSIVE t AS' + expect(@subject.num_reads).to eq(1) + expect(@subject.num_writes).to eq(0) + end + + it 'doesnt track names set as blocked' do + tracker = Tracker.new(blocked_names: ['SCHEMA']) + tracker.start + tracker.track 'SCHEMA', 'SELECT * FROM some_table' + expect(tracker.num_reads).to eq(0) + end + + it 'doesnt track nil names or sql values' do + @subject.track nil, 'SELECT *' + @subject.track 'CACHE', nil + expect(@subject.num_reads).to eq(0) + end + + it 'passes full sql to counter.track calls for reads' do + sql = ' SELECT \'context_external_tools\'.* FROM' + read_counter = mock(:start) + read_counter.expects(:track).with(sql) + tracker = Tracker.new(read_counter: read_counter) + tracker.start + tracker.track 'LOAD', sql + end + + it 'passes full sql to counter.track calls for writes' do + sql = ' UPDATE \'context_external_tools\'.* FROM' + write_counter = mock(:start) + write_counter.expects(:track).with(sql) + tracker = Tracker.new(write_counter: write_counter) + tracker.start + tracker.track 'UPDATE', sql + end + end + + end +end