Add OpenTracing instrumentation for Action View Render events

This change adds three new instrumentations, driven through rails
notifications: render_template.action_view,
render_collection.action_view and render_partial.action_view.

These can help developers understand why renders are taking a long
time which may in turn help them to improve their performance.

changelogs/unreleased/an-opentracing-render-tracing.yml

+---
+title: Add OpenTracing instrumentation for Action View Render events
+merge_request: 24728
+author:
+type: other

config/initializers/tracing.rb

@@ -25,6 +25,7 @@ if Gitlab::Tracing.enabled?
 
   # Instrument Rails
   Gitlab::Tracing::Rails::ActiveRecordSubscriber.instrument
+  Gitlab::Tracing::Rails::ActionViewSubscriber.instrument
 
   # In multi-processed clustered architectures (puma, unicorn) don't
   # start tracing until the worker processes are spawned. This works

lib/gitlab/tracing/rails/action_view_subscriber.rb

+# frozen_string_literal: true
+
+module Gitlab
+  module Tracing
+    module Rails
+      class ActionViewSubscriber
+        include RailsCommon
+
+        COMPONENT_TAG = 'ActionView'
+        RENDER_TEMPLATE_NOTIFICATION_TOPIC = 'render_template.action_view'
+        RENDER_COLLECTION_NOTIFICATION_TOPIC = 'render_collection.action_view'
+        RENDER_PARTIAL_NOTIFICATION_TOPIC = 'render_partial.action_view'
+
+        # Instruments Rails ActionView events for opentracing.
+        # Returns a lambda, which, when called will unsubscribe from the notifications
+        def self.instrument
+          subscriber = new
+
+          subscriptions = [
+            ActiveSupport::Notifications.subscribe(RENDER_TEMPLATE_NOTIFICATION_TOPIC) do |_, start, finish, _, payload|
+              subscriber.notify_render_template(start, finish, payload)
+            end,
+            ActiveSupport::Notifications.subscribe(RENDER_COLLECTION_NOTIFICATION_TOPIC) do |_, start, finish, _, payload|
+              subscriber.notify_render_collection(start, finish, payload)
+            end,
+            ActiveSupport::Notifications.subscribe(RENDER_PARTIAL_NOTIFICATION_TOPIC) do |_, start, finish, _, payload|
+              subscriber.notify_render_partial(start, finish, payload)
+            end
+          ]
+
+          create_unsubscriber subscriptions
+        end
+
+        # For more information on the payloads: https://guides.rubyonrails.org/active_support_instrumentation.html
+        def notify_render_template(start, finish, payload)
+          generate_span_for_notification("render_template", start, finish, payload, tags_for_render_template(payload))
+        end
+
+        def notify_render_collection(start, finish, payload)
+          generate_span_for_notification("render_collection", start, finish, payload, tags_for_render_collection(payload))
+        end
+
+        def notify_render_partial(start, finish, payload)
+          generate_span_for_notification("render_partial", start, finish, payload, tags_for_render_partial(payload))
+        end
+
+        private
+
+        def tags_for_render_template(payload)
+          {
+            'component' =>       COMPONENT_TAG,
+            'template.id' =>     payload[:identifier],
+            'template.layout' => payload[:layout]
+          }
+        end
+
+        def tags_for_render_collection(payload)
+          {
+            'component' =>            COMPONENT_TAG,
+            'template.id' =>          payload[:identifier],
+            'template.count' =>       payload[:count] || 0,
+            'template.cache.hits' =>  payload[:cache_hits] || 0
+          }
+        end
+
+        def tags_for_render_partial(payload)
+          {
+            'component' =>            COMPONENT_TAG,
+            'template.id' =>          payload[:identifier]
+          }
+        end
+      end
+    end
+  end
+end

lib/gitlab/tracing/rails/active_record_subscriber.rb

@@ -4,24 +4,37 @@ module Gitlab
   module Tracing
     module Rails
       class ActiveRecordSubscriber
