Optimizing Linux® Performance [Electronic resources] : A Hands-On Guide to Linux® Performance Tools نسخه متنی

10.7. Analyze the Results

Now that we have used oprofile to collect information about where time is spent when the filter is running, we have to analyze the results to look for ways to change its execution and increase performance.

First, we use oprofile to look at how the entire system was spending time. This is shown in Listing 10.6.

Listing 10.6.

[root@localhost ezolt]# opreport -f | less
CPU: CPU with timer interrupt, speed 0 MHz (estimated)
Profiling through timer interrupt
TIMER:0|
samples|      %|
------------------
69896 36.9285 /usr/local/lib/libgimp-2.0.so.0.0.3
44237 23.3719 /usr/local/lib/libgimpcolor-2.0.so.0.0.3
28386 14.9973 /usr/local/lib/gimp/2.0/plug-ins/lic
16133  8.5236 /usr/lib/libglib-2.0.so.0.400.0
....

As Listing 10.6 shows, 75 percent of the CPU time was spent in the lic process or GIMP-related libraries. Most likely, these libraries are called by the lic process, a fact that we can confirm by combining the information that ltrace gives us with the information from oprofile. Listing 10.7 shows the library calls made for a small portion of the run of the filter.

Listing 10.7.

[ezolt@localhost ktracer]$ ltrace -p 32744 -c
% time     seconds  usecs/call     calls      function
------ ----------- ----------- --------- --------------------
46.13  101.947798         272    374307 rint
15.72   34.745099         278    124862 g_rand_double_range
14.77   32.645236         261    124862 gimp_pixel_rgn_get_pixel
13.01   28.743856         230    124862 gimp_rgba_set_uchar
10.36   22.905472         183    124862 gimp_rgb_to_hsl
0.00    0.006832        6832         1 gtk_widget_destroy
0.00    0.003976        3976         1 gimp_progress_init
0.00    0.003631        3631         1 g_rand_new
0.00    0.001992        1992         1 gimp_drawable_get
0.00    0.001802        1802         1 gimp_drawable_mask_bounds
0.00    0.000184         184         1 g_malloc
0.00    0.000118         118         1 gettext
0.00    0.000100         100         1 gimp_pixel_rgn_init
------ ----------- ----------- --------- --------------------
100.00  221.006096                873763 total

Next, we investigate the information that oprofile gives us about where CPU time is being spent in each of the libraries, and see whether the hot functions in the libraries are the same as those that the filter calls. For each of the three top CPU-using images, we ask opreport to give us more details about which functions in the library are spending all the time. The results are shown in Listing 10.8 for the libgimp, libgimp-color libraries, and the lic process.

Listing 10.8.

[/tmp]# opreport -lf /usr/local/lib/libgimp-2.0.so.0.0.3
CPU: CPU with timer interrupt, speed 0 MHz (estimated)
Profiling through timer interrupt
samples  %         symbol name
27136    38.8234   gimp pixel_rgn_get_pixel
14381    20.5749   gimp drawable_get_tile2
6571      9.4011   gimp tile_unref
6384      9.1336   gimp drawable_get_tile
3921      5.6098   gimp tile_cache_insert
3322      4.7528   gimp tile_ref
3057      4.3736   anonymous symbol from section .plt
2732      3.9087   gimp tile_width
1998      2.8585   gimp tile_height
...
[/tmp]# opreport -lf /usr/local/lib/libgimpcolor-2.0.so.0.0.3
CPU: CPU with timer interrupt, speed 0 MHz (estimated)
Profiling through timer interrupt
samples  %         symbol name
31475    71.1508   gimp rgba_set_uchar
6251     14.1307   gimp bilinear_rgb
2941      6.6483   gimp rgb_multiply
2394      5.4118   gimp rgb_add
466       1.0534   gimp rgba_get_uchar
323       0.7302   gimp rgb_to_hsl
....
[/tmp]# opreport -lf /usr/local/lib/gimp/2.0/plug-ins/lic
CPU: CPU with timer interrupt, speed 0 MHz (estimated)
Profiling through timer interrupt
samples  %         symbol name
11585    40.8124   getpixel
5185     18.2660   lic_image
4759     16.7653   peek
3287     11.5797   filter
1698      5.9818   peekmap
1066      3.7554   anonymous symbol from section .plt
316       1.1132   compute_lic
232       0.8173   rgb_to_hsl
111       0.3910   grady
106       0.3734   gradx
41        0.1444   poke
....

