BigW Consortium Gitlab

Skip to content

G
gitlab-ce
Commit dec3e4ce by Yorick Peterse
Options

Added Sherlock, a custom profiling tool for GitLab

Sherlock will be a new GitLab specific tool for measuring the performance of Rails requests (and SideKiq jobs at some point). Some of the things that are currently tracked: * SQL queries along with their timings, backtraces and query plans (using "EXPLAIN ANALYZE" for PostgreSQL and regular "EXPLAIN" for MySQL) * Timings of application files (including views) on a per line basis * Some meta data such as the request method, path, total duration, etc More tracking (e.g. Rugged or gitlab-shell timings) might be added in the future. Sherlock will replace any existing tools we have used so far (e.g. active_record_query_trace and rack-mini-profiler), hence the corresponding Gems have been removed from the Gemfile. Sherlock can be enabled by starting Rails as following: ENABLE_SHERLOCK=1 bundle exec rails s Recorded transactions can be found at `/sherlock/transactions`.
parent bd54bf7a
Showing with 855 additions and 23 deletions
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'
......
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)
......
app/assets/stylesheets/pages/sherlock.scss 0 → 100644
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;
}
app/controllers/sherlock/application_controller.rb 0 → 100644
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
app/controllers/sherlock/file_samples_controller.rb 0 → 100644
module Sherlock
class FileSamplesController < Sherlock::ApplicationController
def show
@file_sample = @transaction.find_file_sample(params[:id])
end
end
end
app/controllers/sherlock/queries_controller.rb 0 → 100644
module Sherlock
class QueriesController < Sherlock::ApplicationController
def show
@query = @transaction.find_query(params[:id])
end
end
end
app/controllers/sherlock/transactions_controller.rb 0 → 100644
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
app/views/sherlock/file_samples/show.html.haml 0 → 100644
- 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)
app/views/sherlock/queries/_backtrace.html.haml 0 → 100644
.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
app/views/sherlock/queries/_general.html.haml 0 → 100644
.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
app/views/sherlock/queries/show.html.haml 0 → 100644
- 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')
app/views/sherlock/transactions/_file_samples.html.haml 0 → 100644
- if @transaction.file_samples.empty?
.nothing-here-block
= t('sherlock.no_file_samples')
- else
.table-holder
%table.table
%thead
%tr
%th= t('sherlock.time_inclusive')
%th= t('sherlock.path')
%th
%tbody
- @transaction.sorted_file_samples.each do |sample|
%tr
%td
= sample.duration.round(2)
= t('sherlock.milliseconds')
%td= sample.relative_path
%td
= link_to(t('sherlock.view'),
sherlock_transaction_file_sample_path(@transaction, sample),
class: 'btn btn-xs')
app/views/sherlock/transactions/_general.html.haml 0 → 100644
.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')
app/views/sherlock/transactions/_queries.html.haml 0 → 100644
- 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')
app/views/sherlock/transactions/index.html.haml 0 → 100644
- page_title t('sherlock.title')
- header_title t('sherlock.title'), sherlock_transactions_path
.gray-content-block
.pull-right
= link_to(destroy_all_sherlock_transactions_path,
class: 'btn btn-danger',
method: :delete) do
%i.fa.fa-trash
= t('sherlock.delete_all_transactions')
.oneline= t('sherlock.introduction')
- if @transactions.empty?
.nothing-here-block= t('sherlock.no_transactions')
- else
.table-holder
%table.table
%thead
%tr
%th= t('sherlock.type')
%th= t('sherlock.path')
%th= t('sherlock.time')
%th= t('sherlock.queries')
%th= t('sherlock.finished_at')
%th
%tbody
- @transactions.each do |trans|
%tr
%td= trans.type
%td= trans.path
%td
= trans.duration.round(2)
= t('sherlock.seconds')
%td= trans.queries.length
%td
= time_ago_in_words(trans.finished_at)
= t('sherlock.ago')
%td
= link_to(sherlock_transaction_path(trans), class: 'btn btn-xs') do
= t('sherlock.view')
app/views/sherlock/transactions/show.html.haml 0 → 100644
- 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')
config/initializers/rack_profiler.rb deleted 100644 → 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
config/initializers/sherlock.rb 0 → 100644
if Gitlab::Sherlock.enabled?
Gitlab::Application.configure do |config|
config.middleware.use(Gitlab::Sherlock::Middleware)
end
end
config/locales/sherlock.en.yml 0 → 100644
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: '%'
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
......
lib/gitlab/sherlock.rb 0 → 100644
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
lib/gitlab/sherlock/collection.rb 0 → 100644
module Gitlab
module Sherlock
class Collection
include Enumerable
def initialize
@transactions = []
@mutex = Mutex.new
end
def add(transaction)
synchronize { @transactions << transaction }
end
alias_method :<<, :add
def each(&block)
synchronize { @transactions.each(&block) }
end
def clear
synchronize { @transactions.clear }
end
def empty?
synchronize { @transactions.empty? }
end
def find_transaction(id)
find { |trans| trans.id == id }
end
def newest_first
sort { |a, b| b.finished_at <=> a.finished_at }
end
def synchronize(&block)
@mutex.synchronize(&block)
end
end
end
end
lib/gitlab/sherlock/file_sample.rb 0 → 100644
module Gitlab
module Sherlock
class FileSample
attr_reader :id, :file, :line_samples, :events, :duration
def initialize(file, line_samples, duration, events)
@id = SecureRandom.uuid
@file = file
@line_samples = line_samples
@duration = duration
@events = events
end
def relative_path
@relative_path ||= @file.gsub(/^#{Rails.root.to_s}\/?/, '')
end
def to_param
@id
end
def source
@source ||= File.read(@file)
end
end
end
end
lib/gitlab/sherlock/line_profiler.rb 0 → 100644
module Gitlab
module Sherlock
class LineProfiler
# The minimum amount of time that has to be spent in a file for it to be
# included in a list of samples.
MINIMUM_DURATION = 10.0
def profile(&block)
if RUBY_ENGINE == 'ruby'
profile_mri(&block)
else
raise NotImplementedError,
'Line profiling is not supported on this platform'
end
end
def profile_mri
retval = nil
samples = lineprof(/^#{Rails.root.to_s}/) { retval = yield }
file_samples = aggregate_rblineprof(samples)
[retval, file_samples]
end
# Returns an Array of file samples based on the output of rblineprof.
def aggregate_rblineprof(lineprof_stats)
samples = []
lineprof_stats.each do |(file, stats)|
source_lines = File.read(file).each_line.to_a
line_samples = []
total_duration = microsec_to_millisec(stats[0][0])
total_events = stats[0][2]
next if total_duration <= MINIMUM_DURATION
stats[1..-1].each_with_index do |data, index|
next unless source_lines[index]
duration = microsec_to_millisec(data[0])
events = data[2]
line_samples << LineSample.new(duration, events)
end
samples << FileSample.
new(file, line_samples, total_duration, total_events)
end
samples
end
def microsec_to_millisec(microsec)
microsec / 1000.0
end
end
end
end
lib/gitlab/sherlock/line_sample.rb 0 → 100644
module Gitlab
module Sherlock
class LineSample
attr_reader :duration, :events
def initialize(duration, events)
@duration = duration
@events = events
end
def percentage_of(total_duration)
(duration.to_f / total_duration) * 100.0
end
def majority_of?(total_duration)
percentage_of(total_duration) >= 30
end
end
end
end
lib/gitlab/sherlock/location.rb 0 → 100644
module Gitlab
module Sherlock
class Location
attr_reader :path, :line
SHERLOCK_DIR = File.dirname(__FILE__)
def self.from_ruby_location(location)
new(location.path, location.lineno)
end
def initialize(path, line)
@path = path
@line = line
end
def application?
@path.start_with?(Rails.root.to_s) && !path.start_with?(SHERLOCK_DIR)
end
end
end
end
lib/gitlab/sherlock/middleware.rb 0 → 100644
module Gitlab
module Sherlock
# Rack middleware used for tracking request metrics.
class Middleware
CONTENT_TYPES = /text\/html|application\/json/i
IGNORE_PATHS = %r{^/sherlock}
def initialize(app)
@app = app
end
def call(env)
if instrument?(env)
call_with_instrumentation(env)
else
@app.call(env)
end
end
def call_with_instrumentation(env)
trans = Transaction.new(env['REQUEST_METHOD'], env['REQUEST_URI'])
retval = trans.run { @app.call(env) }
Sherlock.collection.add(trans)
retval
end
def instrument?(env)
!!(env['HTTP_ACCEPT'] =~ CONTENT_TYPES &&
env['REQUEST_URI'] !~ IGNORE_PATHS)
end
end
end
end
lib/gitlab/sherlock/query.rb 0 → 100644
module Gitlab
module Sherlock
class Query
attr_reader :id, :query, :started_at, :finished_at, :backtrace
PREFIX_NEWLINE = /
\s+(FROM
|(LEFT|RIGHT)?INNER\s+JOIN
|(LEFT|RIGHT)?OUTER\s+JOIN
|WHERE
|AND
|GROUP\s+BY
|ORDER\s+BY
|LIMIT
|OFFSET)\s+
/ix
def self.new_with_bindings(query, bindings, started_at, finished_at)
bindings.each_with_index do |(column, value), index|
quoted_value = ActiveRecord::Base.connection.quote(value)
query = query.gsub("$#{index + 1}", quoted_value)
end
new(query, started_at, finished_at)
end
def initialize(query, started_at, finished_at)
@id = SecureRandom.uuid
@query = query
@started_at = started_at
@finished_at = finished_at
@backtrace = caller_locations.map do |loc|
Location.from_ruby_location(loc)
end
unless @query.end_with?(';')
@query += ';'
end
end
def duration
@duration ||= (@finished_at - @started_at) * 1000.0
end
def to_param
@id
end
def formatted_query
@formatted_query ||= format_sql(@query)
end
def last_application_frame
@last_application_frame ||= @backtrace.find(&:application?)
end
def application_backtrace
@application_backtrace ||= @backtrace.select(&:application?)
end
def explain
unless @explain
ActiveRecord::Base.connection.transaction do
@explain = raw_explain(@query).values.flatten.join("\n")
# Roll back any queries that mutate data so we don't mess up
# anything when running explain on an INSERT, UPDATE, DELETE, etc.
raise ActiveRecord::Rollback
end
end
@explain
end
private
def raw_explain(query)
if Gitlab::Database.postgresql?
explain = "EXPLAIN ANALYZE #{query};"
else
explain = "EXPLAIN #{query};"
end
ActiveRecord::Base.connection.execute(explain)
end
def format_sql(query)
query.each_line.
map { |line| line.strip }.
join("\n").
gsub(PREFIX_NEWLINE) { "\n#{$1} " }
end
end
end
end
lib/gitlab/sherlock/transaction.rb 0 → 100644
module Gitlab
module Sherlock
class Transaction
attr_reader :id, :type, :path, :queries, :file_samples, :started_at,
:finished_at
def initialize(type, path)
@id = SecureRandom.uuid
@type = type
@path = path
@duration = 0
@queries = []
@file_samples = []
@started_at = nil
@finished_at = nil
@thread = Thread.current
end
def run
@started_at = Time.now
subscriber = subscribe_to_active_record
retval = profile_lines { yield }
@finished_at = Time.now
ActiveSupport::Notifications.unsubscribe(subscriber)
retval
end
def duration
@started_at && @finished_at ? @finished_at - @started_at : 0
end
def to_param
@id
end
def sorted_queries
@queries.sort { |a, b| b.duration <=> a.duration }
end
def sorted_file_samples
@file_samples.sort { |a, b| b.duration <=> a.duration }
end
def find_query(id)
@queries.find { |query| query.id == id }
end
def find_file_sample(id)
@file_samples.find { |sample| sample.id == id }
end
def track_query(query, bindings, start, finish)
@queries << Query.new_with_bindings(query, bindings, start, finish)
end
def profile_lines
retval = nil
if Sherlock.enable_line_profiler?
retval, @file_samples = LineProfiler.new.profile { yield }
else
retval = yield
end
retval
end
def subscribe_to_active_record
ActiveSupport::Notifications.subscribe('sql.active_record') do |_, start, finish, _, data|
# In case somebody uses a multi-threaded server locally (e.g. Puma) we
# _only_ want to track queries that originate from the transaction
# thread.
next unless Thread.current == @thread
track_query(data[:sql].strip, data[:binds], start, finish)
end
end
end
end
end
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