.c 11:06am  Thursday, 7 October 1982 -*- Bolio -*-

.chapter "Debugging and Metering"

.section "Flow of Control"

.subsection "Tracing"

.defmac trace trace-spec-1 trace-spec-2 ...
3trace* enables one to trace see when and how a function gets
called, and to see what values it returns.  A 2trace-spec* may be
either a function name, or a list of a function name and some keyworded
arguments.  Neither the trace specs nor the keyworded arguments are
evaluated.  For example,
.lisp
(defun fact (x)
  (if (zerop x) 1 (* x (fact (1- x)))))
(trace fact)
  =>  (fact)
(fact 3)
2produces the output, on 3*trace-output**:*
 >>TRACE: enter fact [1], arg = 3.
 >>TRACE: enter fact [2], arg = 2.
  >>TRACE: enter fact [3], arg = 1.
   >>TRACE: enter fact [4], arg = 0.
   >>TRACE: exit  fact [4], value = 1.
  >>TRACE: exit  fact [3], value = 1.
 >>TRACE: exit  fact [2], value = 2.
 >>TRACE: exit  fact [1], value = 6.
.end_lisp

There is only one option currently supported:  this is 3:break*.
The argument to the 3:break* option is evaluated [in the current
lexical environment] when the function is called;  if the result of this
evaluation is 3nil*, then the traceing is simply printed, as above.
If it is 2not* 3nil*, then the lan{nil} debugger is entered,
showing the function call.  The debugger will also be entered when the
function exits, and the values being returned will be displayed.
Typically the "argument" to 3:break* is simply 3t*, as in
.lisp
(trace (fact :break t))
.end_lisp
When the debugger is entered due to tracing a function, it does not
display the special proceed commands;  however, (as always) they may be
listed with the c-m-Q debugger command.  The c-m-Z debugger command will
always be assigned such that it will resume program execution.

3(trace)* returns the status of everything which is currently
traced.  (Currently, redefining a function untraces it by virtue of
overwriting the traced definition.  This will not always be the case.
However, when this happens, 3(trace)* still thinks the function is
traced, although tracing it again or untracing it will recognize what
has happened.)

In lan{nil}, one may trace not only functions (defined with
3defun*), but also macros and special forms.  When a special form is
traced, you are shown that it is a special form, the entire form, and
the value(s) returned on exit.  When a macro is traced, you are shown
that the trace is for a macro, and shown the result of the macro
expansion.  Note, however, that there is usually term_i{macro
cacheing} going on, meaning that the macro expansion for the same form
might not be recomputed every time that form is evaluated, but
remembered for later.  As a result, one may not see the expansion
occuring on every evaluation (but only on the first).  Evaluating
3(flush-macromemos)* will cause 2all* remembered macro
expansions in the lan{nil} to be invalidated, so may be useful in this
case.  Also, there are a number of special forms in lan{nil} which are
implemented as both special forms and also as macros, and in some
contexts the macro might be used in order to do code analysis of the
form (3setf* and its friends do this), 2and* the special form
might be evaluated -- both of these will show up in the trace, modulo
the macro cacheing mentioned.
.end_defmac

.defmac untrace function-1 function-2 ...
3(untrace)* undoes tracing for all functions currently traced, and
returns a description of what had been traced.
3(untrace 2function-1* 2function-2* ...)* undoes tracing
for just those functions.

3untrace*, if it attempts to untrace a function that is not
currently traced (possibly because of redefinition as noted under
3trace*) will print a message to that effect, but will not error.
.end_defmac

.subsection "Who does What, and Where"

.defun who-calls symbol &optional &key (type :function)
This searches all compiled-code modules to find those which reference
the 2type* value-cell of 2symbol*.  2type* may take on the
values 3:function*, 3:value*, 3:local-function*, or
3:local-value*.  It defaults to 3:function*, thus finding all
modules which call the function 2symbol*.  A 2type* of
3:value* would find all those modules which referenced
2symbol* as a special variable.  3:local-function* and
3:local-value* (which should probably be called 3:lexical-* anyway)
aren't actually useful;  they would only find uses where the
references were not compiled away, and all local references are in the
current compiler.

Someday this should be smart enough to do searching through all
defined functions, including interpreted ones.
.end_defun

.defun whereis function
2function* should be a symbol or a compiled-function.
3whereis* returns the compiled-code module (the module-object)
which defines 2function*, or (false) if that cannot be
determined.  It can only determine this for compiled functions.

