Comment 2 for bug 554156

Revision history for this message
Scott Bell (sbvendor) wrote :

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 0.0 2 100.0 2 100.0 - "foreign function new_thread_trampoline"
  28 0 0.0 2 100.0 2 100.0 - "foreign function _pthread_start"
  29 0 0.0 2 100.0 2 100.0 - "foreign function thread_start"
  30 0 0.0 1 50.0 2 100.0 - "foreign function sb_realpath"
  31 0 0.0 1 50.0 2 100.0 - SB-UNIX:UNIX-REALPATH
  32 0 0.0 1 50.0 2 100.0 - SB-IMPL::MAP-DIRECTORY
  33 0 0.0 1 50.0 2 100.0 - (LAMBDA (PATHNAME))
  34 0 0.0 1 50.0 2 100.0 - (FLET SB-IMPL::ITERATE)
  35 0 0.0 1 50.0 2 100.0 - SB-IMPL::CALL-WITH-NATIVE-DIRECTORY-ITERATOR
  36 0 0.0 1 50.0 2 100.0 - SB-IMPL::MAP-MATCHING-DIRECTORIES
  37 0 0.0 1 50.0 2 100.0 - DIRECTORY
  38 0 0.0 1 50.0 2 100.0 - SB-IMPL::RELEASE-FD-STREAM-RESOURCES
  39 0 0.0 1 50.0 2 100.0 - (SB-PCL::FAST-METHOD SB-GRAY::PCL-CLOSE (SB-KERNEL:ANSI-STREAM))
  40 0 0.0 1 50.0 2 100.0 - (FLET #:CLEANUP-FUN-[EXIT-TAG-[RESTORE]342]350)
  41 0 0.0 1 50.0 2 100.0 5298 RESTORE
------------------------------------------------------------------------
          0 0.0 elsewhere
#<SB-SPROF::CALL-GRAPH 2 samples {100970C811}>