Project

General

Profile

Performance profiling » History » Version 7

Radhika Chippada, 06/08/2015 01:53 PM

1 4 Radhika Chippada
h1. Performance profiling
2 1 Radhika Chippada
3
4 4 Radhika Chippada
h2. Workbench
5 1 Radhika Chippada
6
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.
7
8
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. 
9
10
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.
11
12
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.
13
14 5 Radhika Chippada
h3. Proposed solutions
15 1 Radhika Chippada
16 5 Radhika Chippada
h4. Profile using ruby-prof
17 1 Radhika Chippada
18 2 Radhika Chippada
In development environment, use rack-mini-profiler to profile workbench pages. https://github.com/MiniProfiler/rack-mini-profiler
19 1 Radhika Chippada
20 2 Radhika Chippada
* Set the environment variable:   ENABLE_PROFILING=yes
21
22
* Visit a workbench page
23
** After the page loads, you will see a clickable button at the top left corner (with the number of ms taken by the page)
24
** Click on this button to see the profile breakdown of several assets in displaying this page
25 1 Radhika Chippada
** Append ?pp=help to see available options
26
** 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)
27 4 Radhika Chippada
28 5 Radhika Chippada
h2. Benchmarking code snippets
29 4 Radhika Chippada
30
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. 
31
32
http://stackoverflow.com/questions/11887145/fastest-way-to-check-if-a-string-matches-or-not-a-regexp-in-ruby
33
34
I recently used this to benchmark *line.scan /\S+/* which was used in Ruby SDK versus *line.split*
35
36
<pre>
37
irb(main):001:0> require 'benchmark'
38
=> true
39
irb(main):002:0> Benchmark.bm do |x|
40
irb(main):003:1*     s = 'aaa bbb ccc ddd eee'
41
irb(main):004:1>     x.report { 500000.times { a = s.split } }
42
irb(main):005:1>     x.report { 500000.times { a = s.scan /\S+/ } }
43
irb(main):006:1> end
44
       user     system      total        real
45
   0.660000   0.010000   0.670000 (  0.682025)
46
   2.500000   0.010000   2.510000 (  2.551410)
47
=> [#<Benchmark::Tms:0x007fa3620e66d8 @label="", @real=0.682025, @cstime=0.0, @cutime=0.0, 
48
@stime=0.010000000000000002, @utime=0.66, @total=0.67>, #<Benchmark::Tms:0x007fa361111078 
49
@label="", @real=2.55141, @cstime=0.0, @cutime=0.0, @stime=0.009999999999999995, @utime=2.5, 
50
@total=2.51>]
51
</pre>
52 6 Radhika Chippada
53
54
55 7 Radhika Chippada
Another example to compare *=~* with *regexp.match* performance:
56 6 Radhika Chippada
<pre>
57
irb(main):001:0> require 'benchmark'
58
=> true
59
irb(main):002:0> Benchmark.bm do |x|
60
irb(main):003:1* FILE_REGEXP = /^[[:digit:]]+:[[:digit:]]+:/
61
irb(main):004:1>   s = '0:10:abc.txt'
62
irb(main):005:1>   x.report { 1000000.times { s =~ FILE_REGEXP } }
63
irb(main):006:1>   x.report { 1000000.times { FILE_REGEXP.match s } }
64
irb(main):007:1> end
65
       user     system      total        real
66
   0.440000   0.000000   0.440000 (  0.445523)
67
   1.150000   0.010000   1.160000 (  1.162303)
68
=> [#<Benchmark::Tms:0x007feeb40b6850 @label="", @real=0.445523, @cstime=0.0, @cutime=0.0, @stime=0.0, @utime=0.44, 
69
@total=0.44>, #<Benchmark::Tms:0x007feeb40a7440 @label="", @real=1.162303, @cstime=0.0, @cutime=0.0, @stime=0.01, 
70
@utime=1.15, @total=1.16>]
71
</pre>