-        include Gitlab::Tracing::Common
+        include RailsCommon
 
         ACTIVE_RECORD_NOTIFICATION_TOPIC = 'sql.active_record'
-        DEFAULT_OPERATION_NAME = "sqlquery"
+        OPERATION_NAME_PREFIX = 'active_record:'
+        DEFAULT_OPERATION_NAME = 'sqlquery'
 
+        # Instruments Rails ActiveRecord events for opentracing.
+        # Returns a lambda, which, when called will unsubscribe from the notifications
         def self.instrument
           subscriber = new
 
-          ActiveSupport::Notifications.subscribe(ACTIVE_RECORD_NOTIFICATION_TOPIC) do |_, start, finish, _, payload|
+          subscription = ActiveSupport::Notifications.subscribe(ACTIVE_RECORD_NOTIFICATION_TOPIC) do |_, start, finish, _, payload|
             subscriber.notify(start, finish, payload)
           end
+
+          create_unsubscriber [subscription]
         end
 
         # For more information on the payloads: https://guides.rubyonrails.org/active_support_instrumentation.html
         def notify(start, finish, payload)
-          operation_name = payload[:name].presence || DEFAULT_OPERATION_NAME
-          exception = payload[:exception]
-          tags = {
+          generate_span_for_notification(notification_name(payload), start, finish, payload, tags_for_notification(payload))
+        end
+
+        private
+
+        def notification_name(payload)
+          OPERATION_NAME_PREFIX + (payload[:name].presence || DEFAULT_OPERATION_NAME)
+        end
+
+        def tags_for_notification(payload)
+          {
             'component' =>        'ActiveRecord',
             'span.kind' =>        'client',
             'db.type' =>          'sql',
@@ -29,8 +42,6 @@ module Gitlab
             'db.cached' =>        payload[:cached] || false,
             'db.statement' =>     payload[:sql]
           }
-
-          postnotify_span("active_record:#{operation_name}", start, finish, tags: tags, exception: exception)
         end
       end
     end

lib/gitlab/tracing/rails/rails_common.rb

+# frozen_string_literal: true
+
+module Gitlab
+  module Tracing
+    module Rails
+      module RailsCommon
+        extend ActiveSupport::Concern
+        include Gitlab::Tracing::Common
+
+        class_methods do
+          def create_unsubscriber(subscriptions)
+            -> { subscriptions.each { |subscriber| ActiveSupport::Notifications.unsubscribe(subscriber) } }
+          end
+        end
+
+        def generate_span_for_notification(operation_name, start, finish, payload, tags)
+          exception = payload[:exception]
+
+          postnotify_span(operation_name, start, finish, tags: tags, exception: exception)
+        end
+      end
+    end
+  end
+end

spec/lib/gitlab/tracing/rails/action_view_subscriber_spec.rb

+# frozen_string_literal: true
+
+require 'fast_spec_helper'
+require 'rspec-parameterized'
+
+describe Gitlab::Tracing::Rails::ActionViewSubscriber do
+  using RSpec::Parameterized::TableSyntax
+
+  shared_examples 'an actionview notification' do
+    it 'should notify the tracer when the hash contains null values' do
+      expect(subject).to receive(:postnotify_span).with(notification_name, start, finish, tags: expected_tags, exception: exception)
+
+      subject.public_send(notify_method, start, finish, payload)
+    end
+
+    it 'should notify the tracer when the payload is missing values' do
+      expect(subject).to receive(:postnotify_span).with(notification_name, start, finish, tags: expected_tags, exception: exception)
+
+      subject.public_send(notify_method, start, finish, payload.compact)
+    end
+
+    it 'should not throw exceptions when with the default tracer' do
+      expect { subject.public_send(notify_method, start, finish, payload) }.not_to raise_error
+    end
+  end
+
+  describe '.instrument' do
+    it 'is unsubscribeable' do
+      unsubscribe = described_class.instrument
+
+      expect(unsubscribe).not_to be_nil
+      expect { unsubscribe.call }.not_to raise_error
+    end
+  end
+
+  describe '#notify_render_template' do
+    subject { described_class.new }
+    let(:start) { Time.now }
+    let(:finish) { Time.now }
+    let(:notification_name) { 'render_template' }
+    let(:notify_method) { :notify_render_template }
+
+    where(:identifier, :layout, :exception) do
+      nil         | nil           | nil
+      ""          | nil           | nil
+      "show.haml" | nil           | nil
+      nil         | ""            | nil
+      nil         | "layout.haml" | nil
+      nil         | nil           | StandardError.new
+    end
+
+    with_them do
+      let(:payload) do
+        {
+          exception: exception,
+          identifier: identifier,
+          layout: layout
+        }
+      end
+
+      let(:expected_tags) do
+        {
+          'component' =>       'ActionView',
+          'template.id' =>     identifier,
+          'template.layout' => layout
+        }
+      end
+
+      it_behaves_like 'an actionview notification'
+    end
+  end
+
+  describe '#notify_render_collection' do
+    subject { described_class.new }
+    let(:start) { Time.now }
+    let(:finish) { Time.now }
+    let(:notification_name) { 'render_collection' }
+    let(:notify_method) { :notify_render_collection }
+
+    where(
+      :identifier, :count, :expected_count, :cache_hits, :expected_cache_hits, :exception) do
+      nil         | nil           | 0 | nil | 0 | nil
+      ""          | nil           | 0 | nil | 0 | nil
+      "show.haml" | nil           | 0 | nil | 0 | nil
+      nil         | 0             | 0 | nil | 0 | nil
+      nil         | 1             | 1 | nil | 0 | nil
+      nil         | nil           | 0 | 0   | 0 | nil
+      nil         | nil           | 0 | 1   | 1 | nil
+      nil         | nil           | 0 | nil | 0 | StandardError.new
+    end
+
+    with_them do
+      let(:payload) do
+        {
+          exception: exception,
+          identifier: identifier,
+          count: count,
+          cache_hits: cache_hits
+        }
+      end
+
+      let(:expected_tags) do
+        {
+          'component' =>            'ActionView',
+          'template.id' =>          identifier,
+          'template.count' =>       expected_count,
+          'template.cache.hits' =>  expected_cache_hits
+        }
+      end
+
+      it_behaves_like 'an actionview notification'
+    end
+  end
+
+  describe '#notify_render_partial' do
+    subject { described_class.new }
+    let(:start) { Time.now }
+    let(:finish) { Time.now }
+    let(:notification_name) { 'render_partial' }
+    let(:notify_method) { :notify_render_partial }
+
+    where(:identifier, :exception) do
+      nil         | nil
+      ""          | nil
+      "show.haml" | nil
+      nil         | StandardError.new
+    end
+
+    with_them do
+      let(:payload) do
+        {
+          exception: exception,
+          identifier: identifier
+        }
+      end
+
+      let(:expected_tags) do
+        {
+          'component' =>            'ActionView',
+          'template.id' =>          identifier
+        }
+      end
+
+      it_behaves_like 'an actionview notification'
+    end
+  end
+end

spec/lib/gitlab/tracing/rails/active_record_subscriber_spec.rb

@@ -7,11 +7,11 @@ describe Gitlab::Tracing::Rails::ActiveRecordSubscriber do
   using RSpec::Parameterized::TableSyntax
 
   describe '.instrument' do
-    it 'is unsubscribable' do
-      subscription = described_class.instrument
+    it 'is unsubscribeable' do
+      unsubscribe = described_class.instrument
 
-      expect(subscription).not_to be_nil
-      expect { ActiveSupport::Notifications.unsubscribe(subscription) }.not_to raise_error
+      expect(unsubscribe).not_to be_nil
+      expect { unsubscribe.call }.not_to raise_error
     end
   end