diff options
author | Yorick Peterse <yorickpeterse@gmail.com> | 2015-11-04 19:13:19 +0100 |
---|---|---|
committer | Yorick Peterse <yorickpeterse@gmail.com> | 2015-11-09 14:29:10 +0100 |
commit | dec3e4ce64df5f71a7cba7734cada1baa79242cd (patch) | |
tree | f9eb65a953ded11859926010956d19d40bad4d32 | |
parent | bd54bf7a798c06751d464ac3af1fef0e7ee90ea6 (diff) | |
download | gitlab-ce-dec3e4ce64df5f71a7cba7734cada1baa79242cd.tar.gz |
Added Sherlock, a custom profiling tool for GitLab
Sherlock will be a new GitLab specific tool for measuring the
performance of Rails requests (and SideKiq jobs at some point). Some of
the things that are currently tracked:
* SQL queries along with their timings, backtraces and query plans
(using "EXPLAIN ANALYZE" for PostgreSQL and regular "EXPLAIN" for
MySQL)
* Timings of application files (including views) on a per line basis
* Some meta data such as the request method, path, total duration, etc
More tracking (e.g. Rugged or gitlab-shell timings) might be added in
the future.
Sherlock will replace any existing tools we have used so far (e.g.
active_record_query_trace and rack-mini-profiler), hence the
corresponding Gems have been removed from the Gemfile.
Sherlock can be enabled by starting Rails as following:
ENABLE_SHERLOCK=1 bundle exec rails s
Recorded transactions can be found at `/sherlock/transactions`.
29 files changed, 855 insertions, 23 deletions
@@ -215,11 +215,9 @@ group :development do gem "annotate", "~> 2.6.0" gem "letter_opener", '~> 1.1.2' gem 'quiet_assets', '~> 1.0.2' - gem 'rack-mini-profiler', '~> 0.9.0', require: false gem 'rerun', '~> 0.10.0' gem 'bullet', require: false - gem 'active_record_query_trace', require: false - gem 'rack-lineprof', platform: :mri + gem 'rblineprof', platform: :mri, require: false # Better errors handler gem 'better_errors', '~> 1.0.1' diff --git a/Gemfile.lock b/Gemfile.lock index dce728baf18..c602d406711 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -17,7 +17,6 @@ GEM activesupport (= 4.1.12) builder (~> 3.1) erubis (~> 2.7.0) - active_record_query_trace (1.5) activemodel (4.1.12) activesupport (= 4.1.12) builder (~> 3.1) @@ -491,12 +490,6 @@ GEM rack-attack (4.3.0) rack rack-cors (0.4.0) - rack-lineprof (0.0.3) - rack (~> 1.5) - rblineprof (~> 0.3.6) - term-ansicolor (~> 1.3) - rack-mini-profiler (0.9.7) - rack (>= 1.1.3) rack-mount (0.8.3) rack (>= 1.0.0) rack-oauth2 (1.0.10) @@ -779,7 +772,6 @@ PLATFORMS DEPENDENCIES RedCloth (~> 4.2.9) ace-rails-ap (~> 2.0.1) - active_record_query_trace activerecord-deprecated_finders (~> 1.0.3) activerecord-session_store (~> 0.1.0) acts-as-taggable-on (~> 3.4) @@ -878,11 +870,10 @@ DEPENDENCIES quiet_assets (~> 1.0.2) rack-attack (~> 4.3.0) rack-cors (~> 0.4.0) - rack-lineprof - rack-mini-profiler (~> 0.9.0) rack-oauth2 (~> 1.0.5) rails (= 4.1.12) raphael-rails (~> 2.1.2) + rblineprof rdoc (~> 3.6) redcarpet (~> 3.3.3) redis-rails (~> 4.0.0) diff --git a/app/assets/stylesheets/pages/sherlock.scss b/app/assets/stylesheets/pages/sherlock.scss new file mode 100644 index 00000000000..92d84d9640f --- /dev/null +++ b/app/assets/stylesheets/pages/sherlock.scss @@ -0,0 +1,33 @@ +table .sherlock-code { + max-width: 700px; +} + +.sherlock-code { + pre { + word-wrap: normal; + } + + pre code { + white-space: pre; + } +} + +.sherlock-line-samples-table { + margin-bottom: 0px !important; + + thead tr th, + tbody tr td { + font-size: 13px !important; + text-align: right; + padding: 0px 10px !important; + } +} + +.sherlock-file-sample pre { + padding-top: 28px !important; +} + +.sherlock-line-samples-table .slow { + color: $red-light; + font-weight: bold; +} diff --git a/app/controllers/sherlock/application_controller.rb b/app/controllers/sherlock/application_controller.rb new file mode 100644 index 00000000000..682ca5e3821 --- /dev/null +++ b/app/controllers/sherlock/application_controller.rb @@ -0,0 +1,12 @@ +module Sherlock + class ApplicationController < ::ApplicationController + before_action :find_transaction + + def find_transaction + if params[:transaction_id] + @transaction = Gitlab::Sherlock.collection. + find_transaction(params[:transaction_id]) + end + end + end +end diff --git a/app/controllers/sherlock/file_samples_controller.rb b/app/controllers/sherlock/file_samples_controller.rb new file mode 100644 index 00000000000..0c3bc100106 --- /dev/null +++ b/app/controllers/sherlock/file_samples_controller.rb @@ -0,0 +1,7 @@ +module Sherlock + class FileSamplesController < Sherlock::ApplicationController + def show + @file_sample = @transaction.find_file_sample(params[:id]) + end + end +end diff --git a/app/controllers/sherlock/queries_controller.rb b/app/controllers/sherlock/queries_controller.rb new file mode 100644 index 00000000000..63b26aab1a4 --- /dev/null +++ b/app/controllers/sherlock/queries_controller.rb @@ -0,0 +1,7 @@ +module Sherlock + class QueriesController < Sherlock::ApplicationController + def show + @query = @transaction.find_query(params[:id]) + end + end +end diff --git a/app/controllers/sherlock/transactions_controller.rb b/app/controllers/sherlock/transactions_controller.rb new file mode 100644 index 00000000000..ccc739da879 --- /dev/null +++ b/app/controllers/sherlock/transactions_controller.rb @@ -0,0 +1,19 @@ +module Sherlock + class TransactionsController < Sherlock::ApplicationController + def index + @transactions = Gitlab::Sherlock.collection.newest_first + end + + def show + @transaction = Gitlab::Sherlock.collection.find_transaction(params[:id]) + + render_404 unless @transaction + end + + def destroy_all + Gitlab::Sherlock.collection.clear + + redirect_to(:back) + end + end +end diff --git a/app/views/sherlock/file_samples/show.html.haml b/app/views/sherlock/file_samples/show.html.haml new file mode 100644 index 00000000000..cfd11e45b6a --- /dev/null +++ b/app/views/sherlock/file_samples/show.html.haml @@ -0,0 +1,55 @@ +- page_title t('sherlock.title'), t('sherlock.transaction'), + t('sherlock.file_sample') + +- header_title t('sherlock.title'), sherlock_transactions_path + +.gray-content-block + .pull-right + = link_to(sherlock_transaction_path(@transaction), class: 'btn') do + %i.fa.fa-arrow-left + = t('sherlock.transaction') + .oneline + = t('sherlock.file_sample') + = @file_sample.id + +.prepend-top-default + %p + %span.light + #{t('sherlock.time')}: + %strong + = @file_sample.duration.round(2) + = t('sherlock.milliseconds') + %p + %span.light + #{t('sherlock.events')}: + %strong + = @file_sample.events + +%article.file-holder + .file-title + %i.fa.fa-file-text-o.fa-fw + %strong + = @file_sample.file + .code.file-content.js-syntax-highlight + .line-numbers + %table.sherlock-line-samples-table + %thead + %tr + %th= t('sherlock.line_capitalized') + %th= t('sherlock.events') + %th= t('sherlock.time') + %th= t('sherlock.percent') + %tbody + - @file_sample.line_samples.each_with_index do |sample, index| + %tr{class: sample.majority_of?(@file_sample.duration) ? 'slow' : ''} + %td= index + 1 + %td= sample.events + %td + = sample.duration.round(2) + = t('sherlock.milliseconds') + %td + = sample.percentage_of(@file_sample.duration).round + = t('sherlock.percent') + + .sherlock-file-sample + = highlight(@file_sample.file, @file_sample.source) diff --git a/app/views/sherlock/queries/_backtrace.html.haml b/app/views/sherlock/queries/_backtrace.html.haml new file mode 100644 index 00000000000..5c9294c0ab5 --- /dev/null +++ b/app/views/sherlock/queries/_backtrace.html.haml @@ -0,0 +1,27 @@ +.prepend-top-default + .panel.panel-default + .panel-heading + %strong + = t('sherlock.application_backtrace') + %ul.well-list + - @query.application_backtrace.each do |location| + %li + = location.path + %small.light + = t('sherlock.line') + = location.line + + .panel.panel-default + .panel-heading + %strong + = t('sherlock.full_backtrace') + %ul.well-list + - @query.backtrace.each do |location| + %li + - if location.application? + %strong= location.path + - else + = location.path + %small.light + = t('sherlock.line') + = location.line diff --git a/app/views/sherlock/queries/_general.html.haml b/app/views/sherlock/queries/_general.html.haml new file mode 100644 index 00000000000..549b47430e6 --- /dev/null +++ b/app/views/sherlock/queries/_general.html.haml @@ -0,0 +1,50 @@ +.prepend-top-default + .panel.panel-default + .panel-heading + %strong + = t('sherlock.general') + %ul.well-list + %li + %span.light + #{t('sherlock.time')}: + %strong + = @query.duration.round(4) + = t('sherlock.milliseconds') + %li + %span.light + #{t('sherlock.origin')}: + %strong + = @query.last_application_frame.path + %small.light + = t('sherlock.line') + = @query.last_application_frame.line + + .panel.panel-default + .panel-heading + .pull-right + %button.js-clipboard-trigger.btn.btn-xs{title: t('sherlock.copy_to_clipboard'), type: :button} + %i.fa.fa-clipboard + %pre.hidden + = @query.formatted_query + %strong + = t('sherlock.query') + %ul.well-list + %li + .code.js-syntax-highlight.sherlock-code + :preserve + #{highlight("#{@query.id}.sql", @query.formatted_query)} + + .panel.panel-default + .panel-heading + .pull-right + %button.js-clipboard-trigger.btn.btn-xs{title: t('sherlock.copy_to_clipboard'), type: :button} + %i.fa.fa-clipboard + %pre.hidden + = @query.explain + %strong + = t('sherlock.query_plan') + %ul.well-list + %li + .code.js-syntax-highlight.sherlock-code + %pre + %code= @query.explain diff --git a/app/views/sherlock/queries/show.html.haml b/app/views/sherlock/queries/show.html.haml new file mode 100644 index 00000000000..4a84348ac82 --- /dev/null +++ b/app/views/sherlock/queries/show.html.haml @@ -0,0 +1,26 @@ +- page_title t('sherlock.title'), t('sherlock.transaction'), t('sherlock.query') +- header_title t('sherlock.title'), sherlock_transactions_path + +%ul.center-top-menu + %li.active + %a(href="#tab-general" data-toggle="tab") + = t('sherlock.general') + %li + %a(href="#tab-backtrace" data-toggle="tab") + = t('sherlock.backtrace') + +.gray-content-block + .pull-right + = link_to(sherlock_transaction_path(@transaction), class: 'btn') do + %i.fa.fa-arrow-left + = t('sherlock.transaction') + .oneline + = t('sherlock.query') + = @query.id + +.tab-content + .tab-pane.active#tab-general + = render(partial: 'general') + + .tab-pane#tab-backtrace + = render(partial: 'backtrace') diff --git a/app/views/sherlock/transactions/_file_samples.html.haml b/app/views/sherlock/transactions/_file_samples.html.haml new file mode 100644 index 00000000000..0afdbc8dffa --- /dev/null +++ b/app/views/sherlock/transactions/_file_samples.html.haml @@ -0,0 +1,22 @@ +- if @transaction.file_samples.empty? + .nothing-here-block + = t('sherlock.no_file_samples') +- else + .table-holder + %table.table + %thead + %tr + %th= t('sherlock.time_inclusive') + %th= t('sherlock.path') + %th + %tbody + - @transaction.sorted_file_samples.each do |sample| + %tr + %td + = sample.duration.round(2) + = t('sherlock.milliseconds') + %td= sample.relative_path + %td + = link_to(t('sherlock.view'), + sherlock_transaction_file_sample_path(@transaction, sample), + class: 'btn btn-xs') diff --git a/app/views/sherlock/transactions/_general.html.haml b/app/views/sherlock/transactions/_general.html.haml new file mode 100644 index 00000000000..4287a0c3203 --- /dev/null +++ b/app/views/sherlock/transactions/_general.html.haml @@ -0,0 +1,33 @@ +.prepend-top-default + .panel.panel-default + .panel-heading + %strong + = t('sherlock.general') + %ul.well-list + %li + %span.light + #{t('sherlock.id')}: + %strong + = @transaction.id + %li + %span.light + #{t('sherlock.type')}: + %strong + = @transaction.type + %li + %span.light + #{t('sherlock.path')}: + %strong + = @transaction.path + %li + %span.light + #{t('sherlock.time')}: + %strong + = @transaction.duration.round(2) + = t('sherlock.seconds') + %li + %span.light + #{t('sherlock.finished_at')}: + %strong + = time_ago_in_words(@transaction.finished_at) + = t('sherlock.ago') diff --git a/app/views/sherlock/transactions/_queries.html.haml b/app/views/sherlock/transactions/_queries.html.haml new file mode 100644 index 00000000000..b7e0162e80d --- /dev/null +++ b/app/views/sherlock/transactions/_queries.html.haml @@ -0,0 +1,24 @@ +- if @transaction.queries.empty? + .nothing-here-block + = t('sherlock.no_queries') +- else + .table-holder + %table.table#sherlock-queries + %thead + %tr + %th= t('sherlock.time') + %th= t('sherlock.query') + %td + %tbody + - @transaction.sorted_queries.each do |query| + %tr + %td + = query.duration.round(2) + = t('sherlock.milliseconds') + %td + .code.js-syntax-highlight.sherlock-code + = highlight("#{query.id}.sql", query.formatted_query) + %td + = link_to(t('sherlock.view'), + sherlock_transaction_query_path(@transaction, query), + class: 'btn btn-xs') diff --git a/app/views/sherlock/transactions/index.html.haml b/app/views/sherlock/transactions/index.html.haml new file mode 100644 index 00000000000..fb31131ba88 --- /dev/null +++ b/app/views/sherlock/transactions/index.html.haml @@ -0,0 +1,40 @@ +- page_title t('sherlock.title') +- header_title t('sherlock.title'), sherlock_transactions_path + +.gray-content-block + .pull-right + = link_to(destroy_all_sherlock_transactions_path, + class: 'btn btn-danger', + method: :delete) do + %i.fa.fa-trash + = t('sherlock.delete_all_transactions') + .oneline= t('sherlock.introduction') + +- if @transactions.empty? + .nothing-here-block= t('sherlock.no_transactions') +- else + .table-holder + %table.table + %thead + %tr + %th= t('sherlock.type') + %th= t('sherlock.path') + %th= t('sherlock.time') + %th= t('sherlock.queries') + %th= t('sherlock.finished_at') + %th + %tbody + - @transactions.each do |trans| + %tr + %td= trans.type + %td= trans.path + %td + = trans.duration.round(2) + = t('sherlock.seconds') + %td= trans.queries.length + %td + = time_ago_in_words(trans.finished_at) + = t('sherlock.ago') + %td + = link_to(sherlock_transaction_path(trans), class: 'btn btn-xs') do + = t('sherlock.view') diff --git a/app/views/sherlock/transactions/show.html.haml b/app/views/sherlock/transactions/show.html.haml new file mode 100644 index 00000000000..3c8ffb06648 --- /dev/null +++ b/app/views/sherlock/transactions/show.html.haml @@ -0,0 +1,36 @@ +- page_title t('sherlock.title'), t('sherlock.transaction') +- header_title t('sherlock.title'), sherlock_transactions_path + +%ul.center-top-menu + %li.active + %a(href="#tab-general" data-toggle="tab") + = t('sherlock.general') + %li + %a(href="#tab-queries" data-toggle="tab") + = t('sherlock.queries') + %span.badge + #{@transaction.queries.length} + %li + %a(href="#tab-file-samples" data-toggle="tab") + = t('sherlock.file_samples') + %span.badge + #{@transaction.file_samples.length} + +.gray-content-block + .pull-right + = link_to(sherlock_transactions_path, class: 'btn') do + %i.fa.fa-arrow-left + = t('sherlock.all_transactions') + .oneline + = t('sherlock.transaction') + = @transaction.id + +.tab-content + .tab-pane.active#tab-general + = render(partial: 'general') + + .tab-pane#tab-queries + = render(partial: 'queries') + + .tab-pane#tab-file-samples + = render(partial: 'file_samples') diff --git a/config/initializers/rack_profiler.rb b/config/initializers/rack_profiler.rb deleted file mode 100644 index 7710eeac453..00000000000 --- a/config/initializers/rack_profiler.rb +++ /dev/null @@ -1,10 +0,0 @@ -if Rails.env.development? - require 'rack-mini-profiler' - - # initialization is skipped so trigger it - Rack::MiniProfilerRails.initialize!(Gitlab::Application) - - Rack::MiniProfiler.config.position = 'right' - Rack::MiniProfiler.config.start_hidden = false - Rack::MiniProfiler.config.skip_paths << '/teaspoon' -end diff --git a/config/initializers/sherlock.rb b/config/initializers/sherlock.rb new file mode 100644 index 00000000000..42b0d78c85f --- /dev/null +++ b/config/initializers/sherlock.rb @@ -0,0 +1,5 @@ +if Gitlab::Sherlock.enabled? + Gitlab::Application.configure do |config| + config.middleware.use(Gitlab::Sherlock::Middleware) + end +end diff --git a/config/locales/sherlock.en.yml b/config/locales/sherlock.en.yml new file mode 100644 index 00000000000..5c146b172b1 --- /dev/null +++ b/config/locales/sherlock.en.yml @@ -0,0 +1,36 @@ +en: + sherlock: + title: Sherlock + delete_all_transactions: Delete All Transactions + introduction: > + Below is a list of all transactions recorded by Sherlock. Requests to + Sherlock's own routes are ignored. + no_transactions: No transactions to show + no_queries: No queries to show + no_file_samples: No file samples to show + all_transactions: All Transactions + transaction: Transaction + query: Query + file_sample: File Sample + type: Type + path: Path + time: Time + queries: Queries + finished_at: Finished at + ago: ago + view: View + seconds: seconds + milliseconds: ms + general: General + id: ID + time_inclusive: Time (inclusive) + backtrace: Backtrace + application_backtrace: Application Backtrace + full_backtrace: Full Backtrace + origin: Origin + line: line + line_capitalized: Line + copy_to_clipboard: Copy to clipboard + query_plan: Query Plan + events: Events + percent: '%' diff --git a/config/routes.rb b/config/routes.rb index 990a00e3d0b..7d8a546a64c 100644 --- a/config/routes.rb +++ b/config/routes.rb @@ -2,6 +2,19 @@ require 'sidekiq/web' require 'api/api' Gitlab::Application.routes.draw do + if Gitlab::Sherlock.enabled? + namespace :sherlock do + resources :transactions, only: [:index, :show] do + resources :queries, only: [:show] + resources :file_samples, only: [:show] + + collection do + delete :destroy_all + end + end + end + end + namespace :ci do # CI API Ci::API::API.logger Rails.logger diff --git a/lib/gitlab/sherlock.rb b/lib/gitlab/sherlock.rb new file mode 100644 index 00000000000..c4b35b24ceb --- /dev/null +++ b/lib/gitlab/sherlock.rb @@ -0,0 +1,20 @@ +require 'securerandom' +require 'rblineprof' if RUBY_ENGINE == 'ruby' + +module Gitlab + module Sherlock + @collection = Collection.new + + class << self + attr_reader :collection + end + + def self.enabled? + Rails.env.development? && !!ENV['ENABLE_SHERLOCK'] + end + + def self.enable_line_profiler? + RUBY_ENGINE == 'ruby' + end + end +end diff --git a/lib/gitlab/sherlock/collection.rb b/lib/gitlab/sherlock/collection.rb new file mode 100644 index 00000000000..accdc6469bc --- /dev/null +++ b/lib/gitlab/sherlock/collection.rb @@ -0,0 +1,42 @@ +module Gitlab + module Sherlock + 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 + + 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..7a220de9abc --- /dev/null +++ b/lib/gitlab/sherlock/file_sample.rb @@ -0,0 +1,27 @@ +module Gitlab + module Sherlock + class FileSample + attr_reader :id, :file, :line_samples, :events, :duration + + 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..a191b1e646d --- /dev/null +++ b/lib/gitlab/sherlock/line_profiler.rb @@ -0,0 +1,60 @@ +module Gitlab + module Sherlock + 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 + + def profile(&block) + if RUBY_ENGINE == 'ruby' + profile_mri(&block) + else + raise NotImplementedError, + 'Line profiling is not supported on this platform' + end + end + + 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. + 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 + + def microsec_to_millisec(microsec) + microsec / 1000.0 + 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..38df7a88e4e --- /dev/null +++ b/lib/gitlab/sherlock/line_sample.rb @@ -0,0 +1,20 @@ +module Gitlab + module Sherlock + class LineSample + attr_reader :duration, :events + + def initialize(duration, events) + @duration = duration + @events = events + end + + def percentage_of(total_duration) + (duration.to_f / total_duration) * 100.0 + end + + 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..8c0b77dce1a --- /dev/null +++ b/lib/gitlab/sherlock/location.rb @@ -0,0 +1,22 @@ +module Gitlab + module Sherlock + class Location + attr_reader :path, :line + + SHERLOCK_DIR = File.dirname(__FILE__) + + def self.from_ruby_location(location) + new(location.path, location.lineno) + end + + def initialize(path, line) + @path = path + @line = line + end + + 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..fca7be858eb --- /dev/null +++ b/lib/gitlab/sherlock/middleware.rb @@ -0,0 +1,36 @@ +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 + + def call(env) + if instrument?(env) + call_with_instrumentation(env) + else + @app.call(env) + end + end + + def call_with_instrumentation(env) + trans = Transaction.new(env['REQUEST_METHOD'], env['REQUEST_URI']) + 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 + end + end +end diff --git a/lib/gitlab/sherlock/query.rb b/lib/gitlab/sherlock/query.rb new file mode 100644 index 00000000000..af76e6fd2bf --- /dev/null +++ b/lib/gitlab/sherlock/query.rb @@ -0,0 +1,96 @@ +module Gitlab + module Sherlock + class Query + attr_reader :id, :query, :started_at, :finished_at, :backtrace + + 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 + + def self.new_with_bindings(query, bindings, started_at, finished_at) + bindings.each_with_index do |(column, value), index| + quoted_value = ActiveRecord::Base.connection.quote(value) + + query = query.gsub("$#{index + 1}", quoted_value) + end + + new(query, started_at, finished_at) + end + + 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 + + def duration + @duration ||= (@finished_at - @started_at) * 1000.0 + end + + def to_param + @id + end + + def formatted_query + @formatted_query ||= format_sql(@query) + end + + def last_application_frame + @last_application_frame ||= @backtrace.find(&:application?) + end + + def application_backtrace + @application_backtrace ||= @backtrace.select(&:application?) + end + + 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..5cb3e86aa4e --- /dev/null +++ b/lib/gitlab/sherlock/transaction.rb @@ -0,0 +1,85 @@ +module Gitlab + module Sherlock + class Transaction + attr_reader :id, :type, :path, :queries, :file_samples, :started_at, + :finished_at + + def initialize(type, path) + @id = SecureRandom.uuid + @type = type + @path = path + @duration = 0 + @queries = [] + @file_samples = [] + @started_at = nil + @finished_at = nil + @thread = Thread.current + end + + def run + @started_at = Time.now + + subscriber = subscribe_to_active_record + + retval = profile_lines { yield } + + @finished_at = Time.now + + ActiveSupport::Notifications.unsubscribe(subscriber) + + retval + end + + def duration + @started_at && @finished_at ? @finished_at - @started_at : 0 + end + + def to_param + @id + end + + def sorted_queries + @queries.sort { |a, b| b.duration <=> a.duration } + end + + def sorted_file_samples + @file_samples.sort { |a, b| b.duration <=> a.duration } + end + + def find_query(id) + @queries.find { |query| query.id == id } + end + + 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 + + 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| + # In case somebody uses a multi-threaded server locally (e.g. Puma) we + # _only_ want to track queries that originate from the transaction + # thread. + next unless Thread.current == @thread + + track_query(data[:sql].strip, data[:binds], start, finish) + end + end + end + end +end |