before first PROFILE line

Thu, 8 Jul 1999 22:39:22 -0700 (PDT)

> I have just done a careful (by hand) investigation of the profiling result on
> ratio regions, which reported a lot of time in `before first PROFILE line' of
> Chunks.   I  deduce  that  the output of mlprof is completely correct, and we
> really are spending that time there.
> reads), each of 32 bits.  Definitely not too bad.

I am willing to buy that there is time spent in these "before PROFILE"
areas, although I don't understand why the previous version of mlprof
didn't report it.  In any case, I have several conclusions.

* We are getting killed by trampolining, the sum of the "magic"
  percentages and the "before" percentages is quite high for some
  programs.  Add in the "gc" initialization costs, and C is really
  killing us.

* The default output of mlprof should be to combine all of the
  "magic", "before", and "gc" entries into a single entry, called, say,
  "C overhead cost".  You can add a switch if you like to print the 
  stuff separated out.

> My summary: mlprof is working perfectly.

I don't completely agree, given the error message that I get when
running mlprof on the results of the profiled compiler compiling
itself.

% ../bin/mlprof mlton.c ../lib/mlton gmon.out >/tmp/self-compile.prof
line number 40676 doesn't fit in [33001, 40674] mod 2^16

Furthermore, I would like to remind you of the results that I got when 
I added my little fix to mlprof so that it wouldn't abort with the
error (results follow).  If these are true, they imply that *almost
all* of the time spent in the self compile is spent in this C overhead 
stuff.  I find this hard to believe.  Were you able to duplicate my
numbers for a profiled self compile?

30008 ticks total
GC_init (C function)                    16.67%
before first PROFILE line of Chunk3820   9.21%
before first PROFILE line of Chunk3584   5.11%
before first PROFILE line of Chunk3787   4.64%
roundPage (C function)                   4.59%
before first PROFILE line of Chunk1244   4.21%
before first PROFILE line of Chunk3791   2.92%
before first PROFILE line of Chunk3826   2.92%
before first PROFILE line of Chunk3790   2.45%
before first PROFILE line of Chunk3818   2.42%
before first PROFILE line of Chunk3825   2.33%
before first PROFILE line of Chunk3807   2.10%
before first PROFILE line of Chunk3643   1.87%
before first PROFILE line of Chunk3748   1.86%
before first PROFILE line of Chunk3824   1.80%
before first PROFILE line of Chunk3798   1.76%
before first PROFILE line of Chunk3827   1.75%
before first PROFILE line of Chunk3550   1.65%
before first PROFILE line of Chunk3750   1.62%
before first PROFILE line of main        1.53%
before first PROFILE line of Chunk3788   1.50%
before first PROFILE line of Chunk3811   1.30%
before first PROFILE line of Chunk3815   1.21%
before first PROFILE line of Chunk3786   1.20%
before first PROFILE line of Chunk3604   1.13%
before first PROFILE line of Chunk3833   1.08%
before first PROFILE line of Chunk3789   1.06%
before first PROFILE line of Chunk3822   1.06%
before first PROFILE line of Chunk3831   1.06%
before first PROFILE line of Chunk3821   1.03%
before first PROFILE line of Chunk3749   1.02%
before first PROFILE line of Chunk3747   0.95%
before first PROFILE line of Chunk3628   0.90%
before first PROFILE line of Chunk3810   0.70%
before first PROFILE line of Chunk3828   0.69%
before first PROFILE line of Chunk3639   0.66%
before first PROFILE line of Chunk3808   0.61%
before first PROFILE line of Chunk3800   0.58%
before first PROFILE line of Chunk3792   0.53%
before first PROFILE line of Chunk211    0.49%
before first PROFILE line of Chunk3752   0.46%
before first PROFILE line of Chunk3785   0.43%
before first PROFILE line of Chunk2970   0.39%
before first PROFILE line of Chunk3829   0.35%
before first PROFILE line of Chunk2991   0.34%
before first PROFILE line of Chunk3795   0.29%
before first PROFILE line of Chunk3631   0.28%
before first PROFILE line of Chunk3644   0.27%
before first PROFILE line of Chunk3751   0.24%
before first PROFILE line of Chunk3549   0.22%
before first PROFILE line of Chunk2992   0.21%
before first PROFILE line of Chunk3793   0.21%
before first PROFILE line of Chunk3591   0.20%
before first PROFILE line of Chunk3632   0.20%
before first PROFILE line of Chunk3636   0.18%
before first PROFILE line of Chunk3809   0.16%
before first PROFILE line of Chunk3819   0.15%
before first PROFILE line of Chunk3608   0.14%
before first PROFILE line of Chunk3682   0.13%
before first PROFILE line of Chunk3773   0.11%
before first PROFILE line of Chunk2835   0.10%
before first PROFILE line of Chunk3598   0.10%
before first PROFILE line of Chunk2972   0.10%
before first PROFILE line of Chunk2822   0.10%
before first PROFILE line of Chunk2900   0.09%
before first PROFILE line of Chunk3606   0.09%
before first PROFILE line of Chunk3528   0.08%
intRem (C function)                      0.08%
before first PROFILE line of Chunk1227   0.07%
before first PROFILE line of Chunk3511   0.07%
intQuot (C function)                     0.07%
setRoundingMode (C function)             0.07%
before first PROFILE line of Chunk2554   0.06%
before first PROFILE line of Chunk2040   0.05%
before first PROFILE line of Chunk2191   0.05%
before first PROFILE line of Chunk2993   0.05%
before first PROFILE line of Chunk3226   0.05%
getRoundingMode (C function)             0.05%
before first PROFILE line of Chunk3547   0.04%
before first PROFILE line of Chunk3496   0.04%
before first PROFILE line of Chunk892    0.04%
before first PROFILE line of Chunk2777   0.04%
round (C function)                       0.04%
stringEqual (C function)                 0.04%
before first PROFILE line of Chunk210    0.03%
before first PROFILE line of Chunk2776   0.03%
before first PROFILE line of Chunk3574   0.03%
before first PROFILE line of Chunk2039   0.02%
before first PROFILE line of Chunk2914   0.02%
before first PROFILE line of Chunk3322   0.02%
before first PROFILE line of Chunk3454   0.02%
before first PROFILE line of Chunk259    0.02%
before first PROFILE line of Chunk2600   0.02%
before first PROFILE line of Chunk3225   0.02%
before first PROFILE line of Chunk3515   0.02%
before first PROFILE line of Chunk3527   0.02%
before first PROFILE line of Chunk3575   0.02%
before first PROFILE line of Chunk3645   0.02%
before first PROFILE line of Chunk56     0.02%
class (C function)                       0.02%
before first PROFILE line of Chunk2510   0.02%
before first PROFILE line of Chunk1297   0.01%
before first PROFILE line of Chunk1308   0.01%
before first PROFILE line of Chunk1385   0.01%
before first PROFILE line of Chunk1402   0.01%
before first PROFILE line of Chunk2740   0.01%
before first PROFILE line of Chunk2980   0.01%
before first PROFILE line of Chunk3334   0.01%
before first PROFILE line of Chunk3335   0.01%
before first PROFILE line of Chunk3551   0.01%
before first PROFILE line of Chunk3566   0.01%
before first PROFILE line of Chunk3626   0.01%
before first PROFILE line of Chunk3646   0.01%
before first PROFILE line of Chunk3647   0.01%
before first PROFILE line of Chunk3799   0.01%
before first PROFILE line of Chunk3806   0.01%
before first PROFILE line of Chunk1301   0.01%
before first PROFILE line of Chunk1401   0.01%
before first PROFILE line of Chunk2214   0.01%
before first PROFILE line of Chunk2316   0.01%
before first PROFILE line of Chunk234    0.01%
before first PROFILE line of Chunk2500   0.01%
before first PROFILE line of Chunk267    0.01%
before first PROFILE line of Chunk3522   0.01%
before first PROFILE line of Chunk3524   0.01%
before first PROFILE line of Chunk3599   0.01%
before first PROFILE line of Chunk3637   0.01%
before first PROFILE line of Chunk3638   0.01%
before first PROFILE line of Chunk3681   0.01%
before first PROFILE line of Chunk3830   0.01%
before first PROFILE line of Chunk71     0.01%
before first PROFILE line of Chunk742    0.01%
translatePointer (C function)            0.01%
before first PROFILE line of Chunk1267   0.01%
before first PROFILE line of Chunk1268   0.01%
before first PROFILE line of Chunk1303   0.01%
before first PROFILE line of Chunk1407   0.01%
before first PROFILE line of Chunk1537   0.01%
before first PROFILE line of Chunk1613   0.01%
before first PROFILE line of Chunk1902   0.01%
before first PROFILE line of Chunk2038   0.01%
before first PROFILE line of Chunk2065   0.01%
before first PROFILE line of Chunk229    0.01%
before first PROFILE line of Chunk2307   0.01%
before first PROFILE line of Chunk2394   0.01%
before first PROFILE line of Chunk2402   0.01%
before first PROFILE line of Chunk2738   0.01%
before first PROFILE line of Chunk2969   0.01%
before first PROFILE line of Chunk2981   0.01%
before first PROFILE line of Chunk3324   0.01%
before first PROFILE line of Chunk3325   0.01%
before first PROFILE line of Chunk3328   0.01%
before first PROFILE line of Chunk3453   0.01%
before first PROFILE line of Chunk3495   0.01%
before first PROFILE line of Chunk3505   0.01%
before first PROFILE line of Chunk3508   0.01%
before first PROFILE line of Chunk3578   0.01%
before first PROFILE line of Chunk3579   0.01%
before first PROFILE line of Chunk3633   0.01%
before first PROFILE line of Chunk3701   0.01%
before first PROFILE line of Chunk3802   0.01%
before first PROFILE line of Chunk55     0.01%
before first PROFILE line of Chunk820    0.01%
before first PROFILE line of Chunk821    0.01%
before first PROFILE line of Chunk822    0.01%
before first PROFILE line of Chunk1212   0.00%
before first PROFILE line of Chunk1228   0.00%
before first PROFILE line of Chunk1248   0.00%
before first PROFILE line of Chunk1266   0.00%
before first PROFILE line of Chunk1269   0.00%
before first PROFILE line of Chunk1272   0.00%
before first PROFILE line of Chunk1307   0.00%
before first PROFILE line of Chunk1309   0.00%
before first PROFILE line of Chunk1310   0.00%
before first PROFILE line of Chunk1335   0.00%
before first PROFILE line of Chunk1376   0.00%
before first PROFILE line of Chunk1410   0.00%
before first PROFILE line of Chunk1496   0.00%
before first PROFILE line of Chunk1623   0.00%
before first PROFILE line of Chunk1650   0.00%
before first PROFILE line of Chunk1692   0.00%
before first PROFILE line of Chunk1711   0.00%
before first PROFILE line of Chunk184    0.00%
before first PROFILE line of Chunk1857   0.00%
before first PROFILE line of Chunk1893   0.00%
before first PROFILE line of Chunk1904   0.00%
before first PROFILE line of Chunk1909   0.00%
before first PROFILE line of Chunk1911   0.00%
before first PROFILE line of Chunk1924   0.00%
before first PROFILE line of Chunk1938   0.00%
before first PROFILE line of Chunk1939   0.00%
before first PROFILE line of Chunk1980   0.00%
before first PROFILE line of Chunk1985   0.00%
before first PROFILE line of Chunk1986   0.00%
before first PROFILE line of Chunk2090   0.00%
before first PROFILE line of Chunk2091   0.00%
before first PROFILE line of Chunk21     0.00%
before first PROFILE line of Chunk2106   0.00%
before first PROFILE line of Chunk2156   0.00%
before first PROFILE line of Chunk2208   0.00%
before first PROFILE line of Chunk2309   0.00%
before first PROFILE line of Chunk2315   0.00%
before first PROFILE line of Chunk2395   0.00%
before first PROFILE line of Chunk2483   0.00%
before first PROFILE line of Chunk2601   0.00%
before first PROFILE line of Chunk2744   0.00%
before first PROFILE line of Chunk31     0.00%
before first PROFILE line of Chunk3205   0.00%
before first PROFILE line of Chunk3206   0.00%
before first PROFILE line of Chunk3255   0.00%
before first PROFILE line of Chunk3273   0.00%
before first PROFILE line of Chunk3323   0.00%
before first PROFILE line of Chunk3344   0.00%
before first PROFILE line of Chunk3351   0.00%
before first PROFILE line of Chunk3354   0.00%
before first PROFILE line of Chunk3363   0.00%
before first PROFILE line of Chunk3369   0.00%
before first PROFILE line of Chunk3397   0.00%
before first PROFILE line of Chunk3398   0.00%
before first PROFILE line of Chunk34     0.00%
before first PROFILE line of Chunk3415   0.00%
before first PROFILE line of Chunk3426   0.00%
before first PROFILE line of Chunk3442   0.00%
before first PROFILE line of Chunk3443   0.00%
before first PROFILE line of Chunk3452   0.00%
before first PROFILE line of Chunk3500   0.00%
before first PROFILE line of Chunk3506   0.00%
before first PROFILE line of Chunk3509   0.00%
before first PROFILE line of Chunk3510   0.00%
before first PROFILE line of Chunk3571   0.00%
before first PROFILE line of Chunk3573   0.00%
before first PROFILE line of Chunk3581   0.00%
before first PROFILE line of Chunk3582   0.00%
before first PROFILE line of Chunk3583   0.00%
before first PROFILE line of Chunk3590   0.00%
before first PROFILE line of Chunk3593   0.00%
before first PROFILE line of Chunk3596   0.00%
before first PROFILE line of Chunk3602   0.00%
before first PROFILE line of Chunk3605   0.00%
before first PROFILE line of Chunk3609   0.00%
before first PROFILE line of Chunk3611   0.00%
before first PROFILE line of Chunk3627   0.00%
before first PROFILE line of Chunk3642   0.00%
before first PROFILE line of Chunk3774   0.00%
before first PROFILE line of Chunk3812   0.00%
before first PROFILE line of Chunk408    0.00%
before first PROFILE line of Chunk498    0.00%
before first PROFILE line of Chunk51     0.00%
before first PROFILE line of Chunk52     0.00%
before first PROFILE line of Chunk553    0.00%
before first PROFILE line of Chunk617    0.00%
before first PROFILE line of Chunk63     0.00%
before first PROFILE line of Chunk66     0.00%
before first PROFILE line of Chunk67     0.00%
before first PROFILE line of Chunk68     0.00%
before first PROFILE line of Chunk70     0.00%
before first PROFILE line of Chunk72     0.00%
before first PROFILE line of Chunk836    0.00%
before first PROFILE line of Chunk837    0.00%
before first PROFILE line of Chunk880    0.00%
before first PROFILE line of Chunk89     0.00%