DOSTATS The Interlisp-D system has a facility for gathering very low-level statistics on function call and return. It is conceptually like performing a {fn 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. {FnDef {Name DOSTATS} {Args FORM TITLE {anonarg} {anonarg} {anonarg}} {Text Collects statistics of the evaluation of {arg FORM} and produces a listing of the results. {arg TITLE}, if supplied, will appear in the heading of the listing. }} Performing a statistics run consists of three phases: {Begin LabeledList three phases of Performing a statistics run} {Indent 5percent} {Max 0} {Label Gathering} {Text The microcode is instructed to emit a statistics event for every function call and return that is executed, and {arg FORM} is evaluated. These events are collected on a file for the next phase (the name of the file is {lisp {bracket DSK}{arg XXX}.STATS}, where {arg XXX} = {lisp (CAR {arg FORM})}). Currently the file must reside on {lisp {bracket DSK}}, 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 {lisp SWAT}). } {Label Analysis} {Text 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. } {Label Summarizing} {Text 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 {lisp {arg XXX}.PRINTOUT} on the connected directory and also shipped to your local printer. } {End LabeledList three phases of Performing a statistics run} Excerpts from a sample statistics printout are shown below, with commentary. The form is {lisp (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 {lisp FOO} calls {lisp FIE}, the time spent inside {lisp FIE} is charged to {lisp FIE} only, not to {lisp 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. {note an example with recognizable fn names, would be better} {note redo after stats package is reworked ---rrb} {Begin LispCode}Statistics from file: {bracket 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) {it (Internal version numbers of microcode, Lisp.run, Lisp.sysout)} Unrecognized events: NIL {it (everything was okay)} Values from MiscStats (times in msecs): SWAPWAITTIME 6137 PAGEFAULTS 58 GCTIME 27392 Not Windowing Filtering out \StackOverflow, \NWWInterrupt, \PageFault, \StatsOverflow {it (time for these functions measured separately)} Ignoring time for GETKEYS, \GETKEY, WAITFORINPUT, DISMISS, GATHERSTATS, \GATHERSTATS, RAID {it (time for these functions ignored completely)} Function timings: #ofCalls PerCall {it total time spent in function (microseconds)} | {it percentage of total analyzed time spent in function} | | {it function name. Number of arguments in brackets} | | | {it number of calls recorded to this fn} | | | | {it 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 {it (functions contributing less than .1% are omitted)} 4840173 Total for 31 entries 5511 Function timings: Filtered out fns #ofCalls PerCall {it (times for functions whose contribution was omitted from the analysis above)} 20225828 70.32% Subr.\StatsOverflow [0] 413 48972 {it (stats overhead)} 6900042 23.99% Subr.\PageFault [1] 58 118966 {it (pagefault activity)} 1635737 5.68% Subr.\NWWInterrupt [0] 762 2146 {it (periodic service)} 28761607 Total for 3 entries 1291 Function timings: Alphabetic #ofCalls PerCall {it (listing as above, but including all functions, and sorted alphabetically)} . . . Call Information: {it (Alphabetic listing of functions, with calls and callers information)} {it (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) . . . {End LispCode} }{End SubSec Gathering Statistics} ‡GACHA ‡z¸