[MLton] MacOS time profiling

[Matthew Fluet]

I was noticing very odd results with time profiling on 
a dual-core/dual-proc Intel MacPro machine:

fenrir:~/devel/mlton/temp/trunk fluet$ /usr/bin/time ./output1 
136.14 real       133.64 user         2.47 sys
fenrir:~/devel/mlton/temp/trunk fluet$ mlprof output1 mlmon.out
4.96 seconds of CPU time (0.00 seconds GC)
            function              cur
------------------------------- -----
StreamIOExtra.output1           35.9%
Primitive.Exn.wrapOverflow.fn   25.2%
Main.once.loop                  16.3%
Sequence.Slice.full              5.6%
UnsignedIntegralComparisons.ltu  5.2%
PosixIO.make.writeArr.fn         4.6%
Main.once                        3.4%
Primitive.Bool.not               2.4%
Sequence.updateMk                1.2%

Note that mlprof is only reporting 4.96 seconds of CPU time, while 
/usr/bin/time is reporting 136.11 seconds of CPU time.

I instrumented the profiling code to print out the current time (via 
gettimeofday) at each invocation of the SIG_PROF handler.  What's odd is 
that I see things like:

GC_handleSigProf (0x000074d3)
tv_sec = 1185827275  tv_usec = 487777
GC_handleSigProf (0x000071a4)
tv_sec = 1185827275  tv_usec = 497771
GC_handleSigProf (0x000074c0)
tv_sec = 1185827275  tv_usec = 507767
GC_handleSigProf (0x00007535)
tv_sec = 1185827275  tv_usec = 517772
GC_handleSigProf (0x000071a2)
tv_sec = 1185827285  tv_usec = 887788
GC_handleSigProf (0x0000719f)
tv_sec = 1185827285  tv_usec = 897771
GC_handleSigProf (0x000074d9)
tv_sec = 1185827285  tv_usec = 907771
GC_handleSigProf (0x0000727d)
tv_sec = 1185827285  tv_usec = 917771

The signal handler is triggered nicely at the requested 10000us interval 
for a while, but then we miss *10 seconds* worth of signals.  And this 
happens a number of times through the course of the execution.

The closest thing to an explaination that I could find was the following:

   library(timeout) does not work reliably when Mac OS X runs on a
   multi-CPU machine. In particular, timeouts tend to happen much later
   than they should. This is caused by an OS bug. One workaround is to
   disable all but one CPU using the "Processor" control in the "System
   Preferences" or the hwprefs command. These utilities are part of "CHUD"
   which can be installed as part of Apple XCode. The underlying bug is
   related to setitimer(ITIMER_VIRTUAL) and has been observed at least up
   to Mac OS X 10.4.8 (Darwin 8.8.1).

   http://www.sics.se/sicstus/docs/4.0.1/html/relnotes/Platform-specific-UNIX-notes.html

Indeed, the effect seems much less pronounced when I disable all but one 
CPU.

However, I could not find a more "official" statement of the bug. 
Searches on the Mac website just turn up the setitimer manual page.