[Sbcl-devel] help with stastical profiler

Jim Newton

unread,

Nov 16, 2015, 10:11:50 AM11/16/15

to SBCL Devel-list

I’m trying to use the statistical profiler of sbcl. When I copy and paste the example from the manual (http://www.sbcl.org/manual/index.html#Statistical-Profiler)

into the repl, I don’t get the expected results.

Can someone help me figure out what’s up?

ETS> (require :sb-sprof)

(declaim (optimize speed))

(defun cpu-test-inner (a i)

(logxor a

(* i 5)

(+ a i)))

(defun cpu-test (n)

(let ((a 0))

(dotimes (i (expt 2 n) a)

(setf a (cpu-test-inner a i)))))

WARNING: redefining FR.EPITA.LRDE.ETS::CPU-TEST in DEFUN

CPU-TEST

ETS> (sb-sprof:with-profiling (:max-samples 1000

:report :flat

:loop nil)

(cpu-test 26))

WARNING:

No sampling progress; run too short, sampling interval too long,

inappropriate set of sampled thread, or 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 {101F46F353}>

ETS>

Stas Boukarev

unread,

Nov 16, 2015, 10:35:12 AM11/16/15

to Jim Newton, SBCL Devel-list

Jim Newton <jimka...@gmail.com> writes:

This is what I get

Number of samples: 72
Sample interval: 0.01 seconds
Total sampling time: 0.71999997 seconds

Number of cycles: 0
Sampled threads:

#<SB-THREAD:THREAD "main thread" RUNNING {1002A9C993}>

Self Total Cumul
Nr Count % Count % Count % Calls Function
------------------------------------------------------------------------

1 19 26.4 64 88.9 19 26.4 - CPU-TEST
2 18 25.0 34 47.2 37 51.4 - CPU-TEST-INNER
3 18 25.0 18 25.0 55 76.4 - SB-KERNEL:TWO-ARG-XOR
4 17 23.6 17 23.6 72 100.0 - SB-VM::GENERIC-+
5 0 0.0 72 100.0 72 100.0 - "Unknown component: #x1002D72240"
6 0 0.0 72 100.0 72 100.0 - SB-INT:SIMPLE-EVAL-IN-LEXENV
7 0 0.0 72 100.0 72 100.0 - EVAL
8 0 0.0 72 100.0 72 100.0 - INTERACTIVE-EVAL
9 0 0.0 72 100.0 72 100.0 - SB-IMPL::REPL-FUN
10 0 0.0 72 100.0 72 100.0 - (LAMBDA NIL :IN SB-IMPL::TOPLEVEL-REPL)
11 0 0.0 72 100.0 72 100.0 - SB-IMPL::%WITH-REBOUND-IO-SYNTAX
12 0 0.0 72 100.0 72 100.0 - SB-IMPL::TOPLEVEL-REPL
13 0 0.0 72 100.0 72 100.0 - SB-IMPL::TOPLEVEL-INIT
14 0 0.0 72 100.0 72 100.0 - (FLET #:WITHOUT-INTERRUPTS-BODY-82 :IN SAVE-LISP-AND-DIE)
15 0 0.0 72 100.0 72 100.0 - (LABELS SB-IMPL::RESTART-LISP :IN SAVE-LISP-AND-DIE)
------------------------------------------------------------------------
0 0.0 elsewhere
#<SB-SPROF::CALL-GRAPH 72 samples {1002E2F783}>

How is just (time (cpu-test 26))?
And what platform are you using?

--
With best regards, Stas.

------------------------------------------------------------------------------
Presto, an open source distributed SQL query engine for big data, initially
developed by Facebook, enables you to easily query your data on Hadoop in a
more interactive manner. Teradata is also now providing full enterprise
support for Presto. Download a free open source copy now.
http://pubads.g.doubleclick.net/gampad/clk?id=250295911&iu=/4140
_______________________________________________
Sbcl-devel mailing list
Sbcl-...@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/sbcl-devel

Jim Newton

unread,

Nov 16, 2015, 10:51:16 AM11/16/15

to SBCL Devel-list

BTW here is a little information about my environment.

ETS> (sb-ext:describe-compiler-policy)

Basic qualities:

COMPILATION-SPEED = 1

DEBUG = 3

SAFETY = 3

SPACE = 0

SPEED = 3

SB-EXT:INHIBIT-WARNINGS = 1

Dependent qualities:

SB-C::CHECK-CONSTANT-MODIFICATION = 1 -> 3 (yes)

SB-C::TYPE-CHECK = 1 -> 3 (full)

SB-C::CHECK-TAG-EXISTENCE = 1 -> 3 (yes)

SB-C::LET-CONVERSION = 1 -> 3 (on)

SB-C:ALIEN-FUNCALL-SAVES-FP-AND-PC = 1 -> 3 (yes)

SB-C:VERIFY-ARG-COUNT = 1 -> 3 (yes)

SB-C::INSERT-DEBUG-CATCH = 1 -> 1 (maybe)

SB-C::RECOGNIZE-SELF-CALLS = 1 -> 0 (no)

SB-C::FLOAT-ACCURACY = 1 -> 3 (full)

SB-C:INSERT-STEP-CONDITIONS = 1 -> 0 (no)

SB-C::COMPUTE-DEBUG-FUN = 1 -> 3 (yes)

SB-C::PRESERVE-SINGLE-USE-DEBUG-VARIABLES = 1 -> 0 (no)

SB-C::INSERT-ARRAY-BOUNDS-CHECKS = 1 -> 3 (yes)

SB-C::STORE-XREF-DATA = 1 -> 3 (yes)

SB-C:STORE-COVERAGE-DATA = 1 -> 0 (no)

SB-C::STORE-CLOSURE-DEBUG-POINTER = 1 -> 0 (no)

SB-C::ALLOW-NON-RETURNING-TAIL-CALL = 1 -> 0 (no)

; No value

ETS> (time (cpu-test 26))

Evaluation took:

1.449 seconds of real time

1.443975 seconds of total run time (1.434469 user, 0.009506 system)

99.65% CPU

3,468,234,304 processor cycles

0 bytes consed

268435428

ETS> *features*

(:SWANK :QUICKLISP :ASDF-PACKAGE-SYSTEM :ASDF3.1 :ASDF3 :ASDF2 :ASDF :OS-MACOSX

:OS-UNIX :NON-BASE-CHARS-EXIST-P :ASDF-UNICODE :64-BIT :ALIEN-CALLBACKS

:ANSI-CL :ASH-RIGHT-VOPS :BSD :C-STACK-IS-CONTROL-STACK :COMMON-LISP

:COMPARE-AND-SWAP-VOPS :COMPLEX-FLOAT-VOPS :CYCLE-COUNTER :DARWIN

:DARWIN9-OR-BETTER :FLOAT-EQL-VOPS :FP-AND-PC-STANDARD-SAVE :GENCGC

:IEEE-FLOATING-POINT :INLINE-CONSTANTS :INODE64 :INTEGER-EQL-VOP

:INTERLEAVED-RAW-SLOTS :LINKAGE-TABLE :LITTLE-ENDIAN :MACH-EXCEPTION-HANDLER

:MACH-O :MEMORY-BARRIER-VOPS :MULTIPLY-HIGH-VOPS :OS-PROVIDES-BLKSIZE-T

:OS-PROVIDES-DLADDR :OS-PROVIDES-DLOPEN :OS-PROVIDES-PUTWC

:OS-PROVIDES-SUSECONDS-T :PACKAGE-LOCAL-NICKNAMES :PRECISE-ARG-COUNT-ERROR

:RAW-INSTANCE-INIT-VOPS :SB-DOC :SB-EVAL :SB-LDB :SB-PACKAGE-LOCKS

:SB-SIMD-PACK :SB-SOURCE-LOCATIONS :SB-TEST :SB-THREAD :SB-UNICODE :SBCL

:STACK-ALLOCATABLE-CLOSURES :STACK-ALLOCATABLE-FIXED-OBJECTS

:STACK-ALLOCATABLE-LISTS :STACK-ALLOCATABLE-VECTORS

:STACK-GROWS-DOWNWARD-NOT-UPWARD :SYMBOL-INFO-VOPS :UD2-BREAKPOINTS :UNIX

:UNWIND-TO-FRAME-AND-CALL-VOP :X86-64)

ETS>

Jim Newton

unread,

Nov 18, 2015, 3:44:51 AM11/18/15

to SBCL Devel-list

I tried it again with a different compiler policy, but it still doesn't seem to work.

CL-USER> (sb-sprof:with-profiling (:max-samples 1000

:report :flat

:loop nil)

(cpu-test 26))

WARNING:

No sampling progress; run too short, sampling interval too long,

inappropriate set of sampled thread, or 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 {10123AE973}>

CL-USER> (sb-ext:describe-compiler-policy)

Basic qualities:

COMPILATION-SPEED = 1

DEBUG = 1

SAFETY = 1

SPACE = 1

SPEED = 3

INHIBIT-WARNINGS = 1

Dependent qualities:

SB-C::CHECK-CONSTANT-MODIFICATION = 1 -> 1 (maybe)

SB-C::TYPE-CHECK = 1 -> 2 (weak)

SB-C::CHECK-TAG-EXISTENCE = 1 -> 3 (yes)

SB-C::LET-CONVERSION = 1 -> 3 (on)

SB-C:ALIEN-FUNCALL-SAVES-FP-AND-PC = 1 -> 0 (no)

SB-C:VERIFY-ARG-COUNT = 1 -> 3 (yes)

SB-C::INSERT-DEBUG-CATCH = 1 -> 0 (no)

SB-C::RECOGNIZE-SELF-CALLS = 1 -> 3 (yes)

SB-C::FLOAT-ACCURACY = 1 -> 3 (full)

SB-C:INSERT-STEP-CONDITIONS = 1 -> 0 (no)

SB-C::COMPUTE-DEBUG-FUN = 1 -> 1 (minimal)

SB-C::PRESERVE-SINGLE-USE-DEBUG-VARIABLES = 1 -> 0 (no)

SB-C::INSERT-ARRAY-BOUNDS-CHECKS = 1 -> 3 (yes)

SB-C::STORE-XREF-DATA = 1 -> 3 (yes)

SB-C:STORE-COVERAGE-DATA = 1 -> 0 (no)

SB-C::STORE-CLOSURE-DEBUG-POINTER = 1 -> 0 (no)

SB-C::ALLOW-NON-RETURNING-TAIL-CALL = 1 -> 0 (no)

; No value

CL-USER>

On Mon, Nov 16, 2015 at 4:07 PM, Jim Newton <jimka...@gmail.com> wrote:

Stas Boukarev

unread,

Nov 18, 2015, 10:02:09 AM11/18/15

to Jim Newton, SBCL Devel-list

Jim Newton <jimka...@gmail.com> writes:

> I tried it again with a different compiler policy, but it still doesn't
> seem to work.

sb-sprof doesn't work indeed on OS X. Try running it without multiple
threads or with :mode :time.

--
With best regards, Stas.

------------------------------------------------------------------------------

Tito Latini

unread,

Nov 18, 2015, 11:41:46 AM11/18/15

to sbcl-...@lists.sourceforge.net

> CL-USER> (sb-sprof:with-profiling (:max-samples 1000
> :report :flat
> :loop nil)
> (cpu-test 26))
> WARNING:
> No sampling progress; run too short, sampling interval too long,
> inappropriate set of sampled thread, or possibly a profiler bug.

I don't know if it helps, I can reproduce that problem on Linux x86_64
with SLIME and

(setf swank:*communication-style* :sigio)

in ${HOME}/.swank.lisp, because SAMPLES-INDEX returns the last index
within SB-SPROF:WITH-PROFILING macro:

(when (= ,last-index (samples-index *samples*))
(,oops))

The follow workaround seems to work in this case:

(sb-sys:with-interrupts

(sb-sprof:with-profiling (:max-samples 1000
:report :flat
:loop nil)

(cpu-test 26)))

Stas Boukarev

unread,

Nov 18, 2015, 11:59:32 AM11/18/15

to Tito Latini, sbcl-...@lists.sourceforge.net

Tito Latini <tito....@gmail.com> writes:

>> CL-USER> (sb-sprof:with-profiling (:max-samples 1000
>> :report :flat
>> :loop nil)
>> (cpu-test 26))
>> WARNING:
>> No sampling progress; run too short, sampling interval too long,
>> inappropriate set of sampled thread, or possibly a profiler bug.
>
> I don't know if it helps, I can reproduce that problem on Linux x86_64
> with SLIME and
>
> (setf swank:*communication-style* :sigio)
>
> in ${HOME}/.swank.lisp, because SAMPLES-INDEX returns the last index
> within SB-SPROF:WITH-PROFILING macro:
>
> (when (= ,last-index (samples-index *samples*))
> (,oops))
>
> The follow workaround seems to work in this case:
>
> (sb-sys:with-interrupts
> (sb-sprof:with-profiling (:max-samples 1000
> :report :flat
> :loop nil)
> (cpu-test 26)))

sb-sys:with-interrupts only makes sense if there's a WITHOUT-INTERRUPTS
around it.
Besides, sb-sprof works fine with :sigio.

And i'm not sure how you arrived at

(when (= ,last-index (samples-index *samples*))
(,oops))

it's there to just produce a warning that nothing has been collected.

--
With best regards, Stas.

Tito Latini

unread,

Nov 18, 2015, 12:25:46 PM11/18/15

to Stas Boukarev, sbcl-...@lists.sourceforge.net

when I use :sigio, I get

CL-USER> sb-sys:*interrupts-enabled*
NIL

It is T with other SWANK's communication styles.

Stas Boukarev

unread,

Nov 18, 2015, 1:51:10 PM11/18/15

to Tito Latini, sbcl-...@lists.sourceforge.net

Right you are, this is bogus. I just updated swank to enable interrupts.
Good catch.

But OSX has a different problem with signals, they are delivered to
wrong threads. So profiling outside of slime with just one thread may
work.
Or inside slime using :fd-handler (who knows what else is broken on
:sigio) *communication-style*.

--
With best regards, Stas.

Reply all

Reply to author

Forward