158 | Chapter 6: Performance
Optimizing and Reprofiling
Now, we will examine the profile to find areas of our code that are slow. There are
two main columns we need to watch while scanning the profile:
%Self
This value represents the amount of time spent in this method only (excluding
time spent in its children), relative to total profiling time. If one method is doing
an inordinate amount of work, it will have a proportionally higher%Self value.
Calls
This column shows the number of calls made to this function during the profil-
ing period. All of the optimization in the world on one method will not help if
the method is being called too many times. Again, algorithmic optimizations are
always the place to start; then, individual bits of code can be tweaked if more
performance is needed.
A good place to start is the flat profile, as it is sorted by the%Selfcolumn, highest
first. (The graph profile is sorted by%Totalinstead.) The beginning of our flat pro-
file looks like this:
Thread ID: 2057980
Total: 12.69%self total self wait child calls name
9.93 2.06 1.26 0.00 0.80 2730 GeoRuby::SimpleFeatures::
HexEWKBParser#decode_hex
6.86 1.43 0.87 0.00 0.56 4430 Array#each_index
4.65 1.82 0.59 0.00 1.23 4230 Array#each-1
2.68 0.34 0.34 0.00 0.00 132130 Hash#[]=
2.68 0.34 0.34 0.00 0.00 156540 Fixnum#==
2.60 0.38 0.33 0.00 0.05 77550 String#gsubMost of these values are fairly reasonable (we are doing a lot of necessary data pro-
cessing in Ruby, and it is reasonable thatArray#each_indexwould be a significant
component of this). However, we are spending a lot of time in GeoRuby::
SimpleFeatures::HexEWKBParser#decode_hex. The%Selfvalue of9.93means that we are
spending nearly 10% of the total request time inside this method. We should investi-
gate this by looking for that method’s block in the graph profile (see Figure 6-3).
Figure 6-3. The decode_hex method dominates our request time