Merge pull request #256 from instana/hm/ruby-trace-stats

Report statistics on generated traces

Author: hmadison

lib/instana/backend/host_agent_reporting_observer.rb

@@ -9,6 +9,7 @@ class HostAgentReportingObserver
       ENTITY_DATA_URL = '/com.instana.plugin.ruby.%i'.freeze
       RESPONSE_DATA_URL = '/com.instana.plugin.ruby/response.%i?messageId=%s'.freeze
       TRACES_DATA_URL = "/com.instana.plugin.ruby/traces.%i".freeze
+      TRACE_METRICS_URL = "/tracermetrics".freeze
 
       attr_reader :report_timer
 
@@ -35,10 +36,24 @@ def update(time, _old_version, new_version)
       def report_to_backend
         report_metrics if ::Instana.config[:metrics][:enabled]
         report_traces if ::Instana.config[:tracing][:enabled]
+        report_trace_stats if ::Instana.config[:tracing][:enabled]
       rescue StandardError => e
         @logger.error(%(#{e}\n#{e.backtrace.join("\n")}))
       end
 
+      def report_trace_stats
+        discovery = @discovery.value
+        return unless discovery
+
+        payload = {
+          tracer: 'ruby',
+          pid: discovery['pid'],
+          metrics: @processor.span_metrics
+        }
+
+        @client.send_request('POST', TRACE_METRICS_URL, payload)
+      end
+
       def report_traces
         discovery = @discovery.value
         return unless discovery

lib/instana/instrumentation/active_record.rb

@@ -19,7 +19,7 @@ def log(sql, name = 'SQL', binds = [], *args)
           }
         }
 
-        if binds.all? { |b| b.respond_to?(:value_before_type_cast) }
+        if binds.all? { |b| b.respond_to?(:value_before_type_cast) } && !::Instana.config[:sanitize_sql]
           mapped = binds.map(&:value_before_type_cast)
           call_payload[:activerecord][:binds] = mapped
         end

lib/instana/tracing/processor.rb

@@ -20,6 +20,9 @@ def initialize(logger: ::Instana.logger)
       @batch_size = 3000
       @logger = logger
       @pid = Process.pid
+
+      @spans_opened = Concurrent::AtomicFixnum.new(0)
+      @spans_closed = Concurrent::AtomicFixnum.new(0)
     end
 
     # Adds a span to the span queue
@@ -34,9 +37,31 @@ def add_span(span)
       end
       # :nocov:
 
+      @spans_closed.increment
       @queue.push(span)
     end
 
+    # Note that we've started a new span. Used to
+    # generate monitoring metrics.
+    def start_span(_)
+      @spans_opened.increment
+    end
+
+    # Clears and retrieves metrics associated with span creation and submission
+    def span_metrics
+      response = {
+        opened: @spans_opened.value,
+        closed: @spans_closed.value,
+        filtered: 0,
+        dropped: 0
+      }
+
+      @spans_opened.value = 0
+      @spans_closed.value = 0
+
+      response
+    end
+
     ##
     # send
     #
@@ -82,6 +107,9 @@ def queued_spans
     # test suite to reset state.
     #
     def clear!
+      @spans_opened.value = 0
+      @spans_closed.value = 0
+
       until @queue.empty? do
         # Non-blocking pop; ignore exception
         @queue.pop(true) rescue nil

lib/instana/tracing/span.rb

@@ -71,6 +71,8 @@ def initialize(name, parent_ctx: nil, start_time: ::Instana::Util.now_in_ms)
         configure_custom(name)
       end
 
+      ::Instana.processor.start_span(self)
+
       # Attach a backtrace to all exit spans
       add_stack if ::Instana.config[:collect_backtraces] && exit_span?
     end

test/backend/host_agent_reporting_observer_test.rb

@@ -23,6 +23,8 @@ def test_start_stop
   end
 
   def test_report
+    stub_request(:post, "http://10.10.10.10:9292/tracermetrics")
+      .to_return(status: 200)
     stub_request(:post, "http://10.10.10.10:9292/com.instana.plugin.ruby.0")
       .to_return(status: 200)
 
@@ -35,6 +37,8 @@ def test_report
   end
 
   def test_report_fail
+    stub_request(:post, "http://10.10.10.10:9292/tracermetrics")
+      .to_return(status: 200)
     stub_request(:post, "http://10.10.10.10:9292/com.instana.plugin.ruby.0")
       .to_return(status: 500)
 
@@ -54,6 +58,9 @@ def test_agent_action
       args: {file: 'test_helper.rb'}
     )
 
+    stub_request(:post, "http://10.10.10.10:9292/tracermetrics")
+      .to_return(status: 200)
+
     stub_request(:post, "http://10.10.10.10:9292/com.instana.plugin.ruby.0")
       .to_return(status: 200, body: action)
 
@@ -75,6 +82,9 @@ def test_agent_actions
                          args: {file: 'test_helper.rb'}
                        ])
 
+    stub_request(:post, "http://10.10.10.10:9292/tracermetrics")
+      .to_return(status: 200)
+
     stub_request(:post, "http://10.10.10.10:9292/com.instana.plugin.ruby.0")
       .to_return(status: 200, body: action)
 
@@ -90,6 +100,9 @@ def test_agent_actions
   end
 
   def test_agent_action_error
+    stub_request(:post, "http://10.10.10.10:9292/tracermetrics")
+      .to_return(status: 200)
+
     stub_request(:post, "http://10.10.10.10:9292/com.instana.plugin.ruby.0")
       .to_return(status: 200, body: 'INVALID')
 

test/instrumentation/rails_active_record_test.rb

@@ -38,8 +38,6 @@ def test_create
     data = span[:data][:activerecord]
 
     assert data[:sql].start_with?('INSERT INTO')
-    assert 'core', data[:binds][0]
-    assert 'blue', data[:binds][1]
   end
 
   def test_read
@@ -54,8 +52,6 @@ def test_read
     data = span[:data][:activerecord]
 
     assert data[:sql].start_with?('SELECT')
-    assert 'core', data[:binds][0]
-    assert 1, data[:binds][1]
   end
 
   def test_update
@@ -73,8 +69,6 @@ def test_update
     data = span[:data][:activerecord]
 
     assert data[:sql].start_with?('UPDATE')
-    assert 'red', data[:binds][0]
-    assert 1, data[:binds][2]
   end
 
   def test_delete
@@ -90,7 +84,6 @@ def test_delete
     data = span[:data][:activerecord]
 
     assert data[:sql].start_with?('DELETE')
-    assert 1, data[:binds][0]
   end
 
   def test_raw

test/tracing/span_test.rb

@@ -133,4 +133,21 @@ def test_log_error
     assert_equal({}, span.tags)
     time.verify
   end
+
+  def test_inc_processed_counts
+    clear_all!
+
+    span = Instana::Span.new(:excon)
+    span.close
+
+    metrics = Instana.processor.span_metrics
+
+    assert_equal 1, metrics[:opened]
+    assert_equal 1, metrics[:closed]
+
+    metrics = Instana.processor.span_metrics
+
+    assert_equal 0, metrics[:opened]
+    assert_equal 0, metrics[:closed]
+  end
 end