Dear GAP-Forum,
Craig Struble asked:
Hello, I have a small question regarding the output of DisplayProfile() in
GAP4.1. I got the following output during one of my profiling sessions248141* 289400 -16740 ELM_LIST: For a compressed VecFFE
Profiling prints three columns: The number of times a function gets called,
the time spent by itself and the time spent by its children processes.
What does the * mean,
If either of the numbers take more digits than permitted (the default is 7
which is hardcoded in `profile.g') only the first 6 digits are printed,
followed by a `*'.
and why is the chld/ms column negative? Does having
negative numbers in the profile affect the validity of the profile
results?
Internally, however two other times are measured, the total time spent and
the time spent on itself, the ``child'' column is obtained by
subtraction (this way it is easier to measure, but the display is better to
read), the lines are sorted according to the total time spent.
For pure kernel methods (like ELM_LIST for compressed VecFFE) the ``self'' time
does not make much sense, as no library subroutines are called. I'm not sure
eactly, why the `self' value is bigger than `total' (which is the reason for
the negative difference), I suspect that because of the enormous number of
times the operation gets called a small difference between leaving the
method selection and entering the kernel method sums up.
So what should you do with this line:
Disregard the negative `child' time. It should be 0. (This is only about 7
or 8% of the total time for this particular operation and times when garbage
collections happen will have a much larger impact.)
As GAP measures the total times internally anyhow, the summed `total' is
calculated on this and any negative numbers don't have an effect there.
However I suspect there might be a much bigger distortion (which will have
put the `ELM_LIST' line on the top of your profile) in the profile:
Profiling a function takes constant extra time, the proportional influx of
profiling thus gets the bigger, the faster the function runs. Functions like
list access in the kernel are extremely fast, what the profile is measuring
for these functions therefore is more the profiling time than the execution
time. The large total time then arises only, because the function is called
extremely often.
I hope this is of help,
Alexander Hulpke