As you can see by comparing the output of ltrace in Listing 10.8, and the oprofile output in Listing 10.9, the lic filter is repeatedly calling the library functions that are spending all the time.

Next, we investigate the source code of the lic filter to determine how it is structured, what exactly its hot functions are doing, and how the filter calls the GIMP library functions. The lic function that generated the most samples is the getpixel function, shown by the opannotate output in Listing 10.9. opannotate shows the number of samples, followed by the total percentage of samples in a column to the left of the source. This enables you to look through the source and see which exact source lines are hot.

Listing 10.9.

opannotate --source /usr/local/lib/gimp/2.0/plug-ins/lic
....
:static void
:getpixel (GimpPixelRgn *src_rgn,
:          GimpRGB      *p,
:          gdouble       u,
:          gdouble       v)
428 1.5961  :{ /* getpixel total: 11198 41.7587 */
:  register gint x1, y1, x2, y2;
:  gint width, height;
:  static GimpRGB pp[4];
:
98 0.3655  :  width = src_rgn->w;
72 0.2685  :  height = src_rgn->h;
:
1148 4.2810  :  x1 = (gint)u;
1298 4.8404  :  y1 = (gint)v;
:
603 2.2487  :  if (x1 < 0)
1 0.0037  :    x1 = width - (-x1 % width);
:  else
1605 5.9852  :    x1 = x1 % width;
:
87 0.3244  :  if (y1 < 0)
:    y1 = height - (-y1 % height);
:  else
1264 4.7136  :    y1 = y1 % height;
:
1358 5.0641  :  x2 = (x1 + 1) % width;
1379 5.1425  :  y2 = (y1 + 1) % height;
:
320 1.1933  :  peek (src_rgn, x1, y1, &pp[0]);
267 0.9957  :  peek (src_rgn, x2, y1, &pp[1]);
285 1.0628  :  peek (src_rgn, x1, y2, &pp[2]);
244 0.9099  :  peek (src_rgn, x2, y2, &pp[3]);
:
706 2.6328  :  *p = gimp_bilinear_rgb (u, v, pp);
35 0.1305  :}
...

There are a few interesting things to note about the get_pixel function. First, it calls the gimp_bilinear_rgb function, which is one of the hot functions in the GIMP libraries. Second, it calls the peek function four times. If the get_pixel call is executed many times, the peek function is executed four times as much. Using opannotate to look at the peek function (shown in Listing 10.10), we can see that it calls gimp_pixel_rgn_get_pixel and gimp_rgba_set_uchar, which are top functions for libgimp and libgimp-color respectively.

Listing 10.10.

:static void
:peek (GimpPixelRgn *src_rgn,
:      gint          x,
:      gint          y,
:      GimpRGB      *color)
481  1.7937  :{ /* peek total:   4485 16.7251 */
:  static guchar data[4] = { 0, };
:
1373  5.1201  :  gimp_pixel_rgn_get_pixel (src_rgn, data, x, y);
2458  9.1662  :  gimp_rgba_set_uchar (color, data[0], data[1], data[2],
data[3]);
173  0.6451  :}

Although it is not quite clear exactly what the filter is doing or what the library calls are used for, there are a few curious points. First, peek sounds like a function that would retrieve pixels from the image so that the filter can process them. We can check this hunch shortly. Second, most of the time spent in the filter does not appear to be spent running a mathematical algorithm on the image data. Instead of spending all the CPU time running calculations based on the values of the pixels, this filter appears to spend most of the time retrieving pixels to be manipulated. If this is really the case, perhaps it can be fixed.