From d022ce865502c051c9177fc0f5b2453eae7e7cc2 Mon Sep 17 00:00:00 2001 From: Andrew Newdigate Date: Mon, 28 Jan 2019 15:47:48 +0200 Subject: 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. --- .../unreleased/an-opentracing-render-tracing.yml | 5 + config/initializers/tracing.rb | 1 + lib/gitlab/tracing/rails/action_view_subscriber.rb | 75 +++++++++++ .../tracing/rails/active_record_subscriber.rb | 27 ++-- lib/gitlab/tracing/rails/rails_common.rb | 24 ++++ .../tracing/rails/action_view_subscriber_spec.rb | 147 +++++++++++++++++++++ .../tracing/rails/active_record_subscriber_spec.rb | 8 +- 7 files changed, 275 insertions(+), 12 deletions(-) create mode 100644 changelogs/unreleased/an-opentracing-render-tracing.yml create mode 100644 lib/gitlab/tracing/rails/action_view_subscriber.rb create mode 100644 lib/gitlab/tracing/rails/rails_common.rb create mode 100644 spec/lib/gitlab/tracing/rails/action_view_subscriber_spec.rb diff --git a/changelogs/unreleased/an-opentracing-render-tracing.yml b/changelogs/unreleased/an-opentracing-render-tracing.yml new file mode 100644 index 00000000000..6ff7f1f3cf2 --- /dev/null +++ b/changelogs/unreleased/an-opentracing-render-tracing.yml @@ -0,0 +1,5 @@ +--- +title: Add OpenTracing instrumentation for Action View Render events +merge_request: 24728 +author: +type: other diff --git a/config/initializers/tracing.rb b/config/initializers/tracing.rb index d5bef8edb43..ddd91150c90 100644 --- a/config/initializers/tracing.rb +++ b/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 diff --git a/lib/gitlab/tracing/rails/action_view_subscriber.rb b/lib/gitlab/tracing/rails/action_view_subscriber.rb new file mode 100644 index 00000000000..88816e1fb32 --- /dev/null +++ b/lib/gitlab/tracing/rails/action_view_subscriber.rb @@ -0,0 +1,75 @@ +# 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 diff --git a/lib/gitlab/tracing/rails/active_record_subscriber.rb b/lib/gitlab/tracing/rails/active_record_subscriber.rb index 214eac47e14..32f5658e57e 100644 --- a/lib/gitlab/tracing/rails/active_record_subscriber.rb +++ b/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 diff --git a/lib/gitlab/tracing/rails/rails_common.rb b/lib/gitlab/tracing/rails/rails_common.rb new file mode 100644 index 00000000000..88e914f62f8 --- /dev/null +++ b/lib/gitlab/tracing/rails/rails_common.rb @@ -0,0 +1,24 @@ +# 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 diff --git a/spec/lib/gitlab/tracing/rails/action_view_subscriber_spec.rb b/spec/lib/gitlab/tracing/rails/action_view_subscriber_spec.rb new file mode 100644 index 00000000000..c9d1a06b3e6 --- /dev/null +++ b/spec/lib/gitlab/tracing/rails/action_view_subscriber_spec.rb @@ -0,0 +1,147 @@ +# 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 diff --git a/spec/lib/gitlab/tracing/rails/active_record_subscriber_spec.rb b/spec/lib/gitlab/tracing/rails/active_record_subscriber_spec.rb index 5eb5c044f84..3d066843148 100644 --- a/spec/lib/gitlab/tracing/rails/active_record_subscriber_spec.rb +++ b/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 -- cgit v1.2.1