Commit 26344c8f authored by Yorick Peterse's avatar Yorick Peterse

Merge branch 'sherlock' into 'master'

See merge request !1749
parents bd54bf7a 68843a53
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
......
......@@ -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'
......
......@@ -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)
......
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;
}
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
module Sherlock
class FileSamplesController < Sherlock::ApplicationController
def show
@file_sample = @transaction.find_file_sample(params[:id])
end
end
end
module Sherlock
class QueriesController < Sherlock::ApplicationController
def show
@query = @transaction.find_query(params[:id])
end
end
end
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
......@@ -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')
......
- 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)
.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
.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
- 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')
- 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')
.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')
- 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')
- 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')
- 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')
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
if Gitlab::Sherlock.enabled?
Gitlab::Application.configure do |config|
config.middleware.use(Gitlab::Sherlock::Middleware)
end
end
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
......@@ -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
......
......@@ -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.
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment