> < ^ From:

< ^ Subject:

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

> < [top]