Merge branch 'sherlock' into 'master'

See merge request !1749

8 files changed, 524 insertions, 0 deletions

diff --git a/lib/gitlab/sherlock/collection.rb b/lib/gitlab/sherlock/collection.rb
new file mode 100644
index 00000000000..66bd6258521
--- /dev/null
+++ b/lib/gitlab/sherlock/collection.rb
@@ -0,0 +1,49 @@
+module Gitlab
+  module Sherlock
+    # A collection of transactions recorded by Sherlock.
+    #
+    # Method calls for this class are synchronized using a mutex to allow
+    # sharing of a single Collection instance between threads (e.g. when using
+    # Puma as a webserver).
+    class Collection
+      include Enumerable
+
+      def initialize
+        @transactions = []
+        @mutex = Mutex.new
+      end
+
+      def add(transaction)
+        synchronize { @transactions << transaction }
+      end
+
+      alias_method :<<, :add
+
+      def each(&block)
+        synchronize { @transactions.each(&block) }
+      end
+
+      def clear
+        synchronize { @transactions.clear }
+      end
+
+      def empty?
+        synchronize { @transactions.empty? }
+      end
+
+      def find_transaction(id)
+        find { |trans| trans.id == id }
+      end
+
+      def newest_first
+        sort { |a, b| b.finished_at <=> a.finished_at }
+      end
+
+      private
+
+      def synchronize(&block)
+        @mutex.synchronize(&block)
+      end
+    end
+  end
+end
diff --git a/lib/gitlab/sherlock/file_sample.rb b/lib/gitlab/sherlock/file_sample.rb
new file mode 100644
index 00000000000..8a3e1a5e5bf
--- /dev/null
+++ b/lib/gitlab/sherlock/file_sample.rb
@@ -0,0 +1,31 @@
+module Gitlab
+  module Sherlock
+    class FileSample
+      attr_reader :id, :file, :line_samples, :events, :duration
+
+      # file - The full path to the file this sample belongs to.
+      # line_samples - An array of LineSample objects.
+      # duration - The total execution time in milliseconds.
+      # events - The total amount of events.
+      def initialize(file, line_samples, duration, events)
+        @id = SecureRandom.uuid
+        @file = file
+        @line_samples = line_samples
+        @duration = duration
+        @events = events
+      end
+
+      def relative_path
+        @relative_path ||= @file.gsub(/^#{Rails.root.to_s}\/?/, '')
+      end
+
+      def to_param
+        @id
+      end
+
+      def source
+        @source ||= File.read(@file)
+      end
+    end
+  end
+end
diff --git a/lib/gitlab/sherlock/line_profiler.rb b/lib/gitlab/sherlock/line_profiler.rb
new file mode 100644
index 00000000000..152749dcc39
--- /dev/null
+++ b/lib/gitlab/sherlock/line_profiler.rb
@@ -0,0 +1,96 @@
+module Gitlab
+  module Sherlock
+    # Class for profiling code on a per line basis.
+    #
+    # The LineProfiler class can be used to profile code on per line basis
+    # without littering your code with Ruby implementation specific profiling
+    # methods.
+    #
+    # This profiler only includes samples taking longer than a given threshold
+    # and those that occur in the actual application (e.g. files from Gems are
+    # ignored).
+    class LineProfiler
+      # The minimum amount of time that has to be spent in a file for it to be
+      # included in a list of samples.
+      MINIMUM_DURATION = 10.0
+
+      # Profiles the given block.
+      #
+      # Example:
+      #
+      #     profiler = LineProfiler.new
+      #
+      #     retval, samples = profiler.profile do
+      #       "cats are amazing"
+      #     end
+      #
+      #     retval  # => "cats are amazing"
+      #     samples # => [#<Gitlab::Sherlock::FileSample ...>, ...]
+      #
+      # Returns an Array containing the block's return value and an Array of
+      # FileSample objects.
+      def profile(&block)
+        if mri?
+          profile_mri(&block)
+        else
+          raise NotImplementedError,
+            'Line profiling is not supported on this platform'
+        end
+      end
+
+      # Profiles the given block using rblineprof (MRI only).
+      def profile_mri
+        retval  = nil
+        samples = lineprof(/^#{Rails.root.to_s}/) { retval = yield }
+
+        file_samples = aggregate_rblineprof(samples)
+
+        [retval, file_samples]
+      end
+
+      # Returns an Array of file samples based on the output of rblineprof.
+      #
+      # lineprof_stats - A Hash containing rblineprof statistics on a per file
+      #                  basis.
+      #
+      # Returns an Array of FileSample objects.
+      def aggregate_rblineprof(lineprof_stats)
+        samples = []
+
+        lineprof_stats.each do |(file, stats)|
+          source_lines = File.read(file).each_line.to_a
+          line_samples = []
+
+          total_duration = microsec_to_millisec(stats[0][0])
+          total_events   = stats[0][2]
+
+          next if total_duration <= MINIMUM_DURATION
+
+          stats[1..-1].each_with_index do |data, index|
+            next unless source_lines[index]
+
+            duration = microsec_to_millisec(data[0])
+            events   = data[2]
+
+            line_samples << LineSample.new(duration, events)
+          end
+
+          samples << FileSample.
+            new(file, line_samples, total_duration, total_events)
+        end
+
+        samples
+      end
+
+      private
+
+      def microsec_to_millisec(microsec)
+        microsec / 1000.0
+      end
+
+      def mri?
+        RUBY_ENGINE == 'ruby'
+      end
+    end
+  end
+end
diff --git a/lib/gitlab/sherlock/line_sample.rb b/lib/gitlab/sherlock/line_sample.rb
new file mode 100644
index 00000000000..eb1948eb6d6
--- /dev/null
+++ b/lib/gitlab/sherlock/line_sample.rb
@@ -0,0 +1,36 @@
+module Gitlab
+  module Sherlock
+    class LineSample
+      attr_reader :duration, :events
+
+      # duration - The execution time in milliseconds.
+      # events - The amount of events.
+      def initialize(duration, events)
+        @duration = duration
+        @events = events
+      end
+
+      # Returns the sample duration percentage relative to the given duration.
+      #
+      # Example:
+      #
+      #     sample.duration            # => 150
+      #     sample.percentage_of(1500) # => 10.0
+      #
+      # total_duration - The total duration to compare with.
+      #
+      # Returns a float
+      def percentage_of(total_duration)
+        (duration.to_f / total_duration) * 100.0
+      end
+
+      # Returns true if the current sample takes up the majority of the given
+      # duration.
+      #
+      # total_duration - The total duration to compare with.
+      def majority_of?(total_duration)
+        percentage_of(total_duration) >= 30
+      end
+    end
+  end
+end
diff --git a/lib/gitlab/sherlock/location.rb b/lib/gitlab/sherlock/location.rb
new file mode 100644
index 00000000000..5ac265618ad
--- /dev/null
+++ b/lib/gitlab/sherlock/location.rb
@@ -0,0 +1,26 @@
+module Gitlab
+  module Sherlock
+    class Location
+      attr_reader :path, :line
+
+      SHERLOCK_DIR = File.dirname(__FILE__)
+
+      # Creates a new Location from a `Thread::Backtrace::Location`.
+      def self.from_ruby_location(location)
+        new(location.path, location.lineno)
+      end
+
+      # path - The full path of the frame as a String.
+      # line - The line number of the frame as a Fixnum.
+      def initialize(path, line)
+        @path = path
+        @line = line
+      end
+
+      # Returns true if the current frame originated from the application.
+      def application?
+        @path.start_with?(Rails.root.to_s) && !path.start_with?(SHERLOCK_DIR)
+      end
+    end
+  end
+end
diff --git a/lib/gitlab/sherlock/middleware.rb b/lib/gitlab/sherlock/middleware.rb
new file mode 100644
index 00000000000..687332fc5fc
--- /dev/null
+++ b/lib/gitlab/sherlock/middleware.rb
@@ -0,0 +1,41 @@
+module Gitlab
+  module Sherlock
+    # Rack middleware used for tracking request metrics.
+    class Middleware
+      CONTENT_TYPES = /text\/html|application\/json/i
+
+      IGNORE_PATHS = %r{^/sherlock}
+
+      def initialize(app)
+        @app = app
+      end
+
+      # env - A Hash containing Rack environment details.
+      def call(env)
+        if instrument?(env)
+          call_with_instrumentation(env)
+        else
+          @app.call(env)
+        end
+      end
+
+      def call_with_instrumentation(env)
+        trans = transaction_from_env(env)
+        retval = trans.run { @app.call(env) }
+
+        Sherlock.collection.add(trans)
+
+        retval
+      end
+
+      def instrument?(env)
+        !!(env['HTTP_ACCEPT'] =~ CONTENT_TYPES &&
+           env['REQUEST_URI'] !~ IGNORE_PATHS)
+      end
+
+      def transaction_from_env(env)
+        Transaction.new(env['REQUEST_METHOD'], env['REQUEST_URI'])
+      end
+    end
+  end
+end
diff --git a/lib/gitlab/sherlock/query.rb b/lib/gitlab/sherlock/query.rb
new file mode 100644
index 00000000000..4917c4ae2ac
--- /dev/null
+++ b/lib/gitlab/sherlock/query.rb
@@ -0,0 +1,114 @@
+module Gitlab
+  module Sherlock
+    class Query
+      attr_reader :id, :query, :started_at, :finished_at, :backtrace
+
+      # SQL identifiers that should be prefixed with newlines.
+      PREFIX_NEWLINE = /
+        \s+(FROM
+          |(LEFT|RIGHT)?INNER\s+JOIN
+          |(LEFT|RIGHT)?OUTER\s+JOIN
+          |WHERE
+          |AND
+          |GROUP\s+BY
+          |ORDER\s+BY
+          |LIMIT
+          |OFFSET)\s+/ix # Vim indent breaks when this is on a newline :<
+
+      # Creates a new Query using a String and a separate Array of bindings.
+      #
+      # query - A String containing a SQL query, optionally with numeric
+      #         placeholders (`$1`, `$2`, etc).
+      #
+      # bindings - An Array of ActiveRecord columns and their values.
+      # started_at - The start time of the query as a Time-like object.
+      # finished_at - The completion time of the query as a Time-like object.
+      #
+      # Returns a new Query object.
+      def self.new_with_bindings(query, bindings, started_at, finished_at)
+        bindings.each_with_index do |(_, value), index|
+          quoted_value = ActiveRecord::Base.connection.quote(value)
+
+          query = query.gsub("$#{index + 1}", quoted_value)
+        end
+
+        new(query, started_at, finished_at)
+      end
+
+      # query - The SQL query as a String (without placeholders).
+      # started_at - The start time of the query as a Time-like object.
+      # finished_at - The completion time of the query as a Time-like object.
+      def initialize(query, started_at, finished_at)
+        @id = SecureRandom.uuid
+        @query = query
+        @started_at = started_at
+        @finished_at = finished_at
+        @backtrace = caller_locations.map do |loc|
+          Location.from_ruby_location(loc)
+        end
+
+        unless @query.end_with?(';')
+          @query += ';'
+        end
+      end
+
+      # Returns the query duration in milliseconds.
+      def duration
+        @duration ||= (@finished_at - @started_at) * 1000.0
+      end
+
+      def to_param
+        @id
+      end
+
+      # Returns a human readable version of the query.
+      def formatted_query
+        @formatted_query ||= format_sql(@query)
+      end
+
+      # Returns the last application frame of the backtrace.
+      def last_application_frame
+        @last_application_frame ||= @backtrace.find(&:application?)
+      end
+
+      # Returns an Array of application frames (excluding Gems and the likes).
+      def application_backtrace
+        @application_backtrace ||= @backtrace.select(&:application?)
+      end
+
+      # Returns the query plan as a String.
+      def explain
+        unless @explain
+          ActiveRecord::Base.connection.transaction do
+            @explain = raw_explain(@query).values.flatten.join("\n")
+
+            # Roll back any queries that mutate data so we don't mess up
+            # anything when running explain on an INSERT, UPDATE, DELETE, etc.
+            raise ActiveRecord::Rollback
+          end
+        end
+
+        @explain
+      end
+
+      private
+
+      def raw_explain(query)
+        if Gitlab::Database.postgresql?
+          explain = "EXPLAIN ANALYZE #{query};"
+        else
+          explain = "EXPLAIN #{query};"
+        end
+
+        ActiveRecord::Base.connection.execute(explain)
+      end
+
+      def format_sql(query)
+        query.each_line.
+          map { |line| line.strip }.
+          join("\n").
+          gsub(PREFIX_NEWLINE) { "\n#{$1} " }
+      end
+    end
+  end
+end
diff --git a/lib/gitlab/sherlock/transaction.rb b/lib/gitlab/sherlock/transaction.rb
new file mode 100644
index 00000000000..d87a4c9bb4a
--- /dev/null
+++ b/lib/gitlab/sherlock/transaction.rb
@@ -0,0 +1,131 @@
+module Gitlab
+  module Sherlock
+    class Transaction
+      attr_reader :id, :type, :path, :queries, :file_samples, :started_at,
+        :finished_at, :view_counts
+
+      # type - The type of transaction (e.g. "GET", "POST", etc)
+      # path - The path of the transaction (e.g. the HTTP request path)
+      def initialize(type, path)
+        @id = SecureRandom.uuid
+        @type = type
+        @path = path
+        @queries = []
+        @file_samples = []
+        @started_at = nil
+        @finished_at = nil
+        @thread = Thread.current
+        @view_counts = Hash.new(0)
+      end
+
+      # Runs the transaction and returns the block's return value.
+      def run
+        @started_at = Time.now
+
+        retval = with_subscriptions do
+          profile_lines { yield }
+        end
+
+        @finished_at = Time.now
+
+        retval
+      end
+
+      # Returns the duration in seconds.
+      def duration
+        @duration ||= started_at && finished_at ? finished_at - started_at : 0
+      end
+
+      def to_param
+        @id
+      end
+
+      # Returns the queries sorted in descending order by their durations.
+      def sorted_queries
+        @queries.sort { |a, b| b.duration <=> a.duration }
+      end
+
+      # Returns the file samples sorted in descending order by their durations.
+      def sorted_file_samples
+        @file_samples.sort { |a, b| b.duration <=> a.duration }
+      end
+
+      # Finds a query by the given ID.
+      #
+      # id - The query ID as a String.
+      #
+      # Returns a Query object if one could be found, nil otherwise.
+      def find_query(id)
+        @queries.find { |query| query.id == id }
+      end
+
+      # Finds a file sample by the given ID.
+      #
+      # id - The query ID as a String.
+      #
+      # Returns a FileSample object if one could be found, nil otherwise.
+      def find_file_sample(id)
+        @file_samples.find { |sample| sample.id == id }
+      end
+
+      def profile_lines
+        retval = nil
+
+        if Sherlock.enable_line_profiler?
+          retval, @file_samples = LineProfiler.new.profile { yield }
+        else
+          retval = yield
+        end
+
+        retval
+      end
+
+      def subscribe_to_active_record
+        ActiveSupport::Notifications.subscribe('sql.active_record') do |_, start, finish, _, data|
+          next unless same_thread?
+
+          track_query(data[:sql].strip, data[:binds], start, finish)
+        end
+      end
+
+      def subscribe_to_action_view
+        regex = /render_(template|partial)\.action_view/
+
+        ActiveSupport::Notifications.subscribe(regex) do |_, start, finish, _, data|
+          next unless same_thread?
+
+          track_view(data[:identifier])
+        end
+      end
+
+      private
+
+      def track_query(query, bindings, start, finish)
+        @queries << Query.new_with_bindings(query, bindings, start, finish)
+      end
+
+      def track_view(path)
+        @view_counts[path] += 1
+      end
+
+      def with_subscriptions
+        ar_subscriber = subscribe_to_active_record
+        av_subscriber = subscribe_to_action_view
+
+        retval = yield
+
+        ActiveSupport::Notifications.unsubscribe(ar_subscriber)
+        ActiveSupport::Notifications.unsubscribe(av_subscriber)
+
+        retval
+      end
+
+      # In case somebody uses a multi-threaded server locally (e.g. Puma) we
+      # _only_ want to track notifications that originate from the transaction
+      # thread.
+      def same_thread?
+        Thread.current == @thread
+      end
+    end
+  end
+end