[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
INTERN-LOCAL is the culprit
- To: DLW@alderaan.scrc.symbolics.com, dla@jasper.scrc.symbolics.com
- Subject: INTERN-LOCAL is the culprit
- From: "David E. Wilkins" <munnari!aaii.mu.oz.au!wilkins@uunet.uu.net>
- Date: Mon, 4 Jul 88 14:30:00 EDT
- Cc: munnari!dew@uunet.uu.net, tyson@WARBUCKS.AI.SRI.COM
- Character-type-mappings: (1 0 (NIL 0) (NIL :BOLD NIL) "CPTFONTCB") (2 0 (NIL 0) (NIL :ITALIC NIL) "CPTFONTI") (3 0 (NIL 0) (:FIX :BOLD :LARGE) "MEDFNTB") (4 0 (NIL 0) (:FIX :ITALIC :LARGE) "MEDFNTI") (5 0 (NIL 0) (:FIX :EXTRA-CONDENSED :NORMAL) "CPTFONTCC")
- Fonts: CPTFONT, CPTFONTCB, CPTFONTI, MEDFNTB, MEDFNTI, CPTFONTCC
- Resent-date: Wed, 6 Jul 88 06:31:30 EDT
- Resent-from: David Wilkins <munnari!munmurra.mu.oz.au!dew@uunet.uu.net>
- Resent-message-id: <8807060041.AA04361@uunet.UU.NET>
- Resent-to: pmartin@WARBUCKS.AI.SRI.COM, slug@WARBUCKS.AI.SRI.COM
Date: Sun, 3 Jul 88 09:52 EDT
From: Daniel L. Weinreb <DLW@ALDERAAN.SCRC.Symbolics.COM>
It occurred to both DLA and me that your use of INTERN might possibly
have something to do with the performance results you're seeing. INTERN
creates a new element in a hash table. When the table gets past certain
thresholds, it has to be grown, and all the elements have to be
reinserted at their new locations. This, as you can see, is a
"nonlinear" sort of phenomenon: whether a given run of your program
causes a rehash or not depends on exactly how full the hash table was
before you started, and it might explain why running the program many
times would take wildly different amounts of time on each run. A simple
experiment would be to run the program under Function Call metering, or
Statistical Function Call metering, several times, and see how much time
is being spent in INTERN. (Actually, the best thing would be to run it
under metering several times and simply compare the successive metering
results and see how they vary from run to run.) We'd be very interested
to hear the results of this experiment.
Thanks for figuring this our for me. INTERN is definitely the problem.
The following function was in the code that took 70 sec (+- 50) to run in 7.2:
(defun 1GSYM1 0(x)
(setq x (string (gensym x)))
(or (scl:intern-local-soft x)
(scl:intern-local x)))
;2call 0scl:intern-local-soft2 in case gensym generates things that are already interned (as it has)
0;2then don't try intern-local on them as it takes forever
0;2using names twice shouldn't screw up automatic generation of a plan ---
0;2 will only affect debugging and communication with user that uses these names (eg in interactive
0;2 planning or execution monitoring)
0I replaced this with (defun gsym1 (x) 'x1) and ran the same problem thru
several times. The ETIMES in 7.2 were (to nearest second) 20,24,25,20,33,20,25.
Except for the 33, this is pretty consistent, and a time I am quite happy with.
I did the same in 7.1 and got nearly identical ETIMES. So it is definitely
these interns that caused 7.2 to take an extra 50 seconds.
I generated the following with the metering code. However this is the first
time I have ever used it, and I do not really know what I am doing. There are
3 runs where I metered all the function calls to GSYM1 (original long version)
in 7.2. The first two are the exact original problem. In the third run I
changed the caller to only call GSYM1 for one type of node. Average inclusive
time for intern-local varied from 10 to 43 milliseconds. The elapsed time for
the 2 identical runs was double in one case. Let me know if you
would like me to run any other metering experiments for you.
Since this works so poorly, what is the preferred way in 7.2 to generate names
for thousands of created sturctures in such a way that the user can quickly and
easily type these names back during later interaction?
Thanks, David Wilkins
I'd appreciate it if you could send replies both to "wilkins@ai.sri.com"
and "wilkins@aaii.oz.au". We are trying to debug the second address and
it is not guaranteed to work. Thanks.
run took 606 seconds:
3Metering (7/04/88 18:08:04) FUNCTION-CALL in Dynamic Lisp Listener 14 (GSYM1)
5 Calls Incl Time Excl Time Excl Consing Excl PS time Function
Count Total %Run Avg Total Total Total
-------------------------------------------------------------------------------------------------------------
1443 37473179 95.14% 25968.94 60475 0 0 GSYM1
1443 26280615 66.72% 18212.48 52945 0 3072 SCL:INTERN-LOCAL
1443 25480411 64.69% 17657.94 14174973 0 5120 SI:SHADOW-INTERNAL
331 11862558 30.12% 35838.54 9130 0 0 SI:MAYBE-PREEMPT-CURRENT-PROCESS
331 11853428 30.09% 35810.96 11835194 0 29696 SCL:STACK-GROUP-RESUME
1443 8074185 20.50% 5595.42 51028 0 0 GENSYM
1443 7885991 20.02% 5465.00 100449 0 0 CLI::GENERATE-SYMBOL-NAME
4420 6570608 16.68% 1486.56 56092 0 2048 SYS:%ALLOCATE-BLOCK
2946 5871144 14.91% 1992.92 577692 0 1024 SI:%ALLOCATE-STRUCTURE-BLOCK-ESCAPE
29 5115337 12.99% 176390.94 4170536 0 1403904 SI:%GC-SCAVENGE
2886 5043308 12.80% 1747.51 218624 41847 33792 SI:SIMPLE-MAKE-ARRAY-TYPE-AREA
4329 3607640 9.16% 833.37 185920 0 1024 SI:FIND-SYMBOL-LOCAL
4329 3047092 7.74% 703.88 2997844 0 2744320 SI:PKG-INTERN-INTERNAL
1443 2999515 7.62% 2078.67 23266 0 0 SCL:INTERN-LOCAL-SOFT
4329 2631444 6.68% 607.86 141545 0 4096 MAKE-SYMBOL
0run took 360 seconds:
3Metering (7/04/88 17:20:03) FUNCTION-CALL in Dynamic Lisp Listener 14 (GSYM1)
5 Calls Incl Time Excl Time Excl Consing Excl PS time Function
Count Total %Run Avg Total Total Total
-------------------------------------------------------------------------------------------------------------
1443 18606542 93.38% 12894.35 55970 0 0 GSYM1
1443 15659225 78.59% 10851.85 54302 0 0 SCL:INTERN-LOCAL
1443 15023158 75.40% 10411.06 10711498 0 2048 SI:SHADOW-INTERNAL
216 2451355 12.30% 11348.87 7453 0 0 SI:MAYBE-PREEMPT-CURRENT-PROCESS
216 2443902 12.27% 11314.36 2437059 0 5120 SCL:STACK-GROUP-RESUME
4329 2424947 12.17% 560.16 211024 0 67584 MAKE-SYMBOL
4329 2152672 10.80% 497.27 174744 0 47104 SI:FIND-SYMBOL-LOCAL
4380 2063536 10.36% 471.13 56928 0 3072 SYS:%ALLOCATE-BLOCK
4329 1669983 8.38% 385.77 1621286 0 1253376 SI:PKG-INTERN-INTERNAL
2910 1652564 8.29% 567.89 513984 0 1024 SI:%ALLOCATE-STRUCTURE-BLOCK-ESCAPE
1443 1586068 7.96% 1099.15 23662 0 0 SCL:INTERN-LOCAL-SOFT
1443 1240244 6.22% 859.49 44144 0 0 GENSYM
4329 1223385 6.14% 282.60 88742 21645 1024 SI:%MAKE-STRUCTURE
12 1093196 5.49% 91099.66 971581 0 423936 SI:%GC-SCAVENGE
2886 1093033 5.49% 378.74 673636 0 32768 Method (METERING:ENABLE-METERING METERING:PER-PROCESS-CONTROL-MIXIN)
2886 1000851 5.02% 346.80 307314 16317 134144 SI:SIMPLE-MAKE-ARRAY-TYPE-AREA
0run took 158 seconds:
This run done when gsym1 called on only a small subset of nodes. Avg time in gysm1 much higher.
3Metering (7/04/88 17:55:36) FUNCTION-CALL in Dynamic Lisp Listener 14 (GSYM1)
5 Calls Incl Time Excl Time Excl Consing Excl PS time Function
Count Total %Run Avg Total Total Total
-------------------------------------------------------------------------------------------------------------
176 9573026 97.39% 54392.19 7997 0 1024 GSYM1
176 7634155 77.66% 43375.88 21122 0 13312 SCL:INTERN-LOCAL
176 7421951 75.51% 42170.18 1533707 0 0 SI:SHADOW-INTERNAL
176 4168867 42.41% 23686.74 5935 0 0 SI:PKG-NEW-SYMBOL-INTERNAL
7949 4155455 42.27% 23610.54 3453972 0 2877440 SI:PKG-NEW-SYMBOL
1 3958266 40.27% 3958266.00 238883 0 1024 SI:PKG-REHASH
33 2194775 22.33% 66508.34 727 0 0 SI:MAYBE-PREEMPT-CURRENT-PROCESS
33 2194048 22.32% 66486.30 2192997 0 5120 SCL:STACK-GROUP-RESUME
528 1224719 12.46% 2319.54 23183 0 0 SI:FIND-SYMBOL-LOCAL
528 1179030 11.99% 2233.01 1173075 0 1118208 SI:PKG-INTERN-INTERNAL
176 1159428 11.80% 6587.66 3496 0 0 SCL:INTERN-LOCAL-SOFT
176 756739 7.70% 4299.65 6003 0 0 GENSYM
554 685746 6.98% 1237.81 6325 0 0 SYS:%ALLOCATE-BLOCK
369 652663 6.64% 1768.73 209896 0 0 SI:%ALLOCATE-STRUCTURE-BLOCK-ESCAPE
528 633470 6.44% 1199.75 42254 0 25600 MAKE-SYMBOL