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 <evizitei@instructure.com>
Tested-by: Jenkins
QA-Review: Jeremy Putnam <jeremyp@instructure.com>
Product-Review: Ethan Vizitei <evizitei@instructure.com>

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

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

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

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

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

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