Fwd: Re: [mcclim-devel] Severe performance regression with latest CVS sources?
Paolo Amoroso
amoroso at mclink.it
Sun Apr 16 15:03:13 UTC 2006
Christophe Rhodes <csr21 at cam.ac.uk> 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
More information about the mcclim-devel
mailing list