diff --git a/CHANGELOG b/CHANGELOG index 19f288d0c7ec6905483a2b17f73c3fd5dfc82fb0..217dc4e00434c3ddce529c14ac4cbbd2b8a408ed 100644 --- a/CHANGELOG +++ b/CHANGELOG @@ -1,6 +1,7 @@ Please view this file on the master branch, on stable branches it's out of date. v 8.2.0 (unreleased) + - Added a GitLab specific profiling tool called "Sherlock" (see GitLab CE merge request #1749) - Fix bug where manually merged branches in a MR would end up with an empty diff (Stan Hu) - Force update refs/merge-requests/X/head upon a push to the source branch of a merge request (Stan Hu) - Improved performance of finding users by one of their Email addresses diff --git a/Gemfile b/Gemfile index 0bac89781601962fe7f160a2ed00775021938bfb..b0a7c9b94587712150164bd81dbcd00492e1c9f9 100644 --- a/Gemfile +++ b/Gemfile @@ -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 dce728baf18eba5d863bb6f97c382021801e49b2..c602d40671175afdc1ffb30117bbe9200a890f63 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 0000000000000000000000000000000000000000..92d84d9640fc4cedf8d03bde1070ac7eda7eabf5 --- /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 0000000000000000000000000000000000000000..682ca5e382155f51ccc84432c29b9ecb13ea296a --- /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 0000000000000000000000000000000000000000..0c3bc100106049688ed7a7b0155b6de1a4e4e779 --- /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 0000000000000000000000000000000000000000..63b26aab1a4b96475e8ec294585bad0c2ad16867 --- /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 0000000000000000000000000000000000000000..ccc739da879a1d3f9baaa1341622847fac6c63d4 --- /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/layouts/header/_default.html.haml b/app/views/layouts/header/_default.html.haml index c31b1cbe9a8ab8aaa030154f203a182d4365b46c..c08a7b8074474222551ef746e14cda1269c08bf8 100644 --- a/app/views/layouts/header/_default.html.haml +++ b/app/views/layouts/header/_default.html.haml @@ -21,6 +21,11 @@ %li = link_to new_project_path, title: 'New project', data: {toggle: 'tooltip', placement: 'bottom'} do = icon('plus fw') + - if Gitlab::Sherlock.enabled? + %li + = link_to sherlock_transactions_path, title: 'Sherlock Transactions', + data: {toggle: 'tooltip', placement: 'bottom'} do + = icon('tachometer fw') %li = link_to destroy_user_session_path, class: 'logout', method: :delete, title: 'Sign out', data: {toggle: 'tooltip', placement: 'bottom'} do = icon('sign-out') 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 0000000000000000000000000000000000000000..cfd11e45b6af80d5721f73379ea6074498d7136e --- /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 0000000000000000000000000000000000000000..5c9294c0ab534e0f2879707e06fa119483aab0e8 --- /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 0000000000000000000000000000000000000000..549b47430e697f761c340f5738da302bda36839e --- /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 0000000000000000000000000000000000000000..4a84348ac82582f753d40c81826bdb17684bb4b5 --- /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 0000000000000000000000000000000000000000..4349c9b7aceb206e563e056546f1656125cf79cf --- /dev/null +++ b/app/views/sherlock/transactions/_file_samples.html.haml @@ -0,0 +1,24 @@ +- 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.count') + %th= t('sherlock.path') + %th + %tbody + - @transaction.sorted_file_samples.each do |sample| + %tr + %td + = sample.duration.round(2) + = t('sherlock.milliseconds') + %td= @transaction.view_counts.fetch(sample.file, 1) + %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 0000000000000000000000000000000000000000..4287a0c32036f49cccd1b7ac1482186d7f1f5254 --- /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 0000000000000000000000000000000000000000..b7e0162e80db835d22bc1b3aa44933ee6c3141ad --- /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 0000000000000000000000000000000000000000..010e1a2a9023e8d5a5d96fc63f67c0963cfebd4a --- /dev/null +++ b/app/views/sherlock/transactions/index.html.haml @@ -0,0 +1,42 @@ +- 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 + %span{title: trans.path} + = truncate(trans.path, length: 70) + %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 0000000000000000000000000000000000000000..3c8ffb066484125b3cb1b2880fb7e3f8e305530c --- /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 7710eeac45395d17705422af8cc519e289efb64b..0000000000000000000000000000000000000000 --- 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 0000000000000000000000000000000000000000..42b0d78c85fae51d6c800ab2cc66b0e77afb75a7 --- /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 0000000000000000000000000000000000000000..683b09dc3294d5710850802193572470bee0f5d9 --- /dev/null +++ b/config/locales/sherlock.en.yml @@ -0,0 +1,37 @@ +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: '%' + count: Count diff --git a/config/routes.rb b/config/routes.rb index 990a00e3d0bdd6995dbd67fbb80d8b6ce2c8ab4a..7d8a546a64cece182c03d4599a446ad29c400037 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/doc/development/profiling.md b/doc/development/profiling.md index 80c86ef921e9fed698feda43b3c1fa26bc4cfb0a..e244ad4e881d6caae77437e8f0d515f81a33f8cc 100644 --- a/doc/development/profiling.md +++ b/doc/development/profiling.md @@ -4,11 +4,15 @@ To make it easier to track down performance problems GitLab comes with a set of profiling tools, some of these are available by default while others need to be explicitly enabled. -## rack-mini-profiler +## Sherlock -This Gem is enabled by default in development only. It allows you to see the -timings of the various components that made up a web request (e.g. the SQL -queries executed and their execution timings). +Sherlock is a custom profiling tool built into GitLab. Sherlock is _only_ +available when running GitLab in development mode _and_ when setting the +environment variable `ENABLE_SHERLOCK` to a non empty value. For example: + + ENABLE_SHERLOCK=1 bundle exec rails s + +Recorded transactions can be found by navigating to `/sherlock/transactions`. ## Bullet @@ -21,36 +25,3 @@ starting GitLab. For example: Bullet will log query problems to both the Rails log as well as the Chrome console. - -## ActiveRecord Query Trace - -This Gem adds backtraces for every ActiveRecord query in the Rails console. This -can be useful to track down where a query was executed. Because this Gem adds -quite a bit of noise (5-10 extra lines per ActiveRecord query) it's disabled by -default. To use this Gem you'll need to set `ENABLE_QUERY_TRACE` to a non empty -file before starting GitLab. For example: - - ENABLE_QUERY_TRACE=true bundle exec rails s - -## rack-lineprof - -This is a Gem that can trace the execution time of code on a per line basis. -Because this Gem can add quite a bit of overhead it's disabled by default. To -enable it, set the environment variable `ENABLE_LINEPROF` to a non-empty value. -For example: - - ENABLE_LINEPROF=true bundle exec rails s - -Once enabled you'll need to add a query string parameter to a request to -actually profile code execution. The name of the parameter is `lineprof` and -should be set to a regular expression (minus the starting/ending slash) used to -select what files to profile. To profile all files containing "foo" somewhere in -the path you'd use the following parameter: - - ?lineprof=foo - -Or when filtering for files containing "foo" and "bar" in their path: - - ?lineprof=foo|bar - -Once set the profiling output will be displayed in your terminal. diff --git a/lib/gitlab/sherlock.rb b/lib/gitlab/sherlock.rb new file mode 100644 index 0000000000000000000000000000000000000000..c4b35b24ceb72a3b875dd7c63be3fcdd4c848d40 --- /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 0000000000000000000000000000000000000000..66bd6258521deedc0e6781802c161868c87819ae --- /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 0000000000000000000000000000000000000000..8a3e1a5e5bf1747ae6c62d4f9880556309a3f549 --- /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 0000000000000000000000000000000000000000..152749dcc39f3009db8fc61b6e6b18818c5bb232 --- /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 # => [#, ...] + # + # 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 0000000000000000000000000000000000000000..eb1948eb6d6ff1ee5b818e49837da707551a87de --- /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 0000000000000000000000000000000000000000..5ac265618ad2175eeeaee026506b6c6695fa7083 --- /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 0000000000000000000000000000000000000000..687332fc5fc18fb45bd408e84ebe038bc7eb3c90 --- /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 0000000000000000000000000000000000000000..4917c4ae2ac5c1a0a3b95b72d8cd2a25d42709db --- /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 0000000000000000000000000000000000000000..d87a4c9bb4a82a5e59dc6dbe87dfe0c6436e6673 --- /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 diff --git a/spec/lib/gitlab/sherlock/collection_spec.rb b/spec/lib/gitlab/sherlock/collection_spec.rb new file mode 100644 index 0000000000000000000000000000000000000000..a8a9d6fc7bc171f771893a605f193b11d6019140 --- /dev/null +++ b/spec/lib/gitlab/sherlock/collection_spec.rb @@ -0,0 +1,82 @@ +require 'spec_helper' + +describe Gitlab::Sherlock::Collection do + let(:collection) { described_class.new } + + let(:transaction) do + Gitlab::Sherlock::Transaction.new('POST', '/cat_pictures') + end + + describe '#add' do + it 'adds a new transaction' do + collection.add(transaction) + + expect(collection).to_not be_empty + end + + it 'is aliased as <<' do + collection << transaction + + expect(collection).to_not be_empty + end + end + + describe '#each' do + it 'iterates over every transaction' do + collection.add(transaction) + + expect { |b| collection.each(&b) }.to yield_with_args(transaction) + end + end + + describe '#clear' do + it 'removes all transactions' do + collection.add(transaction) + + collection.clear + + expect(collection).to be_empty + end + end + + describe '#empty?' do + it 'returns true for an empty collection' do + expect(collection).to be_empty + end + + it 'returns false for a collection with a transaction' do + collection.add(transaction) + + expect(collection).to_not be_empty + end + end + + describe '#find_transaction' do + it 'returns the transaction for the given ID' do + collection.add(transaction) + + expect(collection.find_transaction(transaction.id)).to eq(transaction) + end + + it 'returns nil when no transaction could be found' do + collection.add(transaction) + + expect(collection.find_transaction('cats')).to be_nil + end + end + + describe '#newest_first' do + it 'returns transactions sorted from new to old' do + trans1 = Gitlab::Sherlock::Transaction.new('POST', '/cat_pictures') + trans2 = Gitlab::Sherlock::Transaction.new('POST', '/more_cat_pictures') + + allow(trans1).to receive(:finished_at).and_return(Time.utc(2015, 1, 1)) + allow(trans2).to receive(:finished_at).and_return(Time.utc(2015, 1, 2)) + + collection.add(trans1) + collection.add(trans2) + + expect(collection.newest_first).to eq([trans2, trans1]) + end + end +end diff --git a/spec/lib/gitlab/sherlock/file_sample_spec.rb b/spec/lib/gitlab/sherlock/file_sample_spec.rb new file mode 100644 index 0000000000000000000000000000000000000000..f05a59f56f6cb56a76ef3a74a09075861194ea49 --- /dev/null +++ b/spec/lib/gitlab/sherlock/file_sample_spec.rb @@ -0,0 +1,54 @@ +require 'spec_helper' + +describe Gitlab::Sherlock::FileSample do + let(:sample) { described_class.new(__FILE__, [], 150.4, 2) } + + describe '#id' do + it 'returns the ID' do + expect(sample.id).to be_an_instance_of(String) + end + end + + describe '#file' do + it 'returns the file path' do + expect(sample.file).to eq(__FILE__) + end + end + + describe '#line_samples' do + it 'returns the line samples' do + expect(sample.line_samples).to eq([]) + end + end + + describe '#events' do + it 'returns the total number of events' do + expect(sample.events).to eq(2) + end + end + + describe '#duration' do + it 'returns the total execution time' do + expect(sample.duration).to eq(150.4) + end + end + + describe '#relative_path' do + it 'returns the relative path' do + expect(sample.relative_path). + to eq('spec/lib/gitlab/sherlock/file_sample_spec.rb') + end + end + + describe '#to_param' do + it 'returns the sample ID' do + expect(sample.to_param).to eq(sample.id) + end + end + + describe '#source' do + it 'returns the contents of the file' do + expect(sample.source).to eq(File.read(__FILE__)) + end + end +end diff --git a/spec/lib/gitlab/sherlock/line_profiler_spec.rb b/spec/lib/gitlab/sherlock/line_profiler_spec.rb new file mode 100644 index 0000000000000000000000000000000000000000..8f2e1299714ee17775b5b9f1d63d4508193a2660 --- /dev/null +++ b/spec/lib/gitlab/sherlock/line_profiler_spec.rb @@ -0,0 +1,73 @@ +require 'spec_helper' + +describe Gitlab::Sherlock::LineProfiler do + let(:profiler) { described_class.new } + + describe '#profile' do + it 'runs the profiler when using MRI' do + allow(profiler).to receive(:mri?).and_return(true) + allow(profiler).to receive(:profile_mri) + + profiler.profile { 'cats' } + end + + it 'raises NotImplementedError when profiling an unsupported platform' do + allow(profiler).to receive(:mri?).and_return(false) + + expect { profiler.profile { 'cats' } }.to raise_error(NotImplementedError) + end + end + + describe '#profile_mri' do + it 'returns an Array containing the return value and profiling samples' do + allow(profiler).to receive(:lineprof). + and_yield. + and_return({ __FILE__ => [[0, 0, 0, 0]] }) + + retval, samples = profiler.profile_mri { 42 } + + expect(retval).to eq(42) + expect(samples).to eq([]) + end + end + + describe '#aggregate_rblineprof' do + let(:raw_samples) do + { __FILE__ => [[30000, 30000, 5, 0], [15000, 15000, 4, 0]] } + end + + it 'returns an Array of FileSample objects' do + samples = profiler.aggregate_rblineprof(raw_samples) + + expect(samples).to be_an_instance_of(Array) + expect(samples[0]).to be_an_instance_of(Gitlab::Sherlock::FileSample) + end + + describe 'the first FileSample object' do + let(:file_sample) do + profiler.aggregate_rblineprof(raw_samples)[0] + end + + it 'uses the correct file path' do + expect(file_sample.file).to eq(__FILE__) + end + + it 'contains a list of line samples' do + line_sample = file_sample.line_samples[0] + + expect(line_sample).to be_an_instance_of(Gitlab::Sherlock::LineSample) + + expect(line_sample.duration).to eq(15.0) + expect(line_sample.events).to eq(4) + end + + it 'contains the total file execution time' do + expect(file_sample.duration).to eq(30.0) + end + + it 'contains the total amount of file events' do + expect(file_sample.events).to eq(5) + end + end + end +end diff --git a/spec/lib/gitlab/sherlock/line_sample_spec.rb b/spec/lib/gitlab/sherlock/line_sample_spec.rb new file mode 100644 index 0000000000000000000000000000000000000000..5f02f6a3213eb0b998f6b7c2edc6e5b78edbd2d2 --- /dev/null +++ b/spec/lib/gitlab/sherlock/line_sample_spec.rb @@ -0,0 +1,33 @@ +require 'spec_helper' + +describe Gitlab::Sherlock::LineSample do + let(:sample) { described_class.new(150.0, 4) } + + describe '#duration' do + it 'returns the duration' do + expect(sample.duration).to eq(150.0) + end + end + + describe '#events' do + it 'returns the amount of events' do + expect(sample.events).to eq(4) + end + end + + describe '#percentage_of' do + it 'returns the percentage of 1500.0' do + expect(sample.percentage_of(1500.0)).to be_within(0.1).of(10.0) + end + end + + describe '#majority_of' do + it 'returns true if the sample takes up the majority of the given duration' do + expect(sample.majority_of?(500.0)).to eq(true) + end + + it "returns false if the sample doesn't take up the majority of the given duration" do + expect(sample.majority_of?(1500.0)).to eq(false) + end + end +end diff --git a/spec/lib/gitlab/sherlock/location_spec.rb b/spec/lib/gitlab/sherlock/location_spec.rb new file mode 100644 index 0000000000000000000000000000000000000000..b295a624b35e47c86e67ac37da61ddfb233f27dc --- /dev/null +++ b/spec/lib/gitlab/sherlock/location_spec.rb @@ -0,0 +1,40 @@ +require 'spec_helper' + +describe Gitlab::Sherlock::Location do + let(:location) { described_class.new(__FILE__, 1) } + + describe 'from_ruby_location' do + it 'creates a Location from a Thread::Backtrace::Location' do + input = caller_locations[0] + output = described_class.from_ruby_location(input) + + expect(output).to be_an_instance_of(described_class) + expect(output.path).to eq(input.path) + expect(output.line).to eq(input.lineno) + end + end + + describe '#path' do + it 'returns the file path' do + expect(location.path).to eq(__FILE__) + end + end + + describe '#line' do + it 'returns the line number' do + expect(location.line).to eq(1) + end + end + + describe '#application?' do + it 'returns true for an application frame' do + expect(location.application?).to eq(true) + end + + it 'returns false for a non application frame' do + loc = described_class.new('/tmp/cats.rb', 1) + + expect(loc.application?).to eq(false) + end + end +end diff --git a/spec/lib/gitlab/sherlock/middleware_spec.rb b/spec/lib/gitlab/sherlock/middleware_spec.rb new file mode 100644 index 0000000000000000000000000000000000000000..aa74fc53a7954dd6a2413eab494ec4eef64a8d25 --- /dev/null +++ b/spec/lib/gitlab/sherlock/middleware_spec.rb @@ -0,0 +1,79 @@ +require 'spec_helper' + +describe Gitlab::Sherlock::Middleware do + let(:app) { double(:app) } + let(:middleware) { described_class.new(app) } + + describe '#call' do + describe 'when instrumentation is enabled' do + it 'instruments a request' do + allow(middleware).to receive(:instrument?).and_return(true) + allow(middleware).to receive(:call_with_instrumentation) + + middleware.call({}) + end + end + + describe 'when instrumentation is disabled' do + it "doesn't instrument a request" do + allow(middleware).to receive(:instrument).and_return(false) + allow(app).to receive(:call) + + middleware.call({}) + end + end + end + + describe '#call_with_instrumentation' do + it 'instruments a request' do + trans = double(:transaction) + retval = 'cats are amazing' + env = {} + + allow(app).to receive(:call).with(env).and_return(retval) + allow(middleware).to receive(:transaction_from_env).and_return(trans) + allow(trans).to receive(:run).and_yield.and_return(retval) + allow(Gitlab::Sherlock.collection).to receive(:add).with(trans) + + middleware.call_with_instrumentation(env) + end + end + + describe '#instrument?' do + it 'returns false for a text/css request' do + env = { 'HTTP_ACCEPT' => 'text/css', 'REQUEST_URI' => '/' } + + expect(middleware.instrument?(env)).to eq(false) + end + + it 'returns false for a request to a Sherlock route' do + env = { + 'HTTP_ACCEPT' => 'text/html', + 'REQUEST_URI' => '/sherlock/transactions' + } + + expect(middleware.instrument?(env)).to eq(false) + end + + it 'returns true for a request that should be instrumented' do + env = { + 'HTTP_ACCEPT' => 'text/html', + 'REQUEST_URI' => '/cats' + } + + expect(middleware.instrument?(env)).to eq(true) + end + end + + describe '#transaction_from_env' do + it 'returns a Transaction' do + env = { + 'HTTP_ACCEPT' => 'text/html', + 'REQUEST_URI' => '/cats' + } + + expect(middleware.transaction_from_env(env)). + to be_an_instance_of(Gitlab::Sherlock::Transaction) + end + end +end diff --git a/spec/lib/gitlab/sherlock/query_spec.rb b/spec/lib/gitlab/sherlock/query_spec.rb new file mode 100644 index 0000000000000000000000000000000000000000..a9afef5dc1dc8a7ac579bb7eead3ac44d47b320e --- /dev/null +++ b/spec/lib/gitlab/sherlock/query_spec.rb @@ -0,0 +1,113 @@ +require 'spec_helper' + +describe Gitlab::Sherlock::Query do + let(:started_at) { Time.utc(2015, 1, 1) } + let(:finished_at) { started_at + 5 } + + let(:query) do + described_class.new('SELECT COUNT(*) FROM users', started_at, finished_at) + end + + describe 'new_with_bindings' do + it 'returns a Query' do + sql = 'SELECT COUNT(*) FROM users WHERE id = $1' + bindings = [[double(:column), 10]] + + query = described_class. + new_with_bindings(sql, bindings, started_at, finished_at) + + expect(query.query).to eq('SELECT COUNT(*) FROM users WHERE id = 10;') + end + end + + describe '#id' do + it 'returns a String' do + expect(query.id).to be_an_instance_of(String) + end + end + + describe '#query' do + it 'returns the query with a trailing semi-colon' do + expect(query.query).to eq('SELECT COUNT(*) FROM users;') + end + end + + describe '#started_at' do + it 'returns the start time' do + expect(query.started_at).to eq(started_at) + end + end + + describe '#finished_at' do + it 'returns the completion time' do + expect(query.finished_at).to eq(finished_at) + end + end + + describe '#backtrace' do + it 'returns the backtrace' do + expect(query.backtrace).to be_an_instance_of(Array) + end + end + + describe '#duration' do + it 'returns the duration in milliseconds' do + expect(query.duration).to be_within(0.1).of(5000.0) + end + end + + describe '#to_param' do + it 'returns the query ID' do + expect(query.to_param).to eq(query.id) + end + end + + describe '#formatted_query' do + it 'returns a formatted version of the query' do + expect(query.formatted_query).to eq(<<-EOF.strip) +SELECT COUNT(*) +FROM users; + EOF + end + end + + describe '#last_application_frame' do + it 'returns the last application frame' do + frame = query.last_application_frame + + expect(frame).to be_an_instance_of(Gitlab::Sherlock::Location) + expect(frame.path).to eq(__FILE__) + end + end + + describe '#application_backtrace' do + it 'returns an Array of application frames' do + frames = query.application_backtrace + + expect(frames).to be_an_instance_of(Array) + expect(frames).to_not be_empty + + frames.each do |frame| + expect(frame.path).to start_with(Rails.root.to_s) + end + end + end + + describe '#explain' do + it 'returns the query plan as a String' do + lines = [ + ['Aggregate (cost=123 rows=1)'], + [' -> Index Only Scan using index_cats_are_amazing'] + ] + + result = double(:result, values: lines) + + allow(query).to receive(:raw_explain).and_return(result) + + expect(query.explain).to eq(<<-EOF.strip) +Aggregate (cost=123 rows=1) + -> Index Only Scan using index_cats_are_amazing + EOF + end + end +end diff --git a/spec/lib/gitlab/sherlock/transaction_spec.rb b/spec/lib/gitlab/sherlock/transaction_spec.rb new file mode 100644 index 0000000000000000000000000000000000000000..bb49fb65cf8c6ec65bcb5f8a02abe5b17aed2f2b --- /dev/null +++ b/spec/lib/gitlab/sherlock/transaction_spec.rb @@ -0,0 +1,222 @@ +require 'spec_helper' + +describe Gitlab::Sherlock::Transaction do + let(:transaction) { described_class.new('POST', '/cat_pictures') } + + describe '#id' do + it 'returns the transaction ID' do + expect(transaction.id).to be_an_instance_of(String) + end + end + + describe '#type' do + it 'returns the type' do + expect(transaction.type).to eq('POST') + end + end + + describe '#path' do + it 'returns the path' do + expect(transaction.path).to eq('/cat_pictures') + end + end + + describe '#queries' do + it 'returns an Array of queries' do + expect(transaction.queries).to be_an_instance_of(Array) + end + end + + describe '#file_samples' do + it 'returns an Array of file samples' do + expect(transaction.file_samples).to be_an_instance_of(Array) + end + end + + describe '#started_at' do + it 'returns the start time' do + allow(transaction).to receive(:profile_lines).and_yield + + transaction.run { 'cats are amazing' } + + expect(transaction.started_at).to be_an_instance_of(Time) + end + end + + describe '#finished_at' do + it 'returns the completion time' do + allow(transaction).to receive(:profile_lines).and_yield + + transaction.run { 'cats are amazing' } + + expect(transaction.finished_at).to be_an_instance_of(Time) + end + end + + describe '#view_counts' do + it 'returns a Hash' do + expect(transaction.view_counts).to be_an_instance_of(Hash) + end + + it 'sets the default value of a key to 0' do + expect(transaction.view_counts['cats.rb']).to be_zero + end + end + + describe '#run' do + it 'runs the transaction' do + allow(transaction).to receive(:profile_lines).and_yield + + retval = transaction.run { 'cats are amazing' } + + expect(retval).to eq('cats are amazing') + end + end + + describe '#duration' do + it 'returns the duration in seconds' do + start_time = Time.now + + allow(transaction).to receive(:started_at).and_return(start_time) + allow(transaction).to receive(:finished_at).and_return(start_time + 5) + + expect(transaction.duration).to be_within(0.1).of(5.0) + end + end + + describe '#to_param' do + it 'returns the transaction ID' do + expect(transaction.to_param).to eq(transaction.id) + end + end + + describe '#sorted_queries' do + it 'returns the queries in descending order' do + start_time = Time.now + + query1 = Gitlab::Sherlock::Query.new('SELECT 1', start_time, start_time) + + query2 = Gitlab::Sherlock::Query. + new('SELECT 2', start_time, start_time + 5) + + transaction.queries << query1 + transaction.queries << query2 + + expect(transaction.sorted_queries).to eq([query2, query1]) + end + end + + describe '#sorted_file_samples' do + it 'returns the file samples in descending order' do + sample1 = Gitlab::Sherlock::FileSample.new(__FILE__, [], 10.0, 1) + sample2 = Gitlab::Sherlock::FileSample.new(__FILE__, [], 15.0, 1) + + transaction.file_samples << sample1 + transaction.file_samples << sample2 + + expect(transaction.sorted_file_samples).to eq([sample2, sample1]) + end + end + + describe '#find_query' do + it 'returns a Query when found' do + query = Gitlab::Sherlock::Query.new('SELECT 1', Time.now, Time.now) + + transaction.queries << query + + expect(transaction.find_query(query.id)).to eq(query) + end + + it 'returns nil when no query could be found' do + expect(transaction.find_query('cats')).to be_nil + end + end + + describe '#find_file_sample' do + it 'returns a FileSample when found' do + sample = Gitlab::Sherlock::FileSample.new(__FILE__, [], 10.0, 1) + + transaction.file_samples << sample + + expect(transaction.find_file_sample(sample.id)).to eq(sample) + end + + it 'returns nil when no file sample could be found' do + expect(transaction.find_file_sample('cats')).to be_nil + end + end + + describe '#profile_lines' do + describe 'when line profiling is enabled' do + it 'yields the block using the line profiler' do + allow(Gitlab::Sherlock).to receive(:enable_line_profiler?). + and_return(true) + + allow_any_instance_of(Gitlab::Sherlock::LineProfiler). + to receive(:profile).and_return('cats are amazing', []) + + retval = transaction.profile_lines { 'cats are amazing' } + + expect(retval).to eq('cats are amazing') + end + end + + describe 'when line profiling is disabled' do + it 'yields the block' do + allow(Gitlab::Sherlock).to receive(:enable_line_profiler?). + and_return(false) + + retval = transaction.profile_lines { 'cats are amazing' } + + expect(retval).to eq('cats are amazing') + end + end + end + + describe '#subscribe_to_active_record' do + let(:subscription) { transaction.subscribe_to_active_record } + let(:time) { Time.now } + let(:query_data) { { sql: 'SELECT 1', binds: [] } } + + after do + ActiveSupport::Notifications.unsubscribe(subscription) + end + + it 'tracks executed queries' do + expect(transaction).to receive(:track_query). + with('SELECT 1', [], time, time) + + subscription.publish('test', time, time, nil, query_data) + end + + it 'only tracks queries triggered from the transaction thread' do + expect(transaction).to_not receive(:track_query) + + Thread.new { subscription.publish('test', time, time, nil, query_data) }. + join + end + end + + describe '#subscribe_to_action_view' do + let(:subscription) { transaction.subscribe_to_action_view } + let(:time) { Time.now } + let(:view_data) { { identifier: 'foo.rb' } } + + after do + ActiveSupport::Notifications.unsubscribe(subscription) + end + + it 'tracks rendered views' do + expect(transaction).to receive(:track_view).with('foo.rb') + + subscription.publish('test', time, time, nil, view_data) + end + + it 'only tracks views rendered from the transaction thread' do + expect(transaction).to_not receive(:track_view) + + Thread.new { subscription.publish('test', time, time, nil, view_data) }. + join + end + end +end