Arvados

h1. Performance profiling

h2. Workbench

Workbench makes repeated calls for the same object(s) from the API server. Also, workbench sometimes makes multiple calls to the API server. For ex: get a link, one at a time rather than pulling all links needed by the object in one request from API server. This was observed several times in the past. And, we have used “preload-*” in those instances when we noticed this.

As recently as of fixing #5622, it was observed that each link was being retrieved in a separate call. Similar behavior is observed in #5908. 

Given this, it is clear that we have this symptom in several areas in workbench. It is likely that we have other such problem patterns in our implementation.

Thus, it makes sense to do performance profiling of workbench to identify potential areas of improvement in workbench. This can also help identify API methods that can be tweaked to improve API server performance.

h3. Proposed solutions

h4. Profile using ruby-prof

In development environment, use rack-mini-profiler to profile workbench pages. https://github.com/MiniProfiler/rack-mini-profiler

* Set the environment variable:   ENABLE_PROFILING=yes

* Visit a workbench page

** After the page loads, you will see a clickable button at the top left corner (with the number of ms taken by the page)

** Click on this button to see the profile breakdown of several assets in displaying this page

** Append ?pp=help to see available options

** Append ?pp=flamegraph to see a graphical representation of the profile (though I did not find this to be of much help in our workbench)

h2. Benchmarking code snippets

We can use benchmarking to measure the performance of individual code blocks. This might come handy when trying to understand performance issues with specific areas. 

http://stackoverflow.com/questions/11887145/fastest-way-to-check-if-a-string-matches-or-not-a-regexp-in-ruby

I recently used this to benchmark *line.scan /\S+/* which was used in Ruby SDK versus *line.split*

<pre>

irb(main):001:0> require 'benchmark'

=> true

irb(main):002:0> Benchmark.bm do |x|

irb(main):003:1*     s = 'aaa bbb ccc ddd eee'

irb(main):004:1>     x.report { 500000.times { a = s.split } }

irb(main):005:1>     x.report { 500000.times { a = s.scan /\S+/ } }

irb(main):006:1> end

       user     system      total        real

   0.660000   0.010000   0.670000 (  0.682025)

   2.500000   0.010000   2.510000 (  2.551410)

=> [#<Benchmark::Tms:0x007fa3620e66d8 @label="", @real=0.682025, @cstime=0.0, @cutime=0.0, 

@stime=0.010000000000000002, @utime=0.66, @total=0.67>, #<Benchmark::Tms:0x007fa361111078 

@label="", @real=2.55141, @cstime=0.0, @cutime=0.0, @stime=0.009999999999999995, @utime=2.5, 

@total=2.51>]

</pre>

Another example to compare *=~* with *regexp.match* performance:

<pre>

irb(main):001:0> require 'benchmark'

=> true

irb(main):002:0> Benchmark.bm do |x|

irb(main):003:1* FILE_REGEXP = /^[[:digit:]]+:[[:digit:]]+:/

irb(main):004:1>   s = '0:10:abc.txt'

irb(main):005:1>   x.report { 1000000.times { s =~ FILE_REGEXP } }

irb(main):006:1>   x.report { 1000000.times { FILE_REGEXP.match s } }

irb(main):007:1> end

       user     system      total        real

   0.440000   0.000000   0.440000 (  0.445523)

   1.150000   0.010000   1.160000 (  1.162303)

=> [#<Benchmark::Tms:0x007feeb40b6850 @label="", @real=0.445523, @cstime=0.0, @cutime=0.0, @stime=0.0, @utime=0.44, 

@total=0.44>, #<Benchmark::Tms:0x007feeb40a7440 @label="", @real=1.162303, @cstime=0.0, @cutime=0.0, @stime=0.01, 

@utime=1.15, @total=1.16>]

</pre>