From 265ef867fff165643784640d837579ce4fcc2207 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Thu, 5 Nov 2015 18:01:05 +0100 Subject: Added specs and source documentation for Sherlock --- lib/gitlab/sherlock/collection.rb | 7 +++++++ lib/gitlab/sherlock/file_sample.rb | 4 ++++ lib/gitlab/sherlock/line_profiler.rb | 38 +++++++++++++++++++++++++++++++++++- lib/gitlab/sherlock/line_sample.rb | 16 +++++++++++++++ lib/gitlab/sherlock/location.rb | 4 ++++ lib/gitlab/sherlock/middleware.rb | 7 ++++++- lib/gitlab/sherlock/query.rb | 26 ++++++++++++++++++++---- lib/gitlab/sherlock/transaction.rb | 29 +++++++++++++++++++++------ 8 files changed, 119 insertions(+), 12 deletions(-) (limited to 'lib') diff --git a/lib/gitlab/sherlock/collection.rb b/lib/gitlab/sherlock/collection.rb index accdc6469bc..66bd6258521 100644 --- a/lib/gitlab/sherlock/collection.rb +++ b/lib/gitlab/sherlock/collection.rb @@ -1,5 +1,10 @@ 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 @@ -34,6 +39,8 @@ module Gitlab sort { |a, b| b.finished_at <=> a.finished_at } end + private + def synchronize(&block) @mutex.synchronize(&block) end diff --git a/lib/gitlab/sherlock/file_sample.rb b/lib/gitlab/sherlock/file_sample.rb index 7a220de9abc..8a3e1a5e5bf 100644 --- a/lib/gitlab/sherlock/file_sample.rb +++ b/lib/gitlab/sherlock/file_sample.rb @@ -3,6 +3,10 @@ module Gitlab 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 diff --git a/lib/gitlab/sherlock/line_profiler.rb b/lib/gitlab/sherlock/line_profiler.rb index a191b1e646d..152749dcc39 100644 --- a/lib/gitlab/sherlock/line_profiler.rb +++ b/lib/gitlab/sherlock/line_profiler.rb @@ -1,12 +1,36 @@ 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 # => [#, ...] + # + # Returns an Array containing the block's return value and an Array of + # FileSample objects. def profile(&block) - if RUBY_ENGINE == 'ruby' + if mri? profile_mri(&block) else raise NotImplementedError, @@ -14,6 +38,7 @@ module Gitlab end end + # Profiles the given block using rblineprof (MRI only). def profile_mri retval = nil samples = lineprof(/^#{Rails.root.to_s}/) { retval = yield } @@ -24,6 +49,11 @@ module Gitlab 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 = [] @@ -52,9 +82,15 @@ module Gitlab 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 index 38df7a88e4e..eb1948eb6d6 100644 --- a/lib/gitlab/sherlock/line_sample.rb +++ b/lib/gitlab/sherlock/line_sample.rb @@ -3,15 +3,31 @@ module Gitlab 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 diff --git a/lib/gitlab/sherlock/location.rb b/lib/gitlab/sherlock/location.rb index 8c0b77dce1a..5ac265618ad 100644 --- a/lib/gitlab/sherlock/location.rb +++ b/lib/gitlab/sherlock/location.rb @@ -5,15 +5,19 @@ module Gitlab 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 diff --git a/lib/gitlab/sherlock/middleware.rb b/lib/gitlab/sherlock/middleware.rb index fca7be858eb..687332fc5fc 100644 --- a/lib/gitlab/sherlock/middleware.rb +++ b/lib/gitlab/sherlock/middleware.rb @@ -10,6 +10,7 @@ module Gitlab @app = app end + # env - A Hash containing Rack environment details. def call(env) if instrument?(env) call_with_instrumentation(env) @@ -19,7 +20,7 @@ module Gitlab end def call_with_instrumentation(env) - trans = Transaction.new(env['REQUEST_METHOD'], env['REQUEST_URI']) + trans = transaction_from_env(env) retval = trans.run { @app.call(env) } Sherlock.collection.add(trans) @@ -31,6 +32,10 @@ module Gitlab !!(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 index af76e6fd2bf..4917c4ae2ac 100644 --- a/lib/gitlab/sherlock/query.rb +++ b/lib/gitlab/sherlock/query.rb @@ -3,6 +3,7 @@ module Gitlab 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 @@ -12,11 +13,20 @@ module Gitlab |GROUP\s+BY |ORDER\s+BY |LIMIT - |OFFSET)\s+ - /ix - + |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 |(column, value), index| + bindings.each_with_index do |(_, value), index| quoted_value = ActiveRecord::Base.connection.quote(value) query = query.gsub("$#{index + 1}", quoted_value) @@ -25,6 +35,9 @@ module Gitlab 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 @@ -39,6 +52,7 @@ module Gitlab end end + # Returns the query duration in milliseconds. def duration @duration ||= (@finished_at - @started_at) * 1000.0 end @@ -47,18 +61,22 @@ module Gitlab @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 diff --git a/lib/gitlab/sherlock/transaction.rb b/lib/gitlab/sherlock/transaction.rb index 5cb3e86aa4e..4641f15ee33 100644 --- a/lib/gitlab/sherlock/transaction.rb +++ b/lib/gitlab/sherlock/transaction.rb @@ -4,11 +4,12 @@ module Gitlab attr_reader :id, :type, :path, :queries, :file_samples, :started_at, :finished_at + # 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 - @duration = 0 @queries = [] @file_samples = [] @started_at = nil @@ -16,6 +17,7 @@ module Gitlab @thread = Thread.current end + # Runs the transaction and returns the block's return value. def run @started_at = Time.now @@ -30,34 +32,43 @@ module Gitlab retval end + # Returns the duration in seconds. def duration - @started_at && @finished_at ? @finished_at - @started_at : 0 + @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 track_query(query, bindings, start, finish) - @queries << Query.new_with_bindings(query, bindings, start, finish) - end - def profile_lines retval = nil @@ -70,6 +81,12 @@ module Gitlab retval end + private + + def track_query(query, bindings, start, finish) + @queries << Query.new_with_bindings(query, bindings, start, finish) + end + def subscribe_to_active_record ActiveSupport::Notifications.subscribe('sql.active_record') do |_, start, finish, _, data| # In case somebody uses a multi-threaded server locally (e.g. Puma) we -- cgit v1.2.1