Re: Fwd: Re: Severe performance regression with latest CVS sources?

Christophe Rhodes <csr21@xxxxxxxxx> writes:

> It's elided the creation, I'm afraid.  Can you do
>   (defvar *foo*)
>   (time (dotimes (i (* 2 824)) (setq *foo* (make-hash-table))))
> ?

Doh...

CL-USER> (defvar *foo*)
*FOO*
CL-USER> (time (dotimes (i (* 2 824)) (setq *foo* (make-hash-table))))
; Compiling LAMBDA NIL:
; Compiling Top-Level Form:

; Evaluation took:
;   0.01 seconds of real time
;   0.004 seconds of user run time
;   0.002999 seconds of system run time
;   20,036,532 CPU cycles
;   0 page faults and
;   2,386,304 bytes consed.
;
NIL
CL-USER>


> I think the edges-from should be in the graph node output record.  I'm
> not entirely sure how to get at one of those, but you could start by
> inspecting clim:*application-frame* from the slime inspector, finding
> the listener interactor pane, finding its output history, and looking
> at the output records in there.

Here is the interactor's output history just after generating the
graph:

An object.
 [type: CLIM:STANDARD-TREE-OUTPUT-HISTORY]
--------------------
Class: #<STANDARD-CLASS CLIM:STANDARD-TREE-OUTPUT-HISTORY {5837B955}>
Slots:
STREAM = #3=#<CLIM:INTERACTOR-PANE CLIM-LISTENER::INTERACTOR {59E3C0DD}>
COORDINATES = #(0 0 4950 12357)
PARENT = NIL
X = 0
Y = 0
IN-MOVING-P = NIL
CHILDREN = #<SPATIAL-TREES-IMPL::R-TREE 
#<SPATIAL-TREES-PROTOCOL:SPATIAL-TREE-LEAF-NODE 
(#S(SPATIAL-TREES-IMPL::LEAF-NODE-ENTRY :RECTANGLE #<(81,24679/2) - 
(144,24709/2)> :DATUM #<CLIM-INTERNALS::TREE-OUTPUT-RECORD-ENTRY {58A7222D}>) 
#S(SPATIAL-TREES-IMPL::LEAF-NODE-ENTRY :RECTANGLE #<(81,12339) - (724,12357)> 
:DATUM #<CLIM-INTERNALS::TREE-OUTPUT-RECORD-ENTRY {59F0EA95}>) 
#S(SPATIAL-TREES-IMPL::LEAF-NODE-ENTRY :RECTANGLE #<(0,24679/2) - (81,24709/2)> 
:DATUM #<CLIM-INTERNALS::TREE-OUTPUT-RECORD-ENTRY {59F0DCD5}>) 
#S(SPATIAL-TREES-IMPL::LEAF-NODE-ENTRY :RECTANGLE #<(0,17) - (4950,24645/2)> 
:DATUM #<CLIM-INTERNALS::TREE-OUTPUT-RECORD-ENTRY {59D6D0D5}>) 
#S(SPATIAL-TREES-IMPL::LEAF-NODE-ENTRY :RECTANGLE #<(81,0) - (360,15)> :DATUM 
#<CLIM-INTERNALS::TREE-OUTPUT-RECORD-ENTRY {59D6D0C5}>) 
#S(SPATIAL-TREES-IMPL::LEAF-NODE-ENTRY :RECTANGLE #<(81,0) - (724,17)> :DATUM 
#<CLIM-INTERNALS::TREE-OUTPUT-RECORD-ENTRY {59D6D0A5}>) 
#S(SPATIAL-TREES-IMPL::LEAF-NODE-ENTRY :RECTANGLE #<(0,0) - (81,15)> :DATUM 
#<CLIM-INTERNALS::TREE-OUTPUT-RECORD-ENTRY {59D6D085}>))>>
CHILDREN-HASH = #5=#<EQL hash table, 7 entries {59E3DBA5}>
LAST-INSERTION-NR = 13

Where should I look further?


> expensive.  Can you do the same thing, but with the CLIM package
> profiled additionally?  (And then maybe one with CLIM but not
> CLIM-INTERNALS profiled?)  The first 10 or so entries in each profile
> will probably suffice.  (Maybe CLEAR-OUTPUT-RECORD is expensive?)

I include the results below.  Note, however, that I couldn't answer
yes to SLIME's question on whether to also profile methods, because
otherwise I get this error when issuing the `M-x slime-profile-report'
command:

Error in function PROFILE::PI-OR-LOSE:
   No profile info for (PCL:FAST-METHOD CLIM:PROCESS-NEXT-EVENT
                        (CLIM:BASIC-PORT))
   [Condition of type SIMPLE-ERROR]

Restarts:
  0: [ABORT-REQUEST] Abort handling SLIME request.
  1: [ABORT] Return to Top-Level.

Backtrace:
  0: (PROFILE::PI-OR-LOSE
      (PCL:FAST-METHOD CLIM:PROCESS-NEXT-EVENT (CLIM:BASIC-PORT)))
  1: (PROFILE::%REPORT-TIMES
      ((PCL:FAST-METHOD CLIM-INTERNALS::DEFAULT-COMPLETION-NAME-KEY #)
       (PCL:FAST-METHOD CLIM-INTERNALS::DEFAULT-COMPLETION-NAME-KEY #)
       (PCL:FAST-METHOD CLIM-INTERNALS::DEFAULT-COMPLETION-NAME-KEY #)
       (PCL:FAST-METHOD CLIM-INTERNALS::DEFAULT-COMPLETION-NAME-KEY #)
       (PCL:FAST-METHOD CLIM-INTERNALS::DEFAULT-COMPLETION-NAME-KEY #) ...)
      :PRINTFUNCTION NIL)
  2: ("DEFUN EVAL-FOR-EMACS")
  3: ((METHOD SWANK-BACKEND:CALL-WITH-DEBUGGER-HOOK NIL (T T)) #<#1=unused-arg>
      #<#1#> #<Function SWANK:SWANK-DEBUGGER-HOOK {5889D589}>
      #<Closure Over Function "DEFUN EVAL-FOR-EMACS" {5B1801A1}>)
  4: ("DEFUN HANDLE-REQUEST")
  5: ((METHOD SWANK-BACKEND:CALL-WITH-DEBUGGER-HOOK NIL (T T)) #<#1=unused-arg>
      #<#1#> #<Function SWANK:SWANK-DEBUGGER-HOOK {5889D589}>
      #<Function "DEFUN HANDLE-REQUEST" {585EB179}>)
 --more--


Paolo

========================================================================
PROFILED PACKAGES: CLIMI; CLIM (no methods)

     Consed |     Calls |   Secs | Sec/Call | Bytes/C. | Name:
-----------------------------------------------------------------------
609,294,888 |     2,021 | 17.476 |  0.00865 |  301,482 | 
CLIM:MAP-OVER-OUTPUT-RECORDS
                  1,132: #<Code Object "DEFMETHOD %TREE-RECOMPUTE-EXTENT* 
(COMPOUND-OUTPUT-RECORD)"
                           {58EB3847}>
                    828: #<Code Object "DEFMETHOD* (SETF 
OUTPUT-RECORD-POSITION)"
                           {58C0AF87}>
                     12: #<Code Object "DEFMETHOD COMPUTE-NEW-OUTPUT-RECORDS 
(STANDARD-UPDATING-OUTPUT-RECORD T)"
                           {58BA4677}>
                     12: #<Code Object "DEF-PROFILE-FWRAPPER 1" {1035F597}>
                     11: #<Code Object "DEFMETHOD INVOKE-UPDATING-OUTPUT 
(UPDATING-OUTPUT-STREAM-MIXIN T T T T T T)"
                           {58BA1007}>

136,259,960 |       290 |  4.179 |  0.01441 |  469,862 | 
CLIM-INTERNALS::MAP-OVER-TREE-OUTPUT-RECORDS
                    268: #<Code Object "LAMBDA (FWRAPPER)" {5A560007}>
                     13: #<Code Object "DEF-PROFILE-FWRAPPER 2" {104B4357}>
                      9: #<Code Object "DEF-PROFILE-FWRAPPER 3" {104C0147}>

    208,200 |         7 |  2.430 |  0.34714 |   29,743 | (PCL:FAST-METHOD
                                                          
CLIM-INTERNALS::EVENT-QUEUE-LISTEN-OR-WAIT
                                                          
(CLIM-INTERNALS::STANDARD-EVENT-QUEUE))
                      7: #<Code Object "DEFMETHOD STREAM-INPUT-WAIT 
(STANDARD-EXTENDED-INPUT-STREAM)"
                           {58ED7AC7}>

  2,142,376 |     3,881 |  0.312 |  0.00008 |      552 | 
CLIM:MAKE-BOUNDING-RECTANGLE
                  3,869: #<Code Object "DEFMETHOD* (SETF 
OUTPUT-RECORD-POSITION)"
                           {58B9F04F}>
                     12: #<Code Object "DEFMETHOD RESIZE-SHEET (BASIC-SHEET T 
T)"
                           {58C53267}>

  1,092,544 |     7,586 |  0.175 |  0.00002 |      144 | CLIM:MERGE-TEXT-STYLES
                  5,926: #<Code Object "DEFMETHOD 
DO-GRAPHICS-WITH-OPTIONS-INTERNAL (MEDIUM T T)"
                           {58C16657}>
                    827: #<Code Object "DEFMETHOD 
DO-GRAPHICS-WITH-OPTIONS-INTERNAL (MEDIUM T T)"
                           {58C16657}>
                    827: #<Code Object "DEFMETHOD 
DO-GRAPHICS-WITH-OPTIONS-INTERNAL (MEDIUM T T)"
                           {58C16657}>
                      3: #<Code Object "DEF-PROFILE-FWRAPPER 1" {1035F597}>
                      3: #<Code Object "DEFMETHOD INVOKE-WITH-TEXT-STYLE 
(MEDIUM T T)"
                           {58C4B19F}>

  2,167,264 |     1,246 |  0.108 |  0.00009 |    1,739 | 
CLIM:MEDIUM-DRAW-POLYGON*
                  1,217: #<Code Object "DEFMETHOD 
DO-GRAPHICS-WITH-OPTIONS-INTERNAL (MEDIUM T T)"
                           {58C16657}>
                     29: #<Code Object "DEFMETHOD 
MAP-OVER-OUTPUT-RECORDS-OVERLAPPING-REGION (T STANDARD-SEQUENCE-OUTPUT-RECORD 
T)"
                           {58C07007}>

  1,530,936 |     1,109 |  0.098 |  0.00009 |    1,380 | CLIM:DRAW-ARROW*
                  1,109: #<Code Object "DEFUN LAYOUT-EDGE-1" {5A6F4327}>

    907,424 |     1,109 |  0.098 |  0.00009 |      818 | 
CLIM:MAKE-ROTATION-TRANSFORMATION*
                  1,109: #<Code Object "DEF-PROFILE-FWRAPPER 1" {104A818F}>

  2,407,712 |     1,158 |  0.098 |  0.00008 |    2,079 | CLIM:MEDIUM-DRAW-LINE*
                  1,109: #<Code Object "DEFMETHOD 
DO-GRAPHICS-WITH-OPTIONS-INTERNAL (MEDIUM T T)"
                           {58C16657}>
                     49: #<Code Object "DEFMETHOD 
MAP-OVER-OUTPUT-RECORDS-OVERLAPPING-REGION (T STANDARD-SEQUENCE-OUTPUT-RECORD 
T)"
                           {58C07007}>
[...]
-------------------------------------------------------------------
782,665,592 | 2,348,996 | 26.619 |          |          | Total

1465 functions were not called.  See profile::*no-calls* for a list
========================================================================
PROFILED PACKAGES: CLIM (no methods)

     Consed |     Calls |   Secs | Sec/Call |   Bytes/C. | Name:
-----------------------------------------------------------------------
609,332,232 |     2,653 | 17.739 |  0.00669 |    229,677 | 
CLIM:MAP-OVER-OUTPUT-RECORDS
                  1,353: #<Code Object "DEFMETHOD %TREE-RECOMPUTE-EXTENT* 
(COMPOUND-OUTPUT-RECORD)"
                           {58E81007}>
                    828: #<Code Object "DEFMETHOD* (SETF 
OUTPUT-RECORD-POSITION)"
                           {58E7F60F}>
                    148: #<Code Object "DEFMETHOD COMPUTE-NEW-OUTPUT-RECORDS 
(STANDARD-UPDATING-OUTPUT-RECORD T)"
                           {58F0768F}>
                    148: #<Code Object "DEFMETHOD REDISPLAY-OUTPUT-RECORD 
(UPDATING-OUTPUT-RECORD UPDATING-OUTPUT-STREAM-MIXIN)"
                           {58F0CED7}>
                    137: #<Code Object "DEFMETHOD INVOKE-UPDATING-OUTPUT 
(UPDATING-OUTPUT-STREAM-MIXIN T T T T T T)"
                           {58D69007}>

  1,546,512 |       144 | 12.439 |  0.08638 |     10,740 | 
CLIM:STREAM-INPUT-WAIT
                    144: #<Code Object "DEFMETHOD STREAM-READ-GESTURE 
(STANDARD-EXTENDED-INPUT-STREAM)"
                           {58D52007}>

 11,474,312 |         1 | 12.200 | 12.20000 | 11,474,312 | 
CLIM:COMMAND-LINE-READ-REMAINING-ARGUMENTS-FOR-PARTIAL-COMMAND
                      1: #<Code Object "DEFUN ACCEPT-1" {5937D4F7}>

145,076,320 |     3,567 |  4.686 |  0.00131 |     40,672 | 
CLIM:MAP-OVER-OUTPUT-RECORDS-CONTAINING-POSITION
                  3,564: #<Code Object "DEFUN 
MAP-OVER-PRESENTATIONS-CONTAINING-POSITION"
                           {5A835BBF}>
                      3: #<Code Object "DEFINE-DEFAULT-PRESENTATION-METHOD 
PRESENTATION-REFINED-POSITION-TEST"
                           {58ED6A97}>

  1,034,544 |       145 |  0.319 |  0.00220 |      7,135 | 
CLIM:HIGHLIGHT-APPLICABLE-PRESENTATION
                    145: #<Code Object "DEFMETHOD STREAM-READ-GESTURE 
(STANDARD-EXTENDED-INPUT-STREAM)"
                           {58D52007}>

  3,077,808 |         7 |  0.190 |  0.02714 |    439,687 | CLIM:STREAM-ACCEPT
                      6: #<Code Object "DEFUN ACCEPT" {58438007}>
                      1: #<Code Object "DEFUN ACCEPT" {58438007}>

  5,562,064 |       823 |  0.187 |  0.00023 |      6,758 | 
CLIM:INVOKE-WITH-OUTPUT-TO-OUTPUT-RECORD
                    822: #<Code Object "DEFMETHOD GENERATE-GRAPH-NODES 
(STANDARD-GRAPH-OUTPUT-RECORD T T T T)"
                           {58D8025F}>
                      1: #<Code Object "DEFUN INVOKE-AND-CENTER-OUTPUT"
                           {58902B47}>

  4,623,008 |     1,246 |  0.165 |  0.00013 |      3,710 | 
CLIM:MEDIUM-DRAW-POLYGON*
                  1,217: #<Code Object "DEFMETHOD 
DO-GRAPHICS-WITH-OPTIONS-INTERNAL (MEDIUM T T)"
                           {58D3B007}>
                     29: #<Code Object "DEFMETHOD 
MAP-OVER-OUTPUT-RECORDS-OVERLAPPING-REGION (T STANDARD-SEQUENCE-OUTPUT-RECORD 
T)"
                           {58E84007}>

  1,698,080 |     1,109 |  0.156 |  0.00014 |      1,531 | CLIM:DRAW-ARROW*
                  1,109: #<Code Object "DEFUN LAYOUT-EDGE-1" {5A844B6F}>

  2,442,360 |     1,183 |  0.115 |  0.00010 |      2,065 | 
CLIM:MEDIUM-DRAW-LINE*
                  1,117: #<Code Object "DEFMETHOD 
DO-GRAPHICS-WITH-OPTIONS-INTERNAL (MEDIUM T T)"
                           {58D3B007}>
                     66: #<Code Object "DEFMETHOD 
MAP-OVER-OUTPUT-RECORDS-OVERLAPPING-REGION (T STANDARD-SEQUENCE-OUTPUT-RECORD 
T)"
                           {58E84007}>

    411,032 |         1 |  0.100 |  0.10000 |    411,032 | 
CLIM:LAYOUT-GRAPH-NODES
                      1: #<Code Object "DEFUN FORMAT-GRAPH-FROM-ROOTS"
                           {5AAAF737}>

  1,687,088 |         1 |  0.090 |  0.09000 |  1,687,088 | 
CLIM:LAYOUT-GRAPH-EDGES
                      1: #<Code Object "DEFMETHOD 
INVOKE-WITH-OUTPUT-RECORDING-OPTIONS (OUTPUT-RECORDING-STREAM T T T)"
                           {58DBD54F}>
[...]
-------------------------------------------------------------------
813,068,904 | 2,535,994 | 49.557 |          |            | Total

498 functions were not called.  See profile::*no-calls* for a list
========================================================================

-- 
Lisp Propulsion Laboratory log - http://www.paoloamoroso.it/log