diff options
author | Yorick Peterse <yorickpeterse@gmail.com> | 2015-11-09 16:40:26 +0300 |
---|---|---|
committer | Yorick Peterse <yorickpeterse@gmail.com> | 2015-11-09 16:40:26 +0300 |
commit | 26344c8f82c06a4d9cc65760bc8f2764a55a338b (patch) | |
tree | 746cccf3b454a569468b0933abb3766b25ef9460 /lib/gitlab/sherlock | |
parent | bd54bf7a798c06751d464ac3af1fef0e7ee90ea6 (diff) | |
parent | 68843a53e6cfe5493ad46dac58b469dd969a0edf (diff) |
Merge branch 'sherlock' into 'master'
See merge request !1749
Diffstat (limited to 'lib/gitlab/sherlock')
-rw-r--r-- | lib/gitlab/sherlock/collection.rb | 49 | ||||
-rw-r--r-- | lib/gitlab/sherlock/file_sample.rb | 31 | ||||
-rw-r--r-- | lib/gitlab/sherlock/line_profiler.rb | 96 | ||||
-rw-r--r-- | lib/gitlab/sherlock/line_sample.rb | 36 | ||||
-rw-r--r-- | lib/gitlab/sherlock/location.rb | 26 | ||||
-rw-r--r-- | lib/gitlab/sherlock/middleware.rb | 41 | ||||
-rw-r--r-- | lib/gitlab/sherlock/query.rb | 114 | ||||
-rw-r--r-- | lib/gitlab/sherlock/transaction.rb | 131 |
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 |