bullet
bullet copied to clipboard
Published
20 hours ago •
flyerhzm
flyerhzm
Big performance issues with auto-crafted active record model
TL;DR When bullet is activated, my request take ~4 seconds to load. When it's not, it take only 0.05s
The problem
I've a big performance issue in the case of crafted active record model.
Before showing the issue, I need to explain first what we do:
We need to handle parameterable views in our project, to simplify our code and avoid N+1 request. The fact is the views we are trying to render are too complex for the standard eager_loading / includes or active record.
We then prefer to craft our views through SQL and use it as readonly model through active record.
Here is an example of our views:
class View::Parametrable < ActiveRecord::Base
self.abstract_class = true
def readonly?; true; end
def self.view
raise NotImplementedError, "Parametrable view must implement a class method view to perform the SQL!"
end
def self.columns_definition
raise NotImplementedError, "You must setup the columns"
end
def self.[](*args)
Class.new(self) do
default_scope -> { include_from(*args) }
end
end
def self.load_schema!
@columns_hash = Hash[
self.columns_definition.map do |name, value|
[name.to_s,
ActiveRecord::ConnectionAdapters::Column.new(
name.to_s,
nil,
ActiveRecord::ConnectionAdapters::SqlTypeMetadata.new(sql_type: value)
)
]
end
]
end
private
def self.include_from *args
@computed_view ||= sanitize_sql([self.view, *args])
code = "(#{@computed_view}) AS #{self.table_name}"
from(code)
end
end
And here an example of implementation:
class View::UserHistory < View::Parametrable
def self.columns_definition
{
id: 'integer',
user_id: 'integer',
project_id: 'integer',
batch_id: 'integer',
project_name: 'text',
state: 'text',
starts_at: 'date',
ends_at: 'date',
status: 'string',
task_id: 'integer',
total_time: 'integer',
end_reason: 'string',
total_pause_time: 'integer'
}
end
def self.view
<<-SQL
SELECT
user_time_ranges.id as id,
user_time_ranges.user_id as user_id,
projects.id as project_id,
project_tasks.batch_id as batch_id,
projects.name as project_name,
project_task_states.state as state,
user_time_ranges.starts_at as starts_at,
user_time_ranges.ends_at as ends_at,
(
CASE
WHEN project_task_states.ends_at IS NULL THEN 'done'
ELSE 'in_progress'
END
) as status,
project_tasks.id as task_id,
user_time_ranges.total_in_seconds as total_time,
user_time_ranges.end_reason as end_reason,
(
SELECT
EXTRACT(
EPOCH FROM utr2.starts_at - user_time_ranges.ends_at
)::integer
FROM user_time_ranges utr2
WHERE
utr2.starts_at > user_time_ranges.ends_at AND
utr2.user_id = :user_id
ORDER BY utr2.starts_at ASC
LIMIT 1
) as total_pause_time
FROM user_time_ranges
INNER JOIN project_tasks ON project_tasks.id = user_time_ranges.task_id
INNER JOIN project_task_states ON project_task_states.id = user_time_ranges.state_id
INNER JOIN projects ON projects.id = project_tasks.project_id
WHERE
user_time_ranges.starts_at >= :starts_at AND
user_time_ranges.ends_at <= :ends_at AND
user_time_ranges.user_id = :user_id
ORDER BY
user_time_ranges.starts_at ASC
SQL
end
belongs_to :project
belongs_to :task, class_name: "Project::Task"
belongs_to :user
belongs_to :time_range, class_name: "User::TimeRange"
end
Then we access to the view like this:
View::UserHistory[starts_at: '2017-02-15 00:00:00', ends_at: '2017-02-15 23:59:59', user_id: 53]
It works perfectly fine with Active Record, is quite fast and on our refactoring we improve the speed of our request by a factor of x10 or more.
However, in development target, bullet is starting to get stuck with theses kind of models.
Here is the profiling stack trace. As seen, the thread love to take time into Object#bullet_key.
As far as I know, our view generation strategy is a bit tricky, we fake the active record columns reflection and the model table doesn't really exists. Yeah, we forge the fake table in the FROM clause of ActiveRecord...
Is there anything we can do to improve our system and make it works with bullet without performance leaking ?
%total %self total self wait child calls name
--------------------------------------------------------------------------------
100.00% 0.00% 4.611 0.000 0.000 4.611 1 ActionView::CompiledTemplates#_app_views_tasks__daily_user_table_html_haml___2212557634625081580_70280950334840
4.600 0.000 0.000 4.600 1/1 ActiveRecord::Relation#to_a
0.011 0.000 0.000 0.011 1/2 ActiveRecord::Scoping::Named::ClassMethods#all
0.000 0.000 0.000 0.000 1/1 Array#count
--------------------------------------------------------------------------------
4.600 0.000 0.000 4.600 1/1 ActionView::CompiledTemplates#_app_views_tasks__daily_user_table_html_haml___2212557634625081580_70280950334840
99.77% 0.00% 4.600 0.000 0.000 4.600 1 ActiveRecord::Relation#to_a
4.600 0.000 0.000 4.600 1/2 ActiveRecord::Relation#records
0.000 0.000 0.000 0.000 1/21 Kernel#dup
--------------------------------------------------------------------------------
2.623 0.000 0.000 2.623 1/2 ActiveRecord::Relation#records
4.600 0.000 0.000 4.600 1/2 ActiveRecord::Relation#to_a
99.77% 0.00% 4.600 0.000 0.000 4.600 2 *ActiveRecord::Relation#records
2.623 0.000 0.000 2.623 1/2 ActiveRecord::Relation#records
2.623 0.000 0.000 2.623 1/1 ActiveRecord::Relation#load
1.027 0.000 0.000 1.027 1/2 <Class::Bullet::Detector::NPlusOneQuery>#add_possible_objects
0.949 0.000 0.000 0.949 1/2 <Class::Bullet::Detector::CounterCache>#add_possible_objects
0.001 0.001 0.000 0.000 1/14 Module#name
0.000 0.000 0.000 0.000 1/1 Kernel#!~
0.000 0.000 0.000 0.000 1/6 <Module::Bullet>#start?
0.000 0.000 0.000 0.000 1/38827 Kernel#class
0.000 0.000 0.000 0.000 1/4 Array#first
--------------------------------------------------------------------------------
2.126 0.067 0.000 2.059 2156/4312 Array#each
2.331 0.075 0.000 2.256 2156/4312 Array#map
96.68% 3.09% 4.458 0.143 0.000 4.315 4312 Object#bullet_key
4.120 4.120 0.000 0.000 4312/4312 Module#to_s
0.172 0.022 0.000 0.151 4312/6468 Object#primary_key_value
0.022 0.013 0.000 0.009 4312/4313 ActiveSupport::NumericWithFormat#to_s
0.001 0.001 0.000 0.000 4312/38827 Kernel#class
--------------------------------------------------------------------------------
4.120 4.120 0.000 0.000 4312/4312 Object#bullet_key
89.36% 89.36% 4.120 4.120 0.000 0.000 4312 Module#to_s
--------------------------------------------------------------------------------
2.623 0.000 0.000 2.623 1/1 ActiveRecord::Relation#records
56.89% 0.00% 2.623 0.000 0.000 2.623 1 ActiveRecord::Relation#load
2.623 0.000 0.000 2.623 1/1 ActiveRecord::Relation#exec_queries
--------------------------------------------------------------------------------
2.623 0.000 0.000 2.623 1/1 ActiveRecord::Relation#load
56.89% 0.00% 2.623 0.000 0.000 2.623 1 ActiveRecord::Relation#exec_queries
2.623 0.000 0.000 2.623 1/1 <Class::ActiveRecord::Base>#find_by_sql
0.000 0.000 0.000 0.000 1/2 ActiveRecord::QueryMethods#arel
0.000 0.000 0.000 0.000 1/1 ActiveRecord::QueryMethods#bound_attributes
0.000 0.000 0.000 0.000 2/2 ActiveRecord::Relation#eager_loading?
0.000 0.000 0.000 0.000 1/1 ActiveRecord::Relation#build_preloader
0.000 0.000 0.000 0.000 1/5 Kernel#freeze
0.000 0.000 0.000 0.000 1/3 ActiveRecord::QueryMethods#preload_values
0.000 0.000 0.000 0.000 1/1 ActiveRecord::QueryMethods#readonly_value
0.000 0.000 0.000 0.000 1/12961 Array#each
0.000 0.000 0.000 0.000 1/5 ActiveRecord::QueryMethods#includes_values
--------------------------------------------------------------------------------
2.623 0.000 0.000 2.623 1/1 ActiveRecord::Relation#exec_queries
56.89% 0.00% 2.623 0.000 0.000 2.623 1 <Class::ActiveRecord::Base>#find_by_sql
1.342 0.000 0.000 1.342 1/2 <Class::Bullet::Detector::CounterCache>#add_possible_objects
1.236 0.000 0.000 1.236 1/2 <Class::Bullet::Detector::NPlusOneQuery>#add_possible_objects
0.046 0.000 0.000 0.046 1/1 ActiveRecord::Querying#find_by_sql
0.000 0.000 0.000 0.000 1/6 <Module::Bullet>#start?
0.000 0.000 0.000 0.000 1/11336 Kernel#is_a?
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/12 ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_no_cache
0.000 0.000 0.000 0.000 1/12 Arel::SelectManager#project
0.004 0.004 0.000 0.000 2/12 ActiveRecord::Result#hash_rows
1.142 0.002 0.000 1.140 4/12 <Class::Bullet::Detector::NPlusOneQuery>#add_possible_objects
1.251 0.002 0.000 1.248 4/12 <Class::Bullet::Detector::CounterCache>#add_possible_objects
51.97% 0.18% 2.396 0.008 0.000 2.388 12 Array#map
2.331 0.075 0.000 2.256 2156/4312 Object#bullet_key
0.057 0.005 0.000 0.051 2156/6468 Object#primary_key_value
0.000 0.000 0.000 0.000 13/21 Kernel#dup
0.000 0.000 0.000 0.000 13/13 String#freeze
0.000 0.000 0.000 0.000 1/12 Array#include?
0.000 0.000 0.000 0.000 1/38827 Kernel#class
--------------------------------------------------------------------------------
0.949 0.000 0.000 0.949 1/2 ActiveRecord::Relation#records
1.342 0.000 0.000 1.342 1/2 <Class::ActiveRecord::Base>#find_by_sql
49.68% 0.00% 2.290 0.000 0.000 2.290 2 <Class::Bullet::Detector::CounterCache>#add_possible_objects
1.251 0.002 0.000 1.248 4/12 Array#map
1.039 0.002 0.000 1.037 2/12961 Array#each
0.000 0.000 0.000 0.000 2/4 Array#join
0.000 0.000 0.000 0.000 2/4 <Module::Bullet>#debug
0.000 0.000 0.000 0.000 2/6 <Module::Bullet>#start?
0.000 0.000 0.000 0.000 2/4 Array#compact
0.000 0.000 0.000 0.000 2/2 <Module::Bullet>#counter_cache_enable?
0.000 0.000 0.000 0.000 2/4 Kernel#Array
--------------------------------------------------------------------------------
1.027 0.000 0.000 1.027 1/2 ActiveRecord::Relation#records
1.236 0.000 0.000 1.236 1/2 <Class::ActiveRecord::Base>#find_by_sql
49.08% 0.00% 2.263 0.000 0.000 2.263 2 <Class::Bullet::Detector::NPlusOneQuery>#add_possible_objects
1.142 0.002 0.000 1.140 4/12 Array#map
1.121 0.002 0.000 1.118 2/12961 Array#each
0.000 0.000 0.000 0.000 2/4 Array#join
0.000 0.000 0.000 0.000 2/4 <Module::Bullet>#debug
0.000 0.000 0.000 0.000 2/4 Array#compact
0.000 0.000 0.000 0.000 2/6 <Module::Bullet>#start?
0.000 0.000 0.000 0.000 2/2 <Module::Bullet>#n_plus_one_query_enable?
0.000 0.000 0.000 0.000 2/4 Kernel#Array
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/12961 ActiveModel::AttributeMethods::ClassMethods#define_attribute_methods
0.000 0.000 0.000 0.000 2/12961 Enumerable#grep
0.000 0.000 0.000 0.000 2/12961 Enumerable#each_entry
0.000 0.000 0.000 0.000 2/12961 ActiveRecord::QueryMethods#validate_order_args
0.000 0.000 0.000 0.000 1/12961 ActiveRecord::Relation#exec_queries
0.000 0.000 0.000 0.000 2/12961 ActiveRecord::Relation::Merger#merge
0.000 0.000 0.000 0.000 2/12961 ActiveSupport::Notifications::Fanout#start
0.000 0.000 0.000 0.000 2/12961 Enumerable#each_with_index
0.000 0.000 0.000 0.000 2/12961 ActiveRecord::Relation::Merger#merge_clauses
0.001 0.000 0.000 0.001 2/12961 ActiveSupport::Notifications::Fanout#finish
0.009 0.000 0.000 0.008 2/12961 Enumerable#inject
0.023 0.001 0.000 0.022 1/12961 ActiveRecord::Result#each
0.064 0.025 0.000 0.039 12936/12961 Enumerable#find
1.039 0.002 0.000 1.037 2/12961 <Class::Bullet::Detector::CounterCache>#add_possible_objects
1.121 0.002 0.000 1.118 2/12961 <Class::Bullet::Detector::NPlusOneQuery>#add_possible_objects
48.45% 0.46% 2.234 0.021 0.000 2.213 12961 *Array#each
2.126 0.067 0.000 2.059 2156/4312 Object#bullet_key
0.025 0.025 0.000 0.000 25872/25872 Symbol#=~
0.025 0.004 0.000 0.021 2156/2156 Bullet::Registry::Object#add
0.022 0.001 0.000 0.021 539/539 ActiveRecord::Persistence::ClassMethods#instantiate
0.014 0.014 0.000 0.000 25872/25872 <Class::ActiveRecord::DynamicMatchers::Method>#pattern
0.008 0.000 0.000 0.008 1/1 BasicObject#instance_exec
0.002 0.001 0.000 0.001 1078/1078 <Class::Bullet::Detector::CounterCache>#possible_objects
0.002 0.001 0.000 0.001 1078/1078 <Class::Bullet::Detector::Association>#possible_objects
0.001 0.000 0.000 0.001 2/2 ActiveSupport::Notifications::Fanout::Subscribers::Evented#finish
0.000 0.000 0.000 0.000 1/1 ActiveRecord::SpawnMethods#merge
0.000 0.000 0.000 0.000 4/4 ActiveRecord::Relation::WhereClause#merge
0.000 0.000 0.000 0.000 13/13 ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#get_oid_type
0.000 0.000 0.000 0.000 1/1 Arel::Visitors::ToSql#visit_Arel_Nodes_SelectCore
0.000 0.000 0.000 0.000 2/2 ActiveSupport::Notifications::Fanout::Subscribers::Evented#start
0.000 0.000 0.000 0.000 1/4 Arel::Visitors::Reduce#visit
0.000 0.000 0.000 0.000 1/1 ActiveSupport::Notifications::Fanout::Subscribers::Timed#finish
0.000 0.000 0.000 0.000 4/6 ActiveRecord::QueryMethods#where_clause
0.000 0.000 0.000 0.000 1/1 ActiveSupport::Notifications::Fanout::Subscribers::Timed#start
0.000 0.000 0.000 0.000 4/6 ActiveRecord::QueryMethods#having_clause
0.000 0.000 0.000 0.000 2/2 ActiveRecord::QueryMethods#having_clause=
0.000 0.000 0.000 0.000 2/2 ActiveRecord::QueryMethods#where_clause=
0.000 0.000 0.000 0.000 24/34 NilClass#nil?
0.000 0.000 0.000 0.000 2/5 ActiveRecord::QueryMethods#from_clause=
0.000 0.000 0.000 0.000 13/13 PG::Result#ftype
0.000 0.000 0.000 0.000 2/2 ActiveRecord::Relation::FromClause#merge
0.000 0.000 0.000 0.000 13/13 PG::Result#fmod
0.000 0.000 0.000 0.000 4/12 ActiveRecord::QueryMethods#from_clause
0.000 0.000 0.000 0.000 1/12952 Kernel#respond_to?
--------------------------------------------------------------------------------
0.057 0.005 0.000 0.051 2156/6468 Array#map
0.172 0.022 0.000 0.151 4312/6468 Object#bullet_key
4.97% 0.59% 0.229 0.027 0.000 0.202 6468 Object#primary_key_value
0.115 0.021 0.000 0.093 12936/12936 ActiveRecord::DynamicMatchers#respond_to?
0.071 0.012 0.000 0.059 6468/6468 ActiveRecord::AttributeMethods::PrimaryKey#id
0.009 0.009 0.000 0.000 12936/19406 ActiveRecord::AttributeMethods::PrimaryKey::ClassMethods#primary_key
0.007 0.007 0.000 0.000 25872/38827 Kernel#class
--------------------------------------------------------------------------------
0.115 0.021 0.000 0.093 12936/12936 Object#primary_key_value
2.49% 0.46% 0.115 0.021 0.000 0.093 12936 ActiveRecord::DynamicMatchers#respond_to?
0.089 0.013 0.000 0.076 12936/12936 <Class::ActiveRecord::DynamicMatchers::Method>#match
0.005 0.005 0.000 0.000 12936/12952 Kernel#respond_to?
--------------------------------------------------------------------------------
0.089 0.013 0.000 0.076 12936/12936 ActiveRecord::DynamicMatchers#respond_to?
1.92% 0.28% 0.089 0.013 0.000 0.076 12936 <Class::ActiveRecord::DynamicMatchers::Method>#match
0.076 0.012 0.000 0.064 12936/12936 Enumerable#find
--------------------------------------------------------------------------------
0.076 0.012 0.000 0.064 12936/12936 <Class::ActiveRecord::DynamicMatchers::Method>#match
1.64% 0.25% 0.076 0.012 0.000 0.064 12936 Enumerable#find
0.064 0.025 0.000 0.039 12936/12961 Array#each
--------------------------------------------------------------------------------
0.071 0.012 0.000 0.059 6468/6468 Object#primary_key_value
1.53% 0.26% 0.071 0.012 0.000 0.059 6468 ActiveRecord::AttributeMethods::PrimaryKey#id
0.044 0.008 0.000 0.036 6468/6468 ActiveRecord::AttributeMethods::Read#_read_attribute
0.009 0.006 0.000 0.003 6468/6468 ActiveRecord::Transactions#sync_with_transaction_state
0.004 0.004 0.000 0.000 6468/19406 ActiveRecord::AttributeMethods::PrimaryKey::ClassMethods#primary_key
0.002 0.002 0.000 0.000 6468/38827 Kernel#class
--------------------------------------------------------------------------------
