1 LISP LIBRARY PACKAGES MANUAL 1 LISP LIBRARY PACKAGES MANUAL PCALLSTATS 1 PROGRAM ANALYSIS 1 PCALLSTATS 6 The Interlisp-D system has a facility for gathering very low-level statistics on function call and return. It is conceptually like performing a BREAKDOWN on every function in the world. The system designers regularly use this facility to determine where time is being spent in suspect computations, suggesting which parts of the system code deserve optimizing. (DOSTATS FORM TITLE) [Function] Collects statistics of the evaluation of FORM and produces a listing of the results. TITLE, if supplied, will appear in the heading of the listing. Performing a statistics run consists of three phases: label gathering, label analysis, and label summarizing. 2 Label Gathering 1 The microcode is instructed to emit a statistics event for every function call and return that is executed, and FORM is evaluated. These events are collected on a file for the next phase (the name of the file is DSK XXX.STATS, where XXX =(CAR FORM)). Currently the file must reside on disk, so be sure you have a lot of space. Even seemingly short computations can generate large numbers of function call/return events. If your disk fills up, Lisp may not recover gracefully (it usually falls into SWAT). 2 Label Analysis 1 The statistics file is read in. For each event, a counter associated with the indicated function is incremented by the amount of time spent in the function. The analysis also records who called which functions, how often, and with how many arguments. This is by far the longest phase. 2 Label Summarizing 1 The results of the analysis are used to produce a listing that shows each of the functions called, sorted by their contribution to the total time, and a cross-reference of who called whom. The listing is put on a file XXX.PRINTOUT on the connected directory and also shipped to your local printer. Excerpts from a sample statistics printout are shown below, with commentary. The form is (RECLAIM), which was fairly brief in this case. Notes The times shown in the printout are for time spent in a single function; there is no cumulative time measurement. The percentages should thus add up to 100%. If FOO calls FIE, the time spent inside FIE is charged to FIE only, not to FOO as well. The times recorded are of the right order of magnitude, and can be compared to each other, but should not be taken literally, as they are inflated by the overhead of recording each call and return event. The total elapsed time for the evaluation phase is much larger still, being dominated by the time to dump the statistics to disk, but this part of the time is filtered out in the analysis. Statistics from file: {DSK}RECLAIM.STATS;1 measuring: evaluation of FORM = (RECLAIM) Computation run on Dolphin serial #237 with 2304 pages of memory. Versions:Ram=7401(17,1)Bcpl=17400(37,0) Lisp=106000(214,0) (internal version numbers of microcode, Lisp.run, Lisp.sysout) Unrecognized events: NIL (everything was okay) Values from MiscStats (times in msecs): SWAPWAITTIME 6137 PAGEFAULTS 58 GCTIME 27392 Not Windowing Filtering out \StackOverflow, \NWWInterrupt, \PageFault, \StatsOverflow (time for these functions measured separately) Ignoring time for GETKEYS, \GETKEY, WAITFORINPUT, DISMISS, GATHERSTATS, \GATHERSTATS, RAID (time for these functions ignored completely) Function timings: #ofCalls PerCall total time spent in function (microseconds) | percentage of total analyzed time spent in function | | function name. Number of arguments in brackets | | | number of calls recorded to this fn | | | | avg time per call (microseconds) 1746426 36.08% \GCMAPTABLE [1] 524 3332 1104420 22.81% \GCMAPSCAN [0] 1 1104420 794862 16.42% \HTFIND [2] 1236 643 461194 9.52% \FREELISTCELL [1] 2044 225 457537 9.45% \GCRECLAIMCELL [1] 1533 298 77437 1.59% \GCMAPUNSCAN [0] 1 77437 52907 1.09% RELEASINGVMEMPAGE [1] 30 1763 47308 0.97% \GCSCANSTACK [0] 1 47308 45365 0.93% FINDPTRSBUFFER [2] 30 1512 9218 0.19% \ADDBASE [2] 31 297 7618 0.15% CREATECELL [1] 18 423 7428 0.15% \INSERTBLOCK [1] 31 239 6856 0.14% \RECLAIMARRAYBLOCK [1] 31 221 21597 0.44% for 18 entries not shown (functions contributing less than .1% are omitted) 4840173 Total for 31 entries 5511 Function timings:Filtered out fns #ofCalls PerCall (times for functions whose contribution was omitted from the analysis above) 20225828 70.32% Subr.\StatsOverflow [0] 413 48972 (stats overhead) 6900042 23.99% Subr.\PageFault [1] 58 118966 (pagefault activity) 1635737 5.68% Subr.\NWWInterrupt [0] 762 2146 (periodic service) 28761607 Total for 3 entries 1291 Function timings: Alphabetic #ofCalls PerCall (listing as above, but including all functions, and sorted alphabetically) . . . Call Information: (Alphabetic listing of functions, with calls and callers information) (number of calls in parentheses) CLOCK Calls: MAKENUMBER (8), \SLOWIPLUS2 (6),CLOCK(2), CREATECELL (2), CLOCK0 (2), \SLOWIDIFFERENCE (2) Callers: \DORECLAIM (2), CLOCK (2) CLOCK0 Callers: CLOCK (2) CREATECELL Calls: \HTFIND (1) Callers: MAKENUMBER (16), CLOCK (2) . . . (LIST ((PAGE NIL (PAPERSIZE Letter FOLIOINFO (ARABIC ) STARTINGPAGE# 370) (0 0 612 792) ((FOLIO NIL (PARALOOKS (QUAD LEFT) CHARLOOKS (SUPERSCRIPT 0 INVISIBLE OFF SELECTPOINT OFF PROTECTED OFF SIZE 10 FAMILY MODERN OVERLINE OFF STRIKEOUT OFF UNDERLINE OFF EXPANSION REGULAR SLOPE REGULAR WEIGHT MEDIUM INVERTED OFF USERINFO NIL STYLE NIL) FORMATINFO (ARABIC )) (54 12 288 36) NIL) (HEADING NIL (HEADINGTYPE FOOTINGV) (54 27 558 36) NIL) (HEADING NIL (HEADINGTYPE VERSOHEAD) (54 762 558 36) NIL) (TEXT NIL NIL (54 54 504 618) NIL))) (PAGE NIL (PAPERSIZE Letter FOLIOINFO (ARABIC )) (0 0 612 792) ((FOLIO NIL (PARALOOKS (QUAD LEFT) CHARLOOKS (SUPERSCRIPT 0 INVISIBLE OFF SELECTPOINT OFF PROTECTED OFF SIZE 10 FAMILY MODERN OVERLINE OFF STRIKEOUT OFF UNDERLINE OFF EXPANSION REGULAR SLOPE REGULAR WEIGHT MEDIUM INVERTED OFF USERINFO NIL STYLE NIL) FORMATINFO (ARABIC )) (558 12 288 36) NIL) (HEADING NIL (HEADINGTYPE FOOTINGR) (54 27 558 36) NIL) (HEADING NIL (HEADINGTYPE RECTOHEAD) (54 762 558 36) NIL) (TEXT NIL NIL (54 54 504 684) NIL))) (PAGE NIL (PAPERSIZE Letter FOLIOINFO (ARABIC )) (0 0 612 792) ((FOLIO NIL (PARALOOKS (QUAD LEFT) CHARLOOKS (SUPERSCRIPT 0 INVISIBLE OFF SELECTPOINT OFF PROTECTED OFF SIZE 10 FAMILY MODERN OVERLINE OFF STRIKEOUT OFF UNDERLINE OFF EXPANSION REGULAR SLOPE REGULAR WEIGHT MEDIUM INVERTED OFF USERINFO NIL STYLE NIL) FORMATINFO (ARABIC )) (54 12 288 36) NIL) (HEADING NIL (HEADINGTYPE FOOTINGV) (54 27 558 36) NIL) (HEADING NIL (HEADINGTYPE VERSOHEAD) (54 762 558 36) NIL) (TEXT NIL NIL (54 54 504 684) NIL))))).ÌÌøø1Ìêøêø1ÌÌøêø.ÌÌøø.ÌÌøø.øø.øø.ø2ø.ÌÌø ø.ÌÌø ø.øø.øø.ø2ø.ÌÌøø.ÌÌøøBøø PAGEHEADING VERSOHEADBøø PAGEHEADING RECTOHEADAøø PAGEHEADINGFOOTINGVAøø PAGEHEADINGFOOTINGR(TERMINAL MODERNMODERN MODERNMODERN GACHA  HRULE.GETFNMODERN  HRULE.GETFNMODERN   HRULE.GETFNMODERN  HRULE.GETFNMODERN   HRULE.GETFNMODERN  k  )):o  HRULE.GETFNMODERN    HRULE.GETFNMODERN  oe  HRULE.GETFNMODERN    HRULE.GETFNMODERN    HRULE.GETFNMODERN  HRULE.GETFNMODERN ½MŠüŠ+B;?($$$H,\+%- 30*#/!/.+1,01/000/3'0.3J:98.8HC32% &Ÿ zº