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.



Optimizing Linux Performance. A Hands-On Guide to Linux Performance Tools
Optimizing Linux Performance: A Hands-On Guide to Linux Performance Tools
ISBN: 0131486829
EAN: 2147483647
Year: 2004
Pages: 132

flylib.com © 2008-2017.
If you may any questions please contact us: flylib@qtcs.net