performance problem - finalization

performance problem - finalization

[Pawel Kobylarz]

I have just finished a computation-intensive application
and I started to profile it. I was removing the main
sources of delay one after another until Finalization
became the main source of delay. Now I just don't know
what to do.

Here is a piece of the summary file generated by gprof:

                                  called/total       parents
index  %time    self descendents  called+self    name     index
                                  called/total       children

                                                     <spontaneous>
[1]     31.6  137.13        0.49
system__finalization_implementation__finalize_list [1]
                0.11        0.38  160504/160504
tool_path__sltoc__finalize$2 [59]
                0.00        0.00    2410/2410
design_expressed__sl_exidx__finalize$2 [193]
                0.00        0.00      42/42
tool_path__feature__sl_sdc__finalize$2 [221]
                0.00        0.00     253/253
tool_path__feature__sl_didx__finalize$2 [268]
                0.00        0.00      41/41
design_expressed__sl_locmap__finalize$2 [308]

The finalize_list function takes 31.6 % of total running time.
137s us used within finalize_list, and 0.49s is used in
its descentants. The descendants are finalize methods
of lists from the Booch Components package.
I thought that the time spent in finalization depends
on the amount of items to finalize. I managed to avoid
the creation of new lists in the most nested loop.
(previously I used there a function that returned
record with list, now I just reference directly
to the source of data. Access is faster, but source
code looks nasty).

And there is the result:


                                  called/total       parents
index  %time    self descendents  called+self    name     index
                                  called/total       children

                                                     <spontaneous>
[1]     33.1  138.68        0.00
system__finalization_implementation__finalize_list [1]
                0.00        0.00    2410/2410
design_expressed__sl_exidx__finalize$2 [183]
                0.00        0.00     253/253
tool_path__feature__sl_didx__finalize$2 [204]
                0.00        0.00      42/42
tool_path__feature__sl_sdc__finalize$2 [209]
                0.00        0.00      41/41
design_expressed__sl_locmap__finalize$2 [300]
                0.00        0.00      28/28
tool_path__sltoc__finalize$2 [307]

Big surprise! Though there is almost nothing to finalize, and no list is
finalized during
computations, the finalize_list takes roughly the same amount of time!
How is it possible?
I cannot track the reason, because the function is "spontaneous"
and (seemingly) does not have parent functions.
What may be important, the time is not spent on starting
on finishing the program, when the lists are created
and destroyed. The time is proportional to the computation
time, where no list is created or destroyed.

What is more, I can see even more problems when I look at the next
most time-consuming functions:

  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 33.1     138.68   138.68
system__finalization_implementation__finalize_list [1]
 14.2     197.98    59.29
system__finalization_implementation__adjust__reverse_adjust.5 [2]
 13.9     256.25    58.27
system__finalization_implementation__adjust$2 [3]
  7.5     287.68    31.43
system__task_specific_data__set_jmpbuf_address [4]
  5.6     311.27    23.59
system__tasking_soft_links__set_jmpbuf_address_nt [8]
  4.2     328.70    17.43
system__finalization_implementation__finalize [11]
  3.8     344.55    15.84
system__task_specific_data__get_jmpbuf_address [13]
  3.5     359.20    14.65
system__tasking_soft_links__get_current_excep_nt [14]
  2.8     370.88    11.69
system__tasking_soft_links__get_jmpbuf_address_nt [15]
  1.3     376.14     5.25    40120     0.13     0.43
planning__commit_operation [12]
  1.1     380.74     4.60
ada__strings__unbounded__adjust [16]
  1.0     384.82     4.08                             __gnat_malloc [17]

  0.0     419.00     0.00        1     0.00     0.00
tst__genetic___clean.5 [469]

The "spontaneous" functions take about 90% of total running time,
though they seem to me (at least finalization) unnecessary.

So I have some questions:
1. When is finalize and other "spontaneous" functions called?
2. Where are they called from?
3. What are the factors that influence time spent in the functions?
4. Why finalization time does not depend on the intensity of
finalizing objects?
5. Why all the "spontaneous" functions take so much time?
In general - how to reduce time spent in these functions?

Please, help.

Pawel Kobylarz