Investigating Performance
Poor performance is bad for user experience. If you notice that parts of the ELN don't perform as well as you'd like, it might be helpful to find out why that is the case, and how you could improve it. This chapter provides some guidance on how to investigate performance.
We follow the example of investigating the performance of creating a reaction. We'll only deal with the backend for the moment, meaning the performance investigation will be limited to Ruby.
For a good general primer on performance investigations have a look at this video.
Isolating the issue
Once you've identified a performance issue (e.g., creating a reaction is slow), you need a quick, repeatable way to reproduce it.
This is why we start by setting up an rspec test to isolate the issue.
spec/api/reaction_api_performance_spec.rb
# frozen_string_literal: true
require 'rails_helper'
describe 'Reaction API POST' do
let(:user) { create(:user) }
let(:root_container) { create(:root_container) }
let(:collection) { Collection.create!(label: 'Collection', user: user) }
let(:reaction) { create(:reaction, name: 'Reaction', collections: [collection]) }
let(:sample) { create(:sample, name: 'Sample', container: FactoryBot.create(:container)) }
let(:molfile) { File.read(Rails.root + 'spec/fixtures/test_2.mol') }
let(:params) do
{
'name' => 'r001',
'collection_id' => collection.id,
'container' => root_container,
'materials' => {
'starting_materials' => [
'id' => sample.id,
'name' => 'starting_material',
'target_amount_unit' => 'mg',
'target_amount_value' => 75.09596,
'equivalent' => 1,
'reference' => false,
'is_new' => false,
'molfile' => molfile,
'container' => root_container
],
'reactants' => [
'target_amount_unit' => 'mg',
'target_amount_value' => 86.09596,
'equivalent' => 2,
'reference' => false,
'is_new' => true,
'molfile' => molfile,
'container' => root_container,
'parent_id' => sample.id # gets named after parent, hence no name specified
],
'products' => [
'name' => 'product',
'target_amount_unit' => 'mg',
'target_amount_value' => 99.08304,
'equivalent' => 5.5,
'reference' => false,
'is_new' => true,
'molfile' => molfile,
'container' => root_container
],
'solvents' => [
'name' => 'solvent',
'target_amount_unit' => 'mg',
'target_amount_value' => 76.09596,
'equivalent' => 1,
'reference' => true,
'is_new' => true,
'molfile' => molfile,
'container' => root_container
]
}
}
end
before do
allow_any_instance_of(WardenAuthentication).to receive(:current_user)
.and_return(user)
ReactionsStartingMaterialSample.create!(
reaction: reaction, sample: sample, reference: true, equivalent: 1
)
end
it 'creates reaction in under one second', :profile do
post '/api/v1/reactions', params: params, as: :json
end
end
Benchmarking
The goal of a performance investigation is to eventually improve performance.
In order for those improvements to be objective, we need a baseline:
How long does it take (on your system) to create a reaction? If you have that number,
you have a target for your improvements.
You can quantifying performance by using a benchmarking tool.
We use rspec-benchmark to benchmark the rspec test we set up earlier.
After installing the framework (bundle add rspec-benchmark) you can make it available as follows.
spec/spec_helper.rb
require 'rspec-benchmark'
RSpec.configure do |config|
config.include RSpec::Benchmark::Matchers
end
You're now ready to include rspec-benchmark syntax / DSL in you test (for details head over to the rspec-benchmark docs):
spec/api/reaction_api_performance_spec.rb
it 'creates reaction in under one second' do
expect { post '/api/v1/reactions', params: params, as: :json }.to perform_under(1000).ms.times.sample(100).times
end
We extended the test such that it's executed 100 times (in order to get statistically meaningful results), and we expect the creation of a reaction to be done in under one second. When running the test, we get the following report.
reaction API
creates reaction in under one second (FAILED - 1)
Failures:
1) reaction API creates reaction in under one second
Failure/Error: expect { post '/api/v1/reactions', params: params, as: :json }.to perform_under(1000).ms.warmup(1).times.sample(100).times
expected block to perform under 1 sec, but performed above 2.31 sec (± 452 ms)
We now have an impression of how long it takes on average to create a reaction on your system. You can use this baseline to start improving the performance.
Profiling
In order to improve performance, we now need to identify hot spots in the code that lend themselves for optimization.
Profiling can help finding these hot spots by breaking down how much time (or CPU cycles) a program spends in each of its components (e.g., methods).
We can use the stackprof gem to profile our rspec test.
After installing the gem with bundle add stackprof we need to configure it as follows.
spec/spec_helper.rb
require 'stackprof'
RSpec.configure do |config|
config.around do |example|
if example.metadata[:profile]
StackProf.run(mode: :wall, interval: 250000, raw: true, out: 'tmp/stackprof.dump') do
example.run
end
else
example.run
end
end
end
We're specifying that we want to sample the call stack every 250000 microseconds and that we want to write the profiling results to tmp/stackprof.dump.
Finally, we can mark our test for profiling by adding the :profile keyword.
spec/api/reaction_api_performance_spec.rb
it 'creates reaction in under one second', :profile do
expect { post '/api/v1/reactions', params: params, as: :json }.to perform_under(1000).ms.times.sample(100).times
end
After running the test, we can visualize the profiling results by having stackprof construct an interactive flamegraph that you can inspect in your browser.
bundle exec stackprof --d3-flamegraph tmp/stackprof.dump > tmp/stackprof-flamegraph.html
Have a look at the following resources for details on how to read flamegraphs:
stackprof can also break down how much time the tests spends on each line of a function call.
This can help zooming in on hot spots.
bundle exec stackprof tmp/stackprof-wall.dump --method ReactionHelpers#update_materials_for_reaction
The result looks as follows. For example, it looks like the call to .save! on line 163 might be a good candidate for further investigation.
ReactionHelpers#update_materials_for_reaction (/workspace/chemotion/app/api/chemotion/reaction_api.rb:48)
samples: 0 self (0.0%) / 568 total (54.9%)
callers:
1038 ( 182.7%) ReactionHelpers#update_materials_for_reaction
568 ( 100.0%) block (2 levels) in <class:ReactionAPI>
520 ( 91.5%) ActiveRecord::ConnectionAdapters::DatabaseStatements#transaction
callees (568 total):
1038 ( 182.7%) ReactionHelpers#update_materials_for_reaction
520 ( 91.5%) ActiveRecord::Transactions::ClassMethods#transaction
411 ( 72.4%) ActiveRecord::Suppressor#save!
59 ( 10.4%) ActiveRecord::Persistence::ClassMethods#create!
49 ( 8.6%) Sample#create_subsample
10 ( 1.8%) ActiveRecord::Associations::CollectionProxy#<<
10 ( 1.8%) ContainerHelpers#update_datamodel
9 ( 1.6%) Sample::GeneratedAssociationMethods#container=
7 ( 1.2%) ActiveRecord::Persistence#update!
3 ( 0.5%) ActiveRecord::Core::ClassMethods#find_by
3 ( 0.5%) ActiveRecord::Core::ClassMethods#find
2 ( 0.4%) ActiveRecord::Inheritance::ClassMethods#new
1 ( 0.2%) Sample::GeneratedAssociationMethods#collections
1 ( 0.2%) ActiveRecord::Relation#destroy_all
1 ( 0.2%) ActiveRecord::Delegation#[]
1 ( 0.2%) ActiveRecord::Aggregations#reload
1 ( 0.2%) Segmentable#save_segments
code:
| 48 | def update_materials_for_reaction(reaction, material_attributes, current_user)
| 49 | collections = reaction.collections
| 50 | materials = OpenStruct.new(material_attributes)
| 51 | materials = {
| 52 | starting_material: Array(material_attributes['starting_materials']).map { |m| OSample.new(m) },
| 53 | reactant: Array(material_attributes['reactants']).map { |m| OSample.new(m) },
| 54 | solvent: Array(material_attributes['solvents']).map { |m| OSample.new(m) },
| 55 | purification_solvent: Array(material_attributes['purification_solvents']).map { |m| OSample.new(m) },
| 56 | product: Array(material_attributes['products']).map { |m| OSample.new(m) }
| 57 | }
520 (50.3%) | 58 | ActiveRecord::Base.transaction do
| 59 | included_sample_ids = []
519 (50.2%) | 60 | materials.each do |material_group, samples|
| 61 | fixed_label = material_group =~ /solvents?|reactants?/ && $&
| 62 | reactions_sample_klass = "Reactions#{material_group.to_s.camelize}Sample"
519 (50.2%) | 63 | samples.each_with_index do |sample, idx|
| 64 | sample.position = idx if sample.position.nil?
| 65 | sample.reference = false if material_group === 'solvent' && sample.reference == true
| 66 | # create new subsample
| 67 | if sample.is_new
| 68 | if sample.parent_id && material_group != 'products'
1 (0.1%) | 69 | parent_sample = Sample.find(sample.parent_id)
| 70 |
| 71 | # TODO: extract subsample method
49 (4.7%) | 72 | subsample = parent_sample.create_subsample(current_user, collections, true)
| 73 |
| 74 | # Use 'reactant' or 'solvent' as short_label
| 75 | subsample.short_label = fixed_label if fixed_label
| 76 |
| 77 | subsample.target_amount_value = sample.target_amount_value
| 78 | subsample.target_amount_unit = sample.target_amount_unit
| 79 | subsample.real_amount_value = sample.real_amount_value
| 80 | subsample.real_amount_unit = sample.real_amount_unit
| 81 | subsample.metrics = sample.metrics
| 82 |
| 83 | # add new data container
| 84 | # subsample.container = create_root_container
3 (0.3%) | 85 | subsample.container = update_datamodel(sample.container) if sample.container
18 (1.7%) | 86 | subsample.save!
1 (0.1%) | 87 | subsample.reload
1 (0.1%) | 88 | subsample.save_segments(segments: parent_sample.segments, current_user_id: current_user.id)
| 89 |
| 90 | included_sample_ids << subsample.id
| 91 | s_id = subsample.id
| 92 | # create new sample
| 93 | else
| 94 | attributes = sample.to_h.except(
| 95 | :id, :is_new, :is_split, :reference, :equivalent, :position,
| 96 | :type, :molecule, :collection_id, :short_label, :waste, :show_label, :coefficient, :user_labels,
| 97 | :boiling_point_lowerbound, :boiling_point_upperbound,
| 98 | :melting_point_lowerbound, :melting_point_upperbound, :segments
| 99 | ).merge(created_by: current_user.id,
| 100 | boiling_point: rangebound(sample.boiling_point_lowerbound, sample.boiling_point_upperbound),
| 101 | melting_point: rangebound(sample.melting_point_lowerbound, sample.melting_point_upperbound))
| 102 |
| 103 | # update attributes[:name] for a copied reaction
| 104 | if (reaction.name || '').include?('Copy') && attributes[:name].present?
| 105 | named_by_reaction = "#{reaction.short_label}"
| 106 | named_by_reaction += "-#{attributes[:name].split('-').last}"
| 107 | attributes.merge!(name: named_by_reaction)
| 108 | end
| 109 |
| 110 | container_info = attributes[:container]
| 111 | attributes.delete(:container)
| 112 | attributes.delete(:segments)
2 (0.2%) | 113 | new_sample = Sample.new(
| 114 | attributes
| 115 | )
| 116 |
| 117 | # Use 'reactant' or 'solvent' as short_label
| 118 | new_sample.short_label = fixed_label if fixed_label
| 119 |
| 120 | # add new data container
6 (0.6%) | 121 | new_sample.container = update_datamodel(container_info)
| 122 |
11 (1.1%) | 123 | new_sample.collections << collections
106 (10.3%) | 124 | new_sample.save!
| 125 | new_sample.save_segments(segments: sample.segments, current_user_id: current_user.id)
| 126 | included_sample_ids << new_sample.id
| 127 | s_id = new_sample.id
| 128 | end
58 (5.6%) | 129 | ReactionsSample.create!(
| 130 | sample_id: s_id,
| 131 | reaction_id: reaction.id,
| 132 | equivalent: sample.equivalent,
| 133 | reference: sample.reference,
| 134 | show_label: sample.show_label,
| 135 | waste: sample.waste,
| 136 | coefficient: sample.coefficient,
| 137 | position: sample.position,
| 138 | type: reactions_sample_klass
| 139 | ) if s_id
| 140 | s_id = nil
| 141 | # update the existing sample
| 142 | else
2 (0.2%) | 143 | existing_sample = Sample.find(sample.id)
| 144 |
| 145 | existing_sample.target_amount_value = sample.target_amount_value
| 146 | existing_sample.target_amount_unit = sample.target_amount_unit
| 147 | existing_sample.real_amount_value = sample.real_amount_value
| 148 | existing_sample.real_amount_unit = sample.real_amount_unit
| 149 | existing_sample.metrics = sample.metrics
| 150 | existing_sample.external_label = sample.external_label if sample.external_label
| 151 | existing_sample.short_label = sample.short_label if sample.short_label
| 152 | existing_sample.short_label = fixed_label if fixed_label
| 153 | existing_sample.name = sample.name if sample.name
| 154 |
1 (0.1%) | 155 | if r = existing_sample.residues[0]
| 156 | r.assign_attributes sample.residues_attributes[0]
| 157 | end
| 158 |
| 159 | if sample.container
10 (1.0%) | 160 | existing_sample.container = update_datamodel(sample.container)
| 161 | end
| 162 |
239 (23.1%) | 163 | existing_sample.save!
| 164 | existing_sample.save_segments(segments: sample.segments, current_user_id: current_user.id) if sample.segments
| 165 |
| 166 | included_sample_ids << existing_sample.id
| 167 |
3 (0.3%) | 168 | existing_association = ReactionsSample.find_by(sample_id: sample.id)
| 169 |
| 170 | # update existing associations
| 171 | if existing_association
7 (0.7%) | 172 | existing_association.update_attributes!(
| 173 | reaction_id: reaction.id,
| 174 | equivalent: sample.equivalent,
| 175 | reference: sample.reference,
| 176 | show_label: sample.show_label,
| 177 | waste: sample.waste,
| 178 | coefficient: sample.coefficient,
| 179 | position: sample.position,
| 180 | type: reactions_sample_klass
| 181 | )
| 182 | # sample was moved to other materialgroup
| 183 | else
| 184 | # create a new association
1 (0.1%) | 185 | ReactionsSample.create!(
| 186 | sample_id: sample.id,
| 187 | reaction_id: reaction.id,
| 188 | equivalent: sample.equivalent,
| 189 | reference: sample.reference,
| 190 | show_label: sample.show_label,
| 191 | waste: sample.waste,
| 192 | coefficient: sample.coefficient,
| 193 | position: sample.position,
| 194 | type: reactions_sample_klass
| 195 | )
| 196 | end
| 197 | end
| 198 | end
| 199 | end
| 200 |
| 201 | # delete all samples not anymore in one of the groups
| 202 |
| 203 | current_sample_ids = reaction.reactions_samples.pluck(:sample_id)
| 204 | deleted_sample_ids = current_sample_ids - included_sample_ids
1 (0.1%) | 205 | Sample.where(id: deleted_sample_ids).destroy_all
| 206 |
| 207 | # for testing
| 208 | # raise ActiveRecord::Rollback
| 209 | end
| 210 |
| 211 | # to update the SVG
| 212 | reaction.reload
48 (4.6%) | 213 | reaction.save!
| 214 | end