Statistical profiler reports no data on Mac OS X x86-64

[Scott Bell]

When attempting to use the statistical profiler on SBCL 1.0.37 x86-64,
under Mac OS X 10.6.3, the use of the WITH-PROFILING macro does
not print any profiling results:

> (require 'sb-sprof)
> (sb-sprof:profile-call-counts "MY-PACKAGE")
> (sb-sprof:with-profiling (:max-samples 2000 :report :flat :loop nil)
            (my-function))
WARNING: No sampling progress; possibly a profiler bug.

Number of samples: 0
Sample interval: 0.01 seconds
Total sampling time: 0.0 seconds
Number of cycles: 0
Sampled threads:

           Self Total Cumul
  Nr Count % Count % Count % Calls Function
------------------------------------------------------------------------
------------------------------------------------------------------------
          0 0.0 elsewhere

System information:

$ uname -a
Darwin vier.local 10.3.0 Darwin Kernel Version 10.3.0: Fri Feb 26 11:58:09 PST 2010; root:xnu-1504.3.12~1/RELEASE_I386 i386

> *features*
(:SB-POSIX-HAS-GETGRNAM :HUNCHENTOOT
 :HUNCHENTOOT-SBCL-DEBUG-PRINT-VARIABLE-ALIST :CHUNGA :FLEXI-STREAMS :CL-FAD
 :URL-REWRITE :PARENSCRIPT :KMR-NORMAL-DSDC :KMR-NORMAL-CESD :SPLIT-SEQUENCE
 :KMR-MOP :HUNCHENTOOT-NO-SSL :CL-PPCRE :ASDF :SB-THREAD :ANSI-CL :COMMON-LISP
 :SBCL :SB-DOC :SB-TEST :SB-LDB :SB-PACKAGE-LOCKS :SB-UNICODE :SB-EVAL
 :SB-SOURCE-LOCATIONS :IEEE-FLOATING-POINT :X86-64 :INODE64 :UNIX :MACH-O :BSD
 :DARWIN :MACH-EXCEPTION-HANDLER :SB-LUTEX :UD2-BREAKPOINTS :GENCGC
 :STACK-GROWS-DOWNWARD-NOT-UPWARD :C-STACK-IS-CONTROL-STACK :LINKAGE-TABLE
 :COMPARE-AND-SWAP-VOPS :UNWIND-TO-FRAME-AND-CALL-VOP :RAW-INSTANCE-INIT-VOPS
 :STACK-ALLOCATABLE-CLOSURES :STACK-ALLOCATABLE-VECTORS
 :STACK-ALLOCATABLE-LISTS :STACK-ALLOCATABLE-FIXED-OBJECTS :ALIEN-CALLBACKS
 :CYCLE-COUNTER :COMPLEX-FLOAT-VOPS :FLOAT-EQL-VOPS :INLINE-CONSTANTS
 :OS-PROVIDES-DLOPEN :OS-PROVIDES-DLADDR :OS-PROVIDES-PUTWC
 :OS-PROVIDES-BLKSIZE-T :OS-PROVIDES-SUSECONDS-T)

[Nikodemus Siivola (nikodemus)]

Call counts are not currently reported unless samples have been gathered for the function (which seems suboptimal, yes), and unless MY-FUNCTION takes > 0.01 seconds of run-time, no samples will be gathered during its run.

Issues to fix:

1) Better WARNING comparing the time the profiling took and the sampling interval, noting if any samples could have been gathered in the first place -- and suggesting a longer profiling run if not.

2) Report call counts for functions for which no samples have been gathered.

[Scott Bell (sbvendor)]

Here is some more detailed output from another run, in which clearly
the profiled body is taking longer than the sample interval to execute,
but fewer samples are taken than expected:

> (sb-sprof:with-profiling (:max-samples 2000 :report :flat :loop nil)
            (time (restore-sheets)))

Evaluation took:
  22.683 seconds of real time
  26.197599 seconds of total run time (14.495562 user, 11.702037 system)
  [ Run times consist of 5.090 seconds GC time, and 21.108 seconds non-GC time. ]
  115.50% CPU
  45,252,381,684 processor cycles
  65 page faults
  1,163,395,360 bytes consed

Number of samples: 2
Sample interval: 0.01 seconds
Total sampling time: 0.02 seconds
Number of cycles: 0
Sampled threads:
 #<SB-THREAD:THREAD "repl-thread" RUNNING {1003594E71}>

           Self Total Cumul
  Nr Count % Count % Count % Calls Function
