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�	VERSOHEAD���������������B����ø��������ø�������PAGEHEADING�	RECTOHEAD���������������A����ø������ø�������PAGEHEADING�FOOTINGV���������������A����ø������ø�������PAGEHEADING�FOOTINGR���������������(��������������������������������������������TERMINAL�
����������MODERN����������MODERN�
���������MODERN����������MODERN�
����������GACHA�
�������������������HRULE.GETFN��MODERN�
���������������������������������������HRULE.GETFN��MODERN�
����������������������������������������������������HRULE.GETFN��MODERN�
���������������������������������������HRULE.GETFN��MODERN�
���������������������������������������������������������
����������������������HRULE.GETFN��MODERN�
���������������������	��k�������������
�������
��������������������)��������������)��������������:�������������o����������
�����HRULE.GETFN��MODERN�
���������������������������������������HRULE.GETFN��MODERN�
���������������������
���o��������������e��������������������������������������������������
�����HRULE.GETFN��MODERN�
����������������������������������������������HRULE.GETFN��MODERN�
���������������������	�� ���������������HRULE.GETFN��MODERN�
���������������������������������������HRULE.GETFN��MODERN���������������������	���½���������������������������M�������������Š��������������������������ü������������Š�������������+���������������������������������������B�������������;�������������?�������������������������������������������������������������������(�������������$�������������$�������������$��������������������������H��������������������,���������������������������������\��������������������+��������������������%�������������-��������������������
�������3���������������������������0��������������������*�������#��������������������/�������!���������������������������/�������������.�������������+�������������1�������������,�������������0�������������1�������������/�������������0�������������0�������������0�������������/�������������3�������������'���������������������������0��������������������.�������������3��������������������J��������������������:����������������������������������������9����������������������������������������8����������������������������������������.�������������8��������������������H�����������������������������������������������������C�������������������������������������������������������������������������3�������������2�������������%�����������������������������������������������������������������&��������������������������������������Ÿzº