From 51939772e6737200a674b16c8e4cf45c329f05ba Mon Sep 17 00:00:00 2001 From: Matt Sanders Date: Thu, 3 Jul 2014 14:57:21 -0700 Subject: [PATCH 1/3] Use controller.action.format as source for instrument_action --- lib/librato/rails/subscribers/controller.rb | 15 ++++++++------- test/integration/instrument_action_test.rb | 7 ++++--- 2 files changed, 12 insertions(+), 10 deletions(-) diff --git a/lib/librato/rails/subscribers/controller.rb b/lib/librato/rails/subscribers/controller.rb index b9284ca..89b5a6b 100644 --- a/lib/librato/rails/subscribers/controller.rb +++ b/lib/librato/rails/subscribers/controller.rb @@ -56,17 +56,18 @@ def self.watch_controller_action(controller, action) end # end group if @watches && @watches.index("#{controller}##{action}") - page_key = "#{controller}.#{action}.#{format}" - collector.group "rails.action.#{page_key}" do |r| + source = "#{controller}.#{action}.#{format}" + collector.group 'rails.action.request' do |r| - r.increment 'total' - r.timing 'time', event.duration + r.increment 'total', source: source + r.increment 'slow' if event.duration > 200.0 + r.timing 'time', event.duration, source: source if exception - r.increment 'exceptions' + r.increment 'exceptions', source: source else - r.timing 'time.db', event.payload[:db_runtime] || 0 - r.timing 'time.view', event.payload[:view_runtime] || 0 + r.timing 'time.db', event.payload[:db_runtime] || 0, source: source + r.timing 'time.view', event.payload[:view_runtime] || 0, source: source end end diff --git a/test/integration/instrument_action_test.rb b/test/integration/instrument_action_test.rb index 65a56c3..c3a80fa 100644 --- a/test/integration/instrument_action_test.rb +++ b/test/integration/instrument_action_test.rb @@ -8,14 +8,15 @@ class InstrumentActionTest < ActiveSupport::IntegrationCase # puts aggregate.instance_variable_get(:@cache).queued.inspect # puts counters.instance_variable_get(:@cache).inspect - base = 'rails.action.InstrumentActionController.inst.html' + source = 'InstrumentActionController.inst.html' + base = 'rails.action.request' timings = %w{time time.db time.view} timings.each do |t| - assert_equal 1, aggregate["#{base}.#{t}"][:count] + assert_equal 1, aggregate.fetch("#{base}.#{t}", source: source)[:count] end - assert_equal 1, counters["#{base}.total"] + assert_equal 1, counters.fetch("#{base}.total", source: source) end end From acb1cf7d03073fd3c4d096f69c43f187d58c54bb Mon Sep 17 00:00:00 2001 From: Matt Sanders Date: Thu, 3 Jul 2014 15:30:17 -0700 Subject: [PATCH 2/3] Fix source for instrument_action slow events --- lib/librato/rails/subscribers/controller.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/librato/rails/subscribers/controller.rb b/lib/librato/rails/subscribers/controller.rb index 89b5a6b..cf8f708 100644 --- a/lib/librato/rails/subscribers/controller.rb +++ b/lib/librato/rails/subscribers/controller.rb @@ -60,7 +60,7 @@ def self.watch_controller_action(controller, action) collector.group 'rails.action.request' do |r| r.increment 'total', source: source - r.increment 'slow' if event.duration > 200.0 + r.increment 'slow', source: source if event.duration > 200.0 r.timing 'time', event.duration, source: source if exception From a5dd5caaf5827311bd2839278dfb39da295525aa Mon Sep 17 00:00:00 2001 From: Matt Sanders Date: Thu, 3 Jul 2014 15:45:08 -0700 Subject: [PATCH 3/3] Update README for revised instrument_action naming scheme --- README.md | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/README.md b/README.md index 267752b..53e62bd 100644 --- a/README.md +++ b/README.md @@ -183,9 +183,16 @@ class CommentController < ApplicationController end ``` -Once you instrument an action, `librato-rails` will start reporting a set of metrics specific to that action including # of requests, total time used per request, and db and view time used per request. +Once you instrument an action, `librato-rails` will start reporting a set of metrics specific to that action including: -Action instrumentation metrics are named following the format `rails.action....*`. +* rails.action.request.total (# of requests) +* rails.action.request.slow (requests >= 200ms to produce) +* rails.action.request.exceptions +* rails.action.request.time (total time spent in action) +* rails.action.request.time.db (db interaction time) +* rails.action.request.time.view (view rendering time) + +Each instrumented action will appear as a source for the `rails.action.*` metrics, for example `mycontroller.action.html`. IMPORTANT NOTE: Metrics from `instrument_action` take into account all time spent in the ActionController stack for that action, including before/after filters and any global processing. They are _not_ equivalent to using a `Librato.timing` block inside the method body.