------------------------------------------------------------------------
   1 1 50.0 1 50.0 1 50.0 - "foreign function getattrlist"
   2 1 50.0 1 50.0 2 100.0 - (FLET #:CLEANUP-FUN-[FORM-FUN-[RELEASE-FD-STREAM-RESOURCES]1153]1161)
   3 0 0.0 2 100.0 2 100.0 1 RESTORE-SHEETS
   4 0 0.0 2 100.0 2 100.0 - SB-EXT:CALL-WITH-TIMING
   5 0 0.0 2 100.0 2 100.0 - "Unknown component: #x1004DFB230"
   6 0 0.0 2 100.0 2 100.0 - SB-INT:SIMPLE-EVAL-IN-LEXENV
   7 0 0.0 2 100.0 2 100.0 - SWANK::EVAL-REGION
   8 0 0.0 2 100.0 2 100.0 - "Unknown component: #x10054130D0"
   9 0 0.0 2 100.0 2 100.0 - SWANK::TRACK-PACKAGE
  10 0 0.0 2 100.0 2 100.0 - SWANK::CALL-WITH-RETRY-RESTART
  11 0 0.0 2 100.0 2 100.0 - SWANK::CALL-WITH-BUFFER-SYNTAX
  12 0 0.0 2 100.0 2 100.0 - SWANK::REPL-EVAL
  13 0 0.0 2 100.0 2 100.0 - SWANK::EVAL-FOR-EMACS
  14 0 0.0 2 100.0 2 100.0 - SWANK::PROCESS-REQUESTS
  15 0 0.0 2 100.0 2 100.0 - "Unknown component: #x10044F60E0"
  16 0 0.0 2 100.0 2 100.0 - SWANK-BACKEND::CALL-WITH-BREAK-HOOK
  17 0 0.0 2 100.0 2 100.0 - (FLET SWANK-BACKEND:CALL-WITH-DEBUGGER-HOOK)
  18 0 0.0 2 100.0 2 100.0 - SWANK::CALL-WITH-BINDINGS
  19 0 0.0 2 100.0 2 100.0 - SWANK::CALL-WITH-CONNECTION
  20 0 0.0 2 100.0 2 100.0 - SWANK::HANDLE-REQUESTS
  21 0 0.0 2 100.0 2 100.0 - (FLET #:WITHOUT-INTERRUPTS-BODY-[BLOCK391]396)
  22 0 0.0 2 100.0 2 100.0 - (FLET SB-THREAD::WITH-MUTEX-THUNK)
  23 0 0.0 2 100.0 2 100.0 - (FLET #:WITHOUT-INTERRUPTS-BODY-[CALL-WITH-MUTEX]293)
  24 0 0.0 2 100.0 2 100.0 - SB-THREAD::CALL-WITH-MUTEX
  25 0 0.0 2 100.0 2 100.0 - SB-THREAD::INITIAL-THREAD-FUNCTION
  26 0 0.0 2 100.0 2 100.0 - "foreign function call_into_lisp"
  27 0 ...

[Nikodemus Siivola (nikodemus)]

> 115.50% CPU

Seems to indicate that the body is running multiple threads. Is this correct?

From the docstring of WITH-PROFILING:

       :MODE <mode>
         If :CPU, run the profiler in CPU profiling mode. If :ALLOC, run the
         profiler in allocation profiling mode. If :TIME, run the profiler
         in wallclock profiling mode.

       :THREADS <list-form>
         Form that evaluates to the list threads to profile, or :ALL to indicate
         that all threads should be profiled. Defaults to the current
         thread. (Note: START-PROFILING defaults to all threads.)

         :THREADS has no effect on call-counting at the moment.

         On some platforms (eg. Darwin) the signals used by the profiler are
         not properly delivered to threads in proportion to their CPU usage
         when doing :CPU profiling. If you see empty call graphs, or are obviously
         missing several samples from certain threads, you may be falling afoul
         of this.

You may want to try

  (with-profiling (:threads :all ...) ...)

and

  (with-profiling (:threads :all :mode :time ...) ...)

[Scott Bell (sbvendor)]

> (sb-sprof:with-profiling (:max-samples 2000 :report :flat :loop nil :threads :all)
            (time (restore-sheets)))

Evaluation took:
  17.414 seconds of real time
  16.451764 seconds of total run time (10.236564 user, 6.215200 system)
  [ Run times consist of 3.401 seconds GC time, and 13.051 seconds non-GC time. ]
  94.48% CPU
  34,721,707,692 processor cycles
  862,107,856 bytes consed

WARNING: No sampling progress; possibly a profiler bug.

Number of samples: 0
Sample interval: 0.01 seconds
Total sampling time: 0.0 seconds
Number of cycles: 0
Sampled threads:

           Self Total Cumul
  Nr Count % Count % Count % Calls Function
------------------------------------------------------------------------
------------------------------------------------------------------------
          0 0.0 elsewhere
#<SB-SPROF::CALL-GRAPH 0 samples {1013021521}>

> (sb-sprof:with-profiling (:max-samples 2000 :report :flat :loop nil :threads :all :mode :time)
            (time (restore-sheets)))
Evaluation took:
  16.989 seconds of real time
  17.905075 seconds of total run time (11.102379 user, 6.802696 system)
  [ Run times consist of 4.862 seconds GC time, and 13.044 seconds non-GC time. ]
  105.39% CPU
  33,875,825,628 processor cycles
  904,438,400 bytes consed

WARNING: No sampling progress; possibly a profiler bug.

Number of samples: 0
Sample interval: 0.01 seconds
Total sampling time: 0.0 seconds
Number of cycles: 0
Sampled threads:

           Self Total Cumul
  Nr Count % Count % Count % Calls Function
------------------------------------------------------------------------
------------------------------------------------------------------------
          0 0.0 elsewhere
#<SB-SPROF::CALL-GRAPH 0 samples {1008772C71}>

The body being executed isn't multi-threaded itself, but this interaction
is from within SLIME, so that might be the source. I'll try these outside
of SLIME.

[Douglas Katzman (dougk)]

sprof may have been broken on macOS but it certainly isn't now. So technically this bug is probably obsolete but since that's not a possible status, "incomplete" will do since we don't know the circumstances surrounding the original problem report.