Someday (i keep saying that don't i) there will be a more general
mechanism, so that the source file can be determined for all "defined
objects", such as those defined with 3defvar*, 3defstruct*,
3defmacro*, etc.  Until then, note the following function:
.end_defun

.defun si:module-source-file module
This returns the name of the source file for the module 2module*.
The current implementation does this by looking at the vasl file from
which 2module* was loaded, so that file must exist on disk (with
the same name).
.end_defun

.defun apropos string &optional (pkg *package*)
This searches through 2pkg* and all of its super-packages (see
(package-section-page)), and prints out those symbols it finds which
have 2string* as a substring.  For each of these, it also prints
some information about whether the symbol is defined as a function,
bound as a variable, etc.  3apropos* returns no values.
.end_defun

.defun apropos-list string &optional (pkg *package*)
This returns a list of all symbols in 2pkg* (and its super-packages)
which contain 2string* as a substring of their names.
.end_lisp

.defun si:apropos-generate fn arg &optional (pkg *package*) (superiors t)
This function maps the function 2fn* over all symbols which
contain 2arg* (a string or symbol) as a substring, in the package
2pkg* (and its superiors, if 2superiors* is not 3nil*).
3si:apropos-generate* uses 3mapatoms* ((mapatoms-fun));  it
is possible that 2fn* could be called on the same symbol more than
once, although that will not happen very often in the current
lan{nil} implementation.

The 3apropos-list* function is defined using this, by
.lisp
(defvar *apropos-list*)
(defun apropos-list (string &optional package?)
  (let ((*apropos-list* ()))
    (si:apropos-generate
      #'(lambda (x) (push x *apropos-list*))
      string package?)
    *apropos-list*))
.end_lisp
One could write variants of this which test the symbol for specific
properties, or with 3boundp* or 3fboundp*, and which print the
results as they are computed rather than accumulating them in a list.
.end_defun

.section "Examining Objects"

.defun inspect object
.defun1 exhibit object
Invokes an interactive structure editor on the object. There is a "?"
command to print out a command menu. The object is sent any of the
following messages, 3:exhibit-self*, 3:select-nth*,
3:store-nth*.  See the definitions for built-in objects in
"[NIL.SRC]EXHIBI.LSP".

Warning!  The exhibitor is used quite a bit in lan{nil} system
debugging.  As a result, it often will permit one to perform
modifications which are normally considered illegal.  More generally,
one must be careful not to modify datastructures in such a way as to
leave things in an inconsistent state;  things like the flavor structure
do quite a bit of bookkeeping and cacheing of information, with the
result that simply modification of the structure is bound to be
incorrect.
.end_defun

.defun describe object
Says a few things about the object.  3describe* returns no values.
.end_defun


.section "The Debugger"

This version of lan{nil} contains a completely new, and much nicer,
debugger.  The debugger may be explicitly invoked from Lisp code by
calling the fun_i{break} function ((break-fun)).

The single most important in the debugger is "?".  Because the debugger
is so important in the runtime environment, it comes supplied with a
fair amount of interactively available documentation.  The current
documentation supplied
is a quick job which will be replaced at some point, but it at least
permits enumeration of the various debugger commands by category.

One debugger command which should be kept in mind is c-m-Q (the
documentation offered interactively describes how characters with these
extra modifier bits may be typed).  This lists the commands which are
specific to the particular error and context.  While this list is
normally printed for errors, when the debugger is entered "more
routinely", such as due to 3step* or 3trace*, this list is
omitted for brevity.


.section "Metering"

.subsection "Timing"

.defmac time form
This is a lan{common lisp} macro for timing the evaluation of
2form*.  2form* is evaluated once, and some information about
the amount of time the evaluation took is printed (to
3*trace-output**).  3time* is a macro, and the code it expands
permits the compilation of a call to 3time* to compile the
2form* properly.  This construct is not accurate enough to time
things which only take a little time, unless they are done in a loop
(compiled) inside the 2form*.
.end_defmac

.defun timer function &optional (loops 1) arguments
Calls 2function* with arguments 2arguments* (a list or simple
vector), 2loops* times, and prints out information on how
much time was taken.  Try, for example,
.lisp
(timer #'cons 100 #(a b))
.end_lisp
Needs some improvement to deal with function-calling and loop
overhead;  for that reason, this is not too useful with short fast
functions.
.end_defun

There is another qualification which must be made about pagefaults and
timing under VMS.  If one attempts to do a timing of something which is
not too large a large number of times, with the result that there is a
moderate amount of compute time and only a small amount of memory
referenced, then depending on the system generation parameter PFRATL,
VMS might reduce the NIL's working set drastically.  While this does not
affect the basic timing, what happens is that the code 2outside* the
loop (including the code which reads the various times) becomes totally
paged out and may add substantial overhead to the timing due to paging.

lan{Common-lisp} defines two functions for obtaining compute and
elapsed time.  Both return integers in the same units, which can
2not* be assumed to be fixnums.  These units are units of
term_i{internal time}, which cannot be depended on to be the same
in different lan{common lisp} implementations.  They may even differ
from one lan{nil} release to another.

.defconstant internal-time-units-per-second
This is an integer which is the number of "tics" of internal time per
second.  It happens that in lan{nil} this is 3100*, because that
is all the accuracy which lan{vms} provides at the moment.  It could
change in the future, and its value should not be depended on.
.end_defconstant

.defun get-internal-run-time
This returns the "run time" of the lan{nil} process in
3internal-time-units-per-second* units.
.end_defun

.defun get-internal-real-time
This returns a measure of elapsed time in
3internal-time-units-per-second* units.  The time-base for this
time measurement may not be depended on;  only differences between the
values of two successive calls should be used for anything.
.end_defun

.defun runtime
This is the old name for 3get-internal-run-time*.  While it is the
same name as the lan{maclisp} function, it is incompatible--the
lan{nil} runtime function returns the run time in units of
hundredths of a second.
.end_defun

.defun elapsed-time
3elapsed-time* returns a measurement of elapsed time, in seconds, as a
double-float.  Two such quantities may be compared to determine
elapsed time.  The origin of this number may not be depended upon;  in
lan{maclisp} it is the "system uptime"; in lan{nil} it happens to
be the double-float representation of the number of seconds since the
origin of the Smithsonian time standard (local time).  This
quantity is only really accurate to hundredths of a second, even
though it is potentially accurate to 100-nanosecond tics.
.end_defun

.defun si:pagefault-count
This returns the number of pagefaults taken by the process since
process creation.  Although this number is interesting to look at to
see if the lan{nil} is thrashing, it must be taken with several
grains of salt due to the way lan{vms} paging/swapping is performed.
2[The following discussion should perhaps be somewhere else, under
"performance considerations"?]*

The following points are especially of note.  First, this number does
not count the number of faults taken which involved fetching a page
from the pagefile (or shared image file).  Rather, it includes those
"faults" for pages which still reside in physical memory, but are just
not contained within the working set.  Also, the overhead of doing
this paging is charged to the process runtime.

Presumably, then, if one sets the working-set extent (the process
parameter/user quota 7WSEXTENT*) high, then the actual working set
in use will approach the number of pages of the job which are resident
in physical memory, and the count of pagefaults will better
approximate the number of pagefaults for non-resident pages.
.end_defun

Note also the 3room* function, which verbosely describes the
virtual memory usage of the lan{nil}, including the size of the
living heap (i.e., how much consing has been going on).

The lan{maclisp}-compatible mac_i{status} macro provides a
3gctime* option which returns the runtime (in the same units as
3runtime* does) which is the contribution to the process runtime
by the garbage-collector.  This is currently, of course, always zero.
When the garbage-collector is available, there will be functions which
parallel the above three, which will return the contributions to
elapsed-time, runtime, and pagefaults by the garbage-collector.  Note
that the values returned by the above functions will always include
the contributions by the garbage-collector.


.section "System Management"

Included are some minimal utility functions for maintaining subsystems
in lan{nil}. These tools are not meant to be a comprehensive set,
"addressing all the issues" as they say. Instead, they address some of
the issues, have been found useful, and are used along with individual system
specific procedures for maintaining systems including the editor and
lan{macsyma}.

The practical working procedure on most programs goes something like the
following: There are a set of source files that make up the program.
One of these files defines a variable set to a list of these file names,
and includes code for loading the files, creating needed package namespace(s),
and peforming other functions as needed. Day-to-day works procedes in
an incremental fasion, changes are made to the sources using the built-in
editor, and these changes are tested and debugged using editor commands
such as CONTROL-META-C (compile-defun, or <CONTROL-Z>-C), and META-Z
(evaluate-defun, or <ESC>-Z) and other utilites in the system as
needed. The editor, debugger, evaluator, and exhibitor are invoked
many times during a days development cycle. From time to time during
editing the changed files are saved of course, as a backup against
environment crashes. At the end of the day, (or perhaps, during lunch
hour, or after several days), a recompilation of the changed program files
may be effected, using some of the functions documented in this section.

A somewhat parallel effort is the maintainence of a system that has "users."
The same methodology as used in a development system is in effect; except
that now the full-recompilation-cycle time may be months, and there is
a definite target-environment which is to receive system changes in the
form of "patch files." (See the documentation of the patch facility.)

Some additional functions documented here provide ways to find out
something about how modules depend on one another. 

.subsection "An example"

.lisp
; This is an example "system-build" file.
(defparameter *my-files*
  '("USR:[ME.SYS]TOPLEVEL"
    "USR:[ME.SYS]UTILS"
    "USR:[ME.SYS]BASIC"))
.end_lisp
.sp 1
.lisp
(defvar *my-modules* ())
.end_lisp
.sp 1
.lisp
(defun load-my-system ()
  (setq *my-modules* (mapcar #'load *my-files*)))
.end_lisp
.sp 1
.lisp
(defun recompile-my-files ()
  (mapcar #'silent-comfile
	  (mapcan #'(lambda (x)
		      (if (utils:source-need-compile? x)
			  (list x)))
		  *my-files*)))
.end_lisp
.sp 1
.lisp
(defun silent-comfile (x)
  (let ((compiler:*messages-to-terminal? ())
	(si:print-gc-messages ()))
    (comfile x)))
.end_lisp
.sp 1
.lisp
(defvar *my-undefined-functions-alist*
  ())
.end_lisp
.sp 1
.lisp
(defun find-my-undefined-functions ()
  (setq *my-undefined-functions-alist* ())
  (mapc 
   #'(lambda (m)
      (if (typep m 'module)
	  (utils:map-over-module-cells
	   #'(lambda (module symbol key)
	       (if (and (eq key :function)
			(not (fboundp symbol)))
		   (let ((a (assq
			     symbol
			     *my-undefined-functions-alist*)))
		     (if a
			 (unless (memq module (cdr a))
			   (push module (cdr a)))
			 (push
			  (list symbol module)
			  *my-undefined-functions-alist*)))))
	    m)))
   *my-modules*)
  *my-undefined-functions-alist*)
.end_lisp

.subsection "Source (Re)Compilation"

.defun utils:vas-source-file filename
Gets the exact name of source file from the object file, 2filename*.
.end_defun

.defun utils:source-need-compile? source-filename &optional object-directory
If there is no object file, or if the version of the number of the present
source file is greater than the version number of the source from which
the object was compiled then this function returns 3t*.
.end_defun

.defun utils:vas-source-needs-recompile? filename
Gets the source file name for the object 2filename* and checks the
version numbers.
.end_defun

.subsection "Information in Modules"

The 3exhibit* function can be used to look at modules interactively.


.subsection "Related Utilities"

These are sometimes used to store information gathered during system
programming, for example, "bug" cases, lists of undefined functions,
sorted lists of special variables, etc.

.defun utils:print-into-file expression &optional filename
Prints the 2expression* into the 2filename* which defaults
to something generated in 7sys$scratch*.
.end_defun

.defun utils:pp-into-file expression &optional filename
As in 3utils:print-into-file* above, but uses the 3pretty-print*
function.
.end_defun


.section "Verification"


.defun verify filename
Expressions are read from the file named 2filename* and fed into
a normal read-eval-print loop. The 2filename* is merged with a
default specification of 7nil$disk:[nil.verify]*. The
input and results are printed both
to the value of 3terminal-io* and to an output file named 2filename*
with file type 7lis*. (This is the closest thing to batch processing that
we support.) There are various files in the 7[nil.verify]* directory that
are "verified" before a release of lan{nil} is made. This function is also
useful for making bug reports that are easy to deal with. For example,
say that you found that multiplication of 2.2 and 3.3 did not work, you
could then make a file 7multbug.lsp* containing the following:
.lisp
(si:print-herald)
;; multiplication bug
(errset (times 2.2 3.3))
.end_lisp
Then run the 3verify* function on this file and send it and the output in
your bug note. An 3errset* would be needed around any expression that
would otherwise cause a fatal error.
.end_defun


