|
|
< Day Day Up > |
|
10.7. Analyze the ResultsNow 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. |
|
|
< Day Day Up > |
|