New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

significant efficiency problem with draw-pattern* #637

Open
john-a-carroll opened this Issue Dec 18, 2018 · 5 comments

Comments

Projects
None yet
2 participants
@john-a-carroll
Copy link
Contributor

john-a-carroll commented Dec 18, 2018

There has been a 100-fold decrease in the performance draw-pattern* over the past 12 months - between versions of 10/2017 and 10/2018.

The problem is obvious if you run the following code, which repeatedly draws a 2x2 pattern to an application pane:

(in-package :clim-user)

(defparameter +pattern+
  (make-pattern
    #2A((0 1)
        (1 0))
    (list +white+ +black+)))

(defun display-pattern (frame stream)
  (declare (ignore frame))
  (window-clear stream)
  (time
    (loop for x from 0 to 250 by 10
      do
      (loop for y from 0 to 250 by 10
        do
        (draw-pattern* stream +pattern+ x y)))))
 
(define-application-frame drawtest ()
  ()
  (:menu-bar t)
  (:panes
    (p1
      (make-pane 'application-pane
        :width 300 :height 300
        :display-function #'display-pattern)))
  (:layouts
    (default
      (spacing (:thickness 20) p1))))

(defun run-drawtest ()
  (run-frame-top-level (make-application-frame 'drawtest)))

(define-drawtest-command (quit :name t :menu t) ()
  (with-application-frame (frame) (frame-exit frame)))

(run-drawtest)

Here's a summary of the timing results:

SBCL 1.3.18, macOS
mcclim-20181018-git
clx-20181018-git
  11.217 seconds of real time
  8.339215 seconds of total run time (6.543405 user, 1.795810 system)
  11,073,952 bytes consed

SBCL 1.3.18, macOS
mcclim-20171023-git
clx-20171023-git
  0.078 seconds of real time
  0.062724 seconds of total run time (0.055204 user, 0.007520 system)
  13,019,632 bytes consed

i.e. the runtime has increased from less than 0.1 second to more than 10 seconds. In my application, this slow-down significantly degrades user experience.

I don't know what could have caused this. Changes in McCLIM or in CLX? The definition of draw-pattern* is certainly very different to what it used to be. I would very much appreciate a fix to get back to somewhere near the old performance.

@dkochmanski

This comment has been minimized.

Copy link
Collaborator

dkochmanski commented Dec 19, 2018

Hey John. I'm trying to reproduce a problem with no success (I have newest McCLIM and CLX). Do you have the same problem if you pull newest versions from repositories?

Evaluation took:
  0.154 seconds of real time
  0.163605 seconds of total run time (0.102585 user, 0.061020 system)
  106.49% CPU
  415 lambdas converted
  418,412,863 processor cycles
  23,861,776 bytes consed

Recent changes to patterns improved correctness in light of spec (i.e you can transform ink, and if you draw pattern with draw-design you may transform pattern and ink), you may see one of newly introduced demos; straighforward case (like yours) shouldn't suffer from speed degradation. You may also use another pattern as an ink (i.e recursive pattern).

I suspect that the performance drop you have witnessed could be due to a switch from structures to classes in CLX. That change was recently retracted (due to multiple regressions, we were not aware of performance degradation). Could you confirm whenever you witness the problem with the newest code and let us know here?

@john-a-carroll

This comment has been minimized.

Copy link
Contributor

john-a-carroll commented Dec 19, 2018

Thanks for checking up on this. I've just re-built SBCL from the latest sources (1.4.14) and switched to the newest code - and unfortunately I still see the same problem.

To try to narrow it down I profiled the run, and I append interesting parts of the output. It seems that almost all of the time is disappearing in Unix locks. This is in macOS (10.12.6). Maybe that's all more efficient in Linux. Unfortunately I haven't got access to my Linux testbed at the moment so I can't check.

Here's my current list of versions:

alexandria-20181210-git
babel-20171227-git
bitio-20171023-git
bordeaux-threads-v0.8.6
cffi_0.20.0
chipz-20180328-git
cl-jpeg-20170630-git
cl-pdf-20170830-git
cl-ppcre-20180831-git
cl-tga-20160318-git
cl-unicode-20180328-git
cl-vectors-20180228-git
closer-mop-20181210-git
clx-20181210-git
deflate-20180228-git
fast-io-20171023-git
flexi-streams-20180711-git
flexichain_1.5.1
ieee-floats-20170830-git
iterate-20180228-git
mcclim-20181210-git
monkeylib-binary-data-20111203-git
opticl-20181210-git
opticl-core-20171019-git
parsley-20180430-git
pngload-20180430-git
retrospectiff-20171019-git
salza2-2.0.9
skippy-1.3.12
slime-v2.22
spatial-trees-20140826-git
static-vectors-v1.8.3
trivial-features-20161204-git
trivial-garbage-20181018-git
trivial-gray-streams-20181018-git
zpb-ttf-1.0.3
zpng-1.2.2

And here are excerpts from the profiling output (based on elapsed time rather than cpu time):

Number of samples:   2266
Sample interval:     0.01 seconds
Total sampling time: 22.66 seconds
Number of cycles:    0
Sampled threads:
 #<SB-THREAD:THREAD "main thread" RUNNING {10005205B3}>
 #<SB-THREAD:THREAD "#<CLIM-CLX::CLX-PORT :HOST \"private/tmp/com.apple.launchd.VtMptjK2HL/org.macosforge.xquartz\" :DISPLAY-ID 0 {104CD95153}>'s event process." RUNNING {104E0834C3}>

                               Callers
                 Total.     Function
 Count     %  Count     %      Callees
------------------------------------------------------------------------
  1129  49.8                   SB-UNIX:UNIX-SIMPLE-POLL [89]
  1129  49.8   1129  49.8   "foreign function __select" [1]
------------------------------------------------------------------------
  1090  48.1                   XLIB::PROCESS-BLOCK [7]
     2   0.1                   (FLET SB-THREAD::WITH-RECURSIVE-LOCK-THUNK :IN XLIB::READ-REPLY-INPUT) [44]
  1092  48.2   1092  48.2   "foreign function swtch_pri" [2]
------------------------------------------------------------------------
     2   0.1                   XLIB::READ-INPUT [42]
     8   0.4                   XLIB::PROCESS-BLOCK [7]
    10   0.4     10   0.4   "foreign function sched_yield" [3]
------------------------------------------------------------------------
     4   0.2                   (LAMBDA (XLIB:DISPLAY XLIB::PREDICATE &REST XLIB::PREDICATE-ARGS) :IN XLIB::READ-INPUT) [8]
     4   0.2      4   0.2   (LAMBDA (SB-PCL::.ARG0.) :IN "SYS:SRC;PCL;BRAID.LISP") [4]
------------------------------------------------------------------------
     4   0.2                   (LAMBDA (XLIB:DISPLAY XLIB::PREDICATE &REST XLIB::PREDICATE-ARGS) :IN XLIB::READ-INPUT) [8]
     4   0.2      4   0.2   SB-KERNEL:CLASSOID-TYPEP [5]
------------------------------------------------------------------------
     4   0.2                   (LAMBDA (XLIB:DISPLAY XLIB::PREDICATE &REST XLIB::PREDICATE-ARGS) :IN XLIB::READ-INPUT) [8]
     4   0.2      4   0.2   (LAMBDA (XLIB::PENDING-COMMAND) :IN XLIB::READ-REPLY) [6]
------------------------------------------------------------------------
  1119  49.4                   XLIB::READ-INPUT [42]
     2   0.1   1119  49.4   XLIB::PROCESS-BLOCK [7]
     8   0.4                   "foreign function sched_yield" [3]
    19   0.8                   (LAMBDA (XLIB:DISPLAY XLIB::PREDICATE &REST XLIB::PREDICATE-ARGS) :IN XLIB::READ-INPUT) [8]
  1090  48.1                   "foreign function swtch_pri" [2]
------------------------------------------------------------------------

...

------------------------------------------------------------------------
  2259  99.7                   SB-THREAD::CALL-WITH-RECURSIVE-LOCK [37]
     0   0.0   2259  99.7   (FLET "WITHOUT-INTERRUPTS-BODY-29" :IN SB-THREAD::CALL-WITH-RECURSIVE-LOCK) [38]
     3   0.1                   (FLET SB-THREAD::WITH-RECURSIVE-LOCK-THUNK :IN XLIB:PUT-IMAGE) [92]
     1   0.0                   SB-THREAD::%WAIT-FOR-MUTEX [82]
  1123  49.6                   (FLET SB-THREAD::WITH-RECURSIVE-LOCK-THUNK :IN XLIB::GET-DRAWABLE-GEOMETRY-BUFFER) [80]
     1   0.0                   (FLET SB-THREAD::WITH-RECURSIVE-LOCK-THUNK :IN XLIB::READ-REPLY-INPUT) [44]
  1133  50.0                   (FLET SB-THREAD::WITH-RECURSIVE-LOCK-THUNK :IN XLIB:PROCESS-EVENT) [39]
------------------------------------------------------------------------
     3   0.1                   XLIB:PUT-IMAGE [10]
     2   0.1                   XLIB::READ-REPLY [81]
  1123  49.6                   XLIB::GET-DRAWABLE-GEOMETRY-BUFFER [79]
     2   0.1                   XLIB::READ-REPLY-INPUT [43]
  1133  50.0                   XLIB:PROCESS-EVENT [36]
     0   0.0   2259  99.7   SB-THREAD::CALL-WITH-RECURSIVE-LOCK [37]
  2259  99.7                   (FLET "WITHOUT-INTERRUPTS-BODY-29" :IN SB-THREAD::CALL-WITH-RECURSIVE-LOCK) [38]
------------------------------------------------------------------------
  1121  49.5                   XLIB::READ-REPLY [81]
  1133  50.0                   XLIB::WAIT-FOR-EVENT [41]
     0   0.0   2254  99.5   XLIB::READ-INPUT [42]
     2   0.1                   "foreign function sched_yield" [3]
     3   0.1                   XLIB::BUFFER-INPUT [103]
  1119  49.4                   XLIB::PROCESS-BLOCK [7]
  1128  49.8                   XLIB::BUFFER-INPUT-WAIT [86]
     2   0.1                   XLIB::READ-REPLY-INPUT [43]
------------------------------------------------------------------------
  1133  50.0                   XLIB::EVENT-LOOP-STEP-BEFORE [40]
     0   0.0   1133  50.0   XLIB::WAIT-FOR-EVENT [41]
  1133  50.0                   XLIB::READ-INPUT [42]
------------------------------------------------------------------------
  1133  50.0                   (FLET SB-THREAD::WITH-RECURSIVE-LOCK-THUNK :IN XLIB:PROCESS-EVENT) [39]
     0   0.0   1133  50.0   XLIB::EVENT-LOOP-STEP-BEFORE [40]
  1133  50.0                   XLIB::WAIT-FOR-EVENT [41]
------------------------------------------------------------------------
  1133  50.0                   (FLET "WITHOUT-INTERRUPTS-BODY-29" :IN SB-THREAD::CALL-WITH-RECURSIVE-LOCK) [38]
     0   0.0   1133  50.0   (FLET SB-THREAD::WITH-RECURSIVE-LOCK-THUNK :IN XLIB:PROCESS-EVENT) [39]
  1133  50.0                   XLIB::EVENT-LOOP-STEP-BEFORE [40]
------------------------------------------------------------------------
  1133  50.0                   (SB-PCL::FAST-METHOD CLIM-BACKEND:GET-NEXT-EVENT (CLIM-CLX::CLX-BASIC-PORT)) [35]
     0   0.0   1133  50.0   XLIB:PROCESS-EVENT [36]
  1133  50.0                   SB-THREAD::CALL-WITH-RECURSIVE-LOCK [37]
------------------------------------------------------------------------

...

           Self        Total        Cumul
  Nr  Count     %  Count     %  Count     %    Calls  Function
------------------------------------------------------------------------
   1   1129  49.8   1129  49.8   1129  49.8        -  "foreign function __select"
   2   1092  48.2   1092  48.2   2221  98.0        -  "foreign function swtch_pri"
   3     10   0.4     10   0.4   2231  98.5        -  "foreign function sched_yield"
   4      4   0.2      4   0.2   2235  98.6        -  (LAMBDA (SB-PCL::.ARG0.) :IN "SYS:SRC;PCL;BRAID.LISP")
   5      4   0.2      4   0.2   2239  98.8        -  SB-KERNEL:CLASSOID-TYPEP
   6      4   0.2      4   0.2   2243  99.0        -  (LAMBDA (XLIB::PENDING-COMMAND) :IN XLIB::READ-REPLY)
   7      2   0.1   1119  49.4   2245  99.1        -  XLIB::PROCESS-BLOCK
   8      2   0.1     19   0.8   2247  99.2        -  (LAMBDA (XLIB:DISPLAY XLIB::PREDICATE &REST XLIB::PREDICATE-ARGS) :IN XLIB::READ-INPUT)
   9      1   0.0      5   0.2   2248  99.2        -  XLIB:PUT-IMAGE
  10      1   0.0      3   0.1   2249  99.2        -  SB-IMPL::REFILL-INPUT-BUFFER
  11      1   0.0      1   0.0   2250  99.3        -  "foreign function __syscall"
  12      1   0.0      1   0.0   2251  99.3        -  XLIB::FAST-WRITE-PIXARRAY
  13      1   0.0      1   0.0   2252  99.4        -  XLIB::WRITE-PIXARRAY-1
  14      1   0.0      1   0.0   2253  99.4        -  (FLET SB-PCL::GET-OR-PUT-CTOR :IN "SYS:SRC;PCL;CTOR.LISP")
  15      1   0.0      1   0.0   2254  99.5        -  SB-UNIX::WITH-DEFERRABLE-SIGNALS-UNBLOCKED
  16      1   0.0      1   0.0   2255  99.5        -  SB-KERNEL:CLASSOID-CELL-TYPEP
  17      1   0.0      1   0.0   2256  99.6        -  (SB-VM::OPTIMIZED-DATA-VECTOR-REF T)
  18      1   0.0      1   0.0   2257  99.6        -  SB-ALIEN-INTERNALS:%SAP-ALIEN
  19      1   0.0      1   0.0   2258  99.6        -  (LAMBDA (SB-PCL::|.P0.|))
  20      1   0.0      1   0.0   2259  99.7        -  SB-VM::ALLOC-TRAMP
  21      0   0.0   2259  99.7   2259  99.7        -  (FLET "WITHOUT-INTERRUPTS-BODY-29" :IN SB-THREAD::CALL-WITH-RECURSIVE-LOCK)
  22      0   0.0   2259  99.7   2259  99.7        -  SB-THREAD::CALL-WITH-RECURSIVE-LOCK
  23      0   0.0   2254  99.5   2259  99.7        -  XLIB::READ-INPUT
  24      0   0.0   1133  50.0   2259  99.7        -  XLIB::WAIT-FOR-EVENT
  25      0   0.0   1133  50.0   2259  99.7        -  XLIB::EVENT-LOOP-STEP-BEFORE
  26      0   0.0   1133  50.0   2259  99.7        -  (FLET SB-THREAD::WITH-RECURSIVE-LOCK-THUNK :IN XLIB:PROCESS-EVENT)
  27      0   0.0   1133  50.0   2259  99.7        -  XLIB:PROCESS-EVENT
  28      0   0.0   1133  50.0   2259  99.7        -  (SB-PCL::FAST-METHOD CLIM-BACKEND:GET-NEXT-EVENT (CLIM-CLX::CLX-BASIC-PORT))
  29      0   0.0   1133  50.0   2259  99.7        -  (SB-PCL::EMF CLIM-BACKEND:GET-NEXT-EVENT)
  30      0   0.0   1133  50.0   2259  99.7        -  (SB-PCL::FAST-METHOD PROCESS-NEXT-EVENT (BASIC-PORT))
  31      0   0.0   1133  50.0   2259  99.7        -  (LAMBDA NIL :IN CLIM-CLX:INITIALIZE-CLX)
  32      0   0.0   1133  50.0   2259  99.7        -  (LAMBDA NIL :IN BORDEAUX-THREADS::BINDING-DEFAULT-SPECIALS)
  33      0   0.0   1133  50.0   2259  99.7        -  (FLET SB-UNIX::BODY :IN SB-THREAD::INITIAL-THREAD-FUNCTION-TRAMPOLINE)
  34      0   0.0   1133  50.0   2259  99.7        -  (FLET "WITHOUT-INTERRUPTS-BODY-4" :IN SB-THREAD::INITIAL-THREAD-FUNCTION-TRAMPOLINE)
  35      0   0.0   1133  50.0   2259  99.7        -  (FLET SB-THREAD::WITH-MUTEX-THUNK :IN SB-THREAD::INITIAL-THREAD-FUNCTION-TRAMPOLINE)
  36      0   0.0   1133  50.0   2259  99.7        -  (FLET "WITHOUT-INTERRUPTS-BODY-1" :IN SB-THREAD::CALL-WITH-MUTEX)
  37      0   0.0   1133  50.0   2259  99.7        -  SB-THREAD::CALL-WITH-MUTEX
  38      0   0.0   1133  50.0   2259  99.7        -  SB-THREAD::INITIAL-THREAD-FUNCTION-TRAMPOLINE
  39      0   0.0   1133  50.0   2259  99.7        -  "foreign function call_into_lisp"
  40      0   0.0   1133  50.0   2259  99.7        -  "foreign function new_thread_trampoline"
  41      0   0.0   1133  50.0   2259  99.7        -  "foreign function _pthread_body"
  42      0   0.0   1133  50.0   2259  99.7        -  "foreign function thread_start"
  43      0   0.0   1132  50.0   2259  99.7        -  (SB-PCL::EMF CLIM-CLX::MEDIUM-GCONTEXT)
  44      0   0.0   1132  50.0   2259  99.7        -  (SB-PCL::FAST-METHOD CLIM-CLX::MEDIUM-DRAW-RECTANGLE-USING-INK* (CLIM-CLX:CLX-MEDIUM T T T T T T))
  45      0   0.0   1132  50.0   2259  99.7        -  (SB-PCL::FAST-METHOD MEDIUM-DRAW-RECTANGLE* :AROUND (CLIM-INTERNALS::TRANSFORM-COORDINATES-MIXIN T T T T T))
  46      0   0.0   1132  50.0   2259  99.7        -  (SB-PCL::FAST-METHOD MEDIUM-DRAW-RECTANGLE* (SHEET T T T T T))
  47      0   0.0   1132  50.0   2259  99.7        -  (SB-PCL::FAST-METHOD CLIM-INTERNALS::DO-GRAPHICS-WITH-OPTIONS-INTERNAL (MEDIUM T T))
  48      0   0.0   1132  50.0   2259  99.7        -  (LABELS #:G5 :IN CLIM-INTERNALS::DO-GRAPHICS-WITH-OPTIONS)
  49      0   0.0   1132  50.0   2259  99.7        -  (SB-PCL::FAST-METHOD CLIM-INTERNALS::DO-GRAPHICS-WITH-OPTIONS (SHEET T))
  50      0   0.0   1132  50.0   2259  99.7        -  DRAW-RECTANGLE*
  51      0   0.0   1132  50.0   2259  99.7        -  (LABELS #:G5 :IN CLIM-INTERNALS::INVOKE-WITH-IDENTITY-TRANSFORMATION)
  52      0   0.0   1132  50.0   2259  99.7        -  (SB-PCL::FAST-METHOD CLIM-INTERNALS::INVOKE-WITH-IDENTITY-TRANSFORMATION (SHEET T))
  53      0   0.0   1132  50.0   2259  99.7        -  DRAW-PATTERN*
  54      0   0.0   1132  50.0   2259  99.7        -  DISPLAY-PATTERN
  55      0   0.0   1132  50.0   2259  99.7        -  (SB-PCL::EMF REDISPLAY-FRAME-PANE)
  56      0   0.0   1132  50.0   2259  99.7        -  (SB-PCL::FAST-METHOD REDISPLAY-FRAME-PANE :AROUND (APPLICATION-FRAME T))
  57      0   0.0   1132  50.0   2259  99.7        -  (SB-PCL::FAST-METHOD MAP-OVER-SHEETS (T BASIC-SHEET))
  58      0   0.0   1132  50.0   2259  99.7        -  SB-KERNEL:%MAP-FOR-EFFECT-ARITY-1
  59      0   0.0   1132  50.0   2259  99.7        -  (SB-PCL::FAST-METHOD DEFAULT-FRAME-TOP-LEVEL (APPLICATION-FRAME))
  60      0   0.0   1132  50.0   2259  99.7        -  (SB-PCL::FAST-METHOD RUN-FRAME-TOP-LEVEL (APPLICATION-FRAME))
  61      0   0.0   1132  50.0   2259  99.7        -  (SB-PCL::FAST-METHOD RUN-FRAME-TOP-LEVEL :AROUND (APPLICATION-FRAME))
  62      0   0.0   1132  50.0   2259  99.7        -  SB-INT:SIMPLE-EVAL-IN-LEXENV
  63      0   0.0   1132  50.0   2259  99.7        -  EVAL
  64      0   0.0   1132  50.0   2259  99.7        -  SB-EXT:INTERACTIVE-EVAL
  65      0   0.0   1132  50.0   2259  99.7        -  SB-IMPL::REPL-FUN
  66      0   0.0   1132  50.0   2259  99.7        -  (FLET "LAMBDA0" :IN "SYS:SRC;CODE;TOPLEVEL.LISP")
  67      0   0.0   1132  50.0   2259  99.7        -  SB-IMPL::%WITH-REBOUND-IO-SYNTAX
  68      0   0.0   1132  50.0   2259  99.7        -  SB-IMPL::TOPLEVEL-REPL
  69      0   0.0   1132  50.0   2259  99.7        -  SB-IMPL::TOPLEVEL-INIT
  70      0   0.0   1132  50.0   2259  99.7        -  (FLET SB-UNIX::BODY :IN SB-EXT:SAVE-LISP-AND-DIE)
  71      0   0.0   1132  50.0   2259  99.7        -  (FLET "WITHOUT-INTERRUPTS-BODY-7" :IN SB-EXT:SAVE-LISP-AND-DIE)
  72      0   0.0   1132  50.0   2259  99.7        -  (LABELS SB-IMPL::RESTART-LISP :IN SB-EXT:SAVE-LISP-AND-DIE)
  73      0   0.0   1131  49.9   2259  99.7        -  (SB-PCL::FAST-METHOD CLIM-CLX::DESIGN-GCONTEXT (CLIM-CLX:CLX-MEDIUM CLIM-EXTENSIONS:PATTERN))
  74      0   0.0   1131  49.9   2259  99.7        -  (SB-PCL::FAST-METHOD CLIM-CLX::MEDIUM-GCONTEXT (CLIM-CLX:CLX-MEDIUM CLIM-EXTENSIONS:TRANSFORMED-DESIGN))
  75      0   0.0   1130  49.9   2259  99.7        -  SB-UNIX:UNIX-SIMPLE-POLL
  76      0   0.0   1128  49.8   2259  99.7        -  SB-SYS:WAIT-UNTIL-FD-USABLE
  77      0   0.0   1128  49.8   2259  99.7        -  XLIB::BUFFER-INPUT-WAIT-DEFAULT
  78      0   0.0   1128  49.8   2259  99.7        -  XLIB::BUFFER-INPUT-WAIT
  79      0   0.0   1124  49.6   2259  99.7        -  CLIM-CLX::COMPUTE-RGB-IMAGE
  80      0   0.0   1123  49.6   2259  99.7        -  XLIB::READ-REPLY
  81      0   0.0   1123  49.6   2259  99.7        -  (FLET SB-THREAD::WITH-RECURSIVE-LOCK-THUNK :IN XLIB::GET-DRAWABLE-GEOMETRY-BUFFER)
  82      0   0.0   1123  49.6   2259  99.7        -  XLIB::GET-DRAWABLE-GEOMETRY-BUFFER
  83      0   0.0   1123  49.6   2259  99.7        -  XLIB:DRAWABLE-DEPTH
  84      0   0.0      7   0.3   2259  99.7        -  CLIM-CLX::COMPUTE-RGB-MASK
  85      0   0.0      3   0.1   2259  99.7        -  XLIB::WRITE-IMAGE-Z
  86      0   0.0      3   0.1   2259  99.7        -  (FLET SB-THREAD::WITH-RECURSIVE-LOCK-THUNK :IN XLIB:PUT-IMAGE)
  87      0   0.0      3   0.1   2259  99.7        -  SB-IMPL::FD-STREAM-READ-N-BYTES
  88      0   0.0      3   0.1   2259  99.7        -  XLIB::BUFFER-READ-DEFAULT
  89      0   0.0      3   0.1   2259  99.7        -  XLIB::BUFFER-INPUT
  90      0   0.0      2   0.1   2259  99.7        -  (FLET SB-THREAD::WITH-RECURSIVE-LOCK-THUNK :IN XLIB::READ-REPLY-INPUT)
  91      0   0.0      2   0.1   2259  99.7        -  SB-THREAD::%%WAIT-FOR
  92      0   0.0      2   0.1   2259  99.7        -  SB-THREAD::%%WAIT-FOR-MUTEX
  93      0   0.0      2   0.1   2259  99.7        -  SB-THREAD::%WAIT-FOR-MUTEX
  94      0   0.0      2   0.1   2259  99.7        -  SB-IMPL::SYSREAD-MAY-BLOCK-P
  95      0   0.0      2   0.1   2259  99.7        -  XLIB::READ-REPLY-INPUT
  96      0   0.0      2   0.1   2259  99.7        -  XLIB:CREATE-PIXMAP
  97      0   0.0      1   0.0   2259  99.7        -  SB-UNIX:NANOSLEEP
  98      0   0.0      1   0.0   2259  99.7        -  XLIB::WRITE-PIXARRAY
  99      0   0.0      1   0.0   2259  99.7        -  (SB-PCL::FAST-METHOD CLIM-CLX::MEDIUM-GCONTEXT (CLIM-CLX:CLX-MEDIUM CLIM-EXTENSIONS:PATTERN))
 100      0   0.0      1   0.0   2259  99.7        -  SB-PCL::ENSURE-CACHED-CTOR
 101      0   0.0      1   0.0   2259  99.7        -  CLIM-EXTENSIONS:EFFECTIVE-TRANSFORMED-DESIGN
 102      0   0.0      1   0.0   2259  99.7        -  (FLET "LAMBDA0" :IN "SYS:SRC;CODE;TARGET-THREAD.LISP")
 103      0   0.0      1   0.0   2259  99.7        -  (LABELS SB-THREAD::TRY :IN SB-THREAD::%%WAIT-FOR)
 104      0   0.0      1   0.0   2259  99.7        -  FIND
 105      0   0.0      1   0.0   2259  99.7        -  SB-KERNEL:%FIND-POSITION
 106      0   0.0      1   0.0   2259  99.7        -  XLIB::SET-GCONTEXT-FUNCTION
 107      0   0.0      1   0.0   2259  99.7        -  XLIB:CREATE-GCONTEXT
------------------------------------------------------------------------
          6   0.3                                     elsewhere
@dkochmanski

This comment has been minimized.

Copy link
Collaborator

dkochmanski commented Dec 19, 2018

could you provide results visualised with clim.flamegraph (branch future)?

https://github.com/scymtym/clim.flamegraph/tree/future

The gist of how to use it:

(require 'sb-sprof)
(asdf:load-system 'clim.flamegraph)

(...
  (sb-sprof:with-profiling () ,@body))

;; exit the frame and run the flamegraph
(clim.flamegraph:flamegraph)

Please run it against fast version and a version with the performance regression.

@john-a-carroll

This comment has been minimized.

Copy link
Contributor

john-a-carroll commented Dec 19, 2018

Yes, no problem - the flamegraphs are below. (I had to make a couple of minor edits to the source of clim.flamegraph to get it to work with the older version of McCLIM).

Both sets of results are with SBCL 1.4.14, macOS 10.12.6. The list of new versions is as above. The list of old versions is:

alexandria-20170830-git
babel-20170630-git
bitio-20171023-git
bordeaux-threads-v0.8.5
cffi_0.19.0
chipz-20160318-git
cl-jpeg-20170630-git
cl-pdf-20170830-git
cl-tga-20160318-git
cl-vectors-20170630-git
closer-mop-20171019-git
clx-20171023-git
deflate-20131211-git
fast-io-20171023-git
flexi-streams-1.0.15
flexichain_1.5.1
ieee-floats-20170830-git
iterate-20160825-darcs
mcclim-20171023-git
monkeylib-binary-data-20111203-git
opticl-20171019-git
opticl-core-20171019-git
parsley-20171023-git
pngload-20171019-git
retrospectiff-20171019-git
salza2-2.0.9
skippy-1.3.12
slime-v2.20
spatial-trees-20140826-git
static-vectors-v1.8.3
trivial-features-20161204-git
trivial-garbage-20150113-git
trivial-gray-streams-20140826-git
zpb-ttf-1.0.3
zpng-1.2.2

Below is the flamegraph for the old, fast version (repeated 150 times to give a similar overall run time and to collect enough profile samples). There are two threads visible, but the CLX one on the right is very thin).

Old, fast version

Below is the flamegraph for the new, slow version:

New, slow version

I've replicated the difference in Clozure CL 1.11, so the Lisp implementation does not seem to be a factor.

@dkochmanski

This comment has been minimized.

Copy link
Collaborator

dkochmanski commented Dec 27, 2018

Thank you. I'm writing here just to note that I haven't forgotten about the issue and I'll do my best to fix it before the upcoming release. I think I know where the problem comes from.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment