Kaffe profiling: Some data and a question

[Danny Hendler]

Hi,

I've conducted some profiling of Kaffe's garbage collection activity.
This was done using gprof on Sunos 4.1.4, profiling kaffe 1.0.b2.
In order for the total sum to be meaningfull, the time counted for
a gc function 'f' was computed as:

counted_time(f) = exec_time(f) + time_of all f descendants which are
                                      not gc functions

I currently have results for 3 applications:

a. A loop of 10^6 multiplications (no object manipulation
   at all, however initial gc activity is relatively significant)

b. A loop of 81*10^9 multiplications (no object manipulation
   at all, initial gc activity not significant)

c. An applications which allocates objects all the time
   (This is a loop of calling a function, which allocates 1000 String
    objects on the stack.)

Generally, it seems the GC can take between 0% - 40% (or even
more if a synthetic application such as c. is being ran longer)
of Kaffe's time (detailed results follow), so a "typical"
application (god knows what this is) will probably take
something like 20%-30%. Note that these synthetic applications
have unrealistically small lines of code, consequently translation
did not play any role.

Has anybody got profiling results regarding other aspects of Kaffe
activities, e.g. interpretation, translation (this should be done with
care, since most [all?] profilers cannot cope with code which is
generated on the fly), synchronization, egc.? Any data would be
welcome.

----------------------------------------------------------------------------------------

a. 10^6 multiplications loop
------------------------------------

Total time: 4.15 sec

Func                 time(sec)  time(%)
------                  -----------  ----------
gcHeapMalloc       0.2         4.8%
gcMalloc            0.2         4.8%
gcFree               0.03        0.7%
gcHeapFree         0.05        1.2%
gc_small_block     0.02        0.5%
gcMan              0.01        0.3%

(All other gc functions are negligible here)

Total: 0.501, ~12%



b. 81*10^6 multiplications loop
-----------------------------------------

Total time: 142.94 sec

Func                 time(sec)  time(%)
------                  -----------  ----------
gc_heap_malloc     0.06        < 0.4%
gcMalloc            0.04        < 0.3%

(All other gc functions are negligible here)

Total: 0.3 sec, less than 0.7%



c. Garbage Creator
------------------------

Total time: 19.22 sec

Func                 time(sec)  time(%)
------                  -----------  ----------
gcMan               1.98        10%
gcheapmalloc        0.48        2.5%
gc_heap_free        0.36        1.8%
WalkMemory        0.7         3.6%
WalkConserv        4.1         21%
WalkClass           0.11        0.5%
WalkNull            0.06        0.3%

(All other gc functions are negligible here)

Total: 7.79 sec, ~ 40%