This chapter details Scheme 48's command processor, which incorporates both a read-eval-print loop and an interactive debugger. At the > prompt, you can type either a Scheme form (expression or definition) or a command beginning with a comma. In inspection mode (see section 3.8) the prompt changes to : and commands no longer need to be preceded by a comma; input beginning with a letter or digit is assumed to be a command, not an expression. In inspection mode the command processor prints out a menu of selectable components for the current object of interest.
The command processor keeps track of a current focus value. This value is normally the last value returned by a command. If a command returns multiple values the focus object is a list of the values. The focus value is not changed if a command returns no values or a distinguished `unspecific' value. Examples of forms that return this unspecific value are definitions, uses of set!, and (if #f 0). It prints as #{Unspecific}.
The reader used by the command processor reads ## as a special expression that evaluates to the current focus object.
> (list 'a 'b)
'(a b)
> (car ##)
'a
> (symbol->string ##)
"a"
> (if #f 0)
#{Unspecific}
> ##
"a"
>
If an error, keyboard interrupt, or other breakpoint occurs, or the ,push command is used, the command processor invokes a recursive copy of itself, preserving the dynamic state of the program when the breakpoint occurred. The recursive invocation creates a new command level. The command levels form a stack with the current level at the top. The command prompt indicates the number of stopped levels below the current one: > or : for the base level and n> or n: for all other levels, where n is the command-level nesting depth. The levels setting described below can be used to disable the automatic pushing of new levels.
The command processor's evaluation package and the value of the current focus value are local to each command level. They are preserved when a new level is pushed and restored when it is discarded. The settings of all other settings are shared by all command levels.
Whenever moving to an existing level, either by sending an ⟨eof⟩ or by using ,reset or the other commands listed above, the command processor runs all of the dynamic-wind “after” thunks belonging to stopped computations on the discarded level(s).
There are many commands related to modules. Only the most commonly used module commands are described here; documentation for the rest can be found in section 4.8. There is also a brief description of modules, structures, and packages in section 2.6 below.
,config ,load filename
to load a file containing module definitions. If no command is given, the config package becomes the execution package for future commands.
If the current focus object is a continuation or a thread, then that continuation or thread's stack is displayed.
Otherwise, if the current command level was initiated because of a breakpoint in the next level down, then the stack at that breakpoint is displayed.
Otherwise, there is no stack to display and a message is printed to that effect.
One line is printed out for each continuation on the chosen stack, going from top to bottom.
After loading the profile-commands structure via
,load-package profile-commands
Scheme 48 provides a basic profiler, with support for flat and call-graph profiles. In addition to call- and runtimes the heap memory usage is estimated as well. By adding the byte-code optimizer profiler-instrumentation to the definition of a structure via a clause
(optimize profiler-instrumentation)
in the structure definition, code will by instrumented with calls to the profiler. The call-times to instrumented code can then be measured exactly. Without instrumentation, the profiler is solely based on sampling and therefore has only limited accuracy. Any evaluation can be profiled with the following command:
The output of the profiler is explained on the basis of the following piece of senseless code:
(define (c x)
(if (= x 0)
0
(+ 1 (c (- x 1)))))
(define (b x)
(let ((y (- x 1)))
(if (> y 0)
(begin
(c y)
(a y)
(+ 1 (a y)))
0)))
(define (a x)
(let ((y (- x 1)))
(if (> y 0)
(begin
(c y)
(b y)
(+ 1 (b y)))
0)))
(define (main x)
(+ 1 (a x)))
The profiler produces the following output:
> ,profile (main 21)
** Samples: 60 (approx. one per 40ms)
** Interrupt time: 50ms
** Real run time: 2430ms
** Total memory: 22k
** GC runs: 0
** Flat result (times in ms):
time cumu self mem calls ms/call name
61.66% 1498 1498 2k 37+51 17 c in "x.scm"
25.0% 2430 608 10k 436 6 b in "x.scm"
13.33% 2430 324 10k 442 5 a in "x.scm"
0.0% 2430 0 0k 1 2430 main in "x.scm"
** Tree result (times in ms):
i time self child mem calls name
0 100.0% 0 2430 0k 0 <profiler> [0]
0 2430 0k 1/1 main in "x.scm" [1]
=========================================================
441/442 b in "x.scm" <cycle 0> [3]
324 891 10k 1/442 main in "x.scm" [1]
1 100.0% 324 891 10k 442 a in "x.scm" <cycle 0> [2]
891 0 1k 22/37 c in "x.scm" [4]
436/436 b in "x.scm" <cycle 0> [3]
=========================================================
436/436 a in "x.scm" <cycle 0> [2]
2 100.0% 608 608 10k 436 b in "x.scm" <cycle 0> [3]
608 0 1k 15/37 c in "x.scm" [4]
441/442 a in "x.scm" <cycle 0> [2]
=========================================================
0 2430 0k 1/1 <profiler> [0]
3 100.0% 0 2430 0k 1 main in "x.scm" [1]
324 891 10k 1/442 a in "x.scm" <cycle 0> [2]
=========================================================
608 0 1k 15/37 b in "x.scm" <cycle 0> [3]
891 0 1k 22/37 a in "x.scm" <cycle 0> [2]
4 61.66% 1498 0 2k 37+51 c in "x.scm" [4]
=========================================================
932 1498 20k 1/1 main in "x.scm" [1]
0 100.0% 932 1498 20k 1+877 <cycle 0 as a whole>
324 891 10k 441 a in "x.scm" <cycle 0> [2]
608 608 10k 436 b in "x.scm" <cycle 0> [3]
0 0 2k 37/37 c in "x.scm" [4]
The formatting of the output is based on the output of GNU gprof 1.
First, general information about the profiling is shown:
samples: total number of samples taken and the average time between two samples
interrupt time: theoretical interrupt time, the time between two samples
real run time: the total run time of the evaluation, simple measurement from the beginning to the end of the evaluation
total memory: the total amount of memory used by the program, here in kilobytes
GC runs: the number of times the garbage collector was running while evaluating
The flat profile gives overall statistics for each procedure in the program:
time: percentage of time the procedure has in the program (based on “self”)
cumu: total cumulative time the procedure was running
self: total time the procedure was running itself (without children)
mem: approximated memory usage of the procedure
calls: the number of non-recursive calls to the procedure. Recursive calls are displayed after an optionally appended "+" to former number (see procedure c in example output above).
ms/call: estimate of the time per call (with children), based on non-recursive calls and “cumu”.
name: the name of the procedure and the file it is defined in
The tree result displays profiling information depending on the caller of a particular procedure. As in gprof output, for each procedure there is an entry. Entries are separated by lines of =s. Each entry displays the callers (indented), the procedure itself and the procedure called (indented). The meaning of the fields depends on the type of the entry, for example:
i time self child mem calls name
324 891 10k 1/442 main [1]
1 100.0% 324 891 10k 442 a <cycle 0> [2]
891 0 1k 22/37 c [4]
Every procedure has a unique index number i (here “1”), based on the position in the call-graph. It is used to quickly find the corresponding entry. The number is appended to the procedure name (in brackets). The meaning of the “cycle” suffix is explained below.
Callers (here main):
self: time spent directly in a when called by main
child: time spent in children of a when called by main
mem: memory usage of a when called by main
calls: two numbers: number of calls to a from main and total number of non-recursive calls to a
Primary line (here a):
time: total percentage of time a was running
self: total time spent directly in a
child: total time spent in children of a
mem: total memory usage of a
calls: the total number of non-recursive calls to a. Recursive calls are displayed after an optional +.
Called (here c):
self: time spent directly in c when called by a
child: time spent in children of c when called by a
mem: memory usage of c when called by a
calls: two numbers: number of calls to c from a and total number of non-recursive calls to c
A special treatment is needed for mutual-recursive procedures. In the example, a calls b and b calls a. This is called a cycle. If a would call another procedure d and d would call a, all three procedures form a cycle.
Cycles have a separate entry in the call graph. This entry consists of the callers into the cycle, the primary line of the cycle, the member procedures of the cycle and the external procedures called by the cycle:
932 1498 20k 1/1 main [1]
0 100.0% 932 1498 20k 1+877 <cycle 0 as a whole>
324 891 10k 441 a <cycle 0> [2]
608 608 10k 436 b <cycle 0> [3]
0 0 2k 37/37 c [4]
Callers (here main):
the meaning of the fields are the same as above. The member procedures of the cycle are seen as a whole.
Primary line:
time: total percentage of time any procedure of the cycle was running
self: total time spent directly in a procedure of the cycle
child: total time spent in external children of a
mem: sum of memory usage of all cycle member procedures
calls: the total number of external calls to the cycle and the total number of calls in the cycle internally
Member procedures:
the meaning of the fields are the same as above, except...
calls: the number of calls to the member procedure from within the cycle
External procedures (here c):
the meaning of the fields are the same as with the member procedures, except...
calls: the number of calls to the external procedure from the cycle and the total number of non-recursive calls to the external procedure
In the current implementation, there are some issues that need to be considered: in the default configuration, samples are taken every 50 milliseconds. Procedures with a by-call run time shorter than the interrupt time are likely to be profiled inaccurately or may not be seen at all, if they have not been instrumented.
The default interrupt time can be set with the profiler-interrupt-time command processor setting, see 3.7. For example,
,set profiler-interrupt-time 200
sets the default profiler sampling interrupt time to 200ms.
Because the interrupt is shared with the thread system, profiling may cause performance issues with multi-threaded programs. Also, programs with deep recursion (resulting in large continuations) can cause the profiler to use a significant percentage of the total run time.
By default, call times are measured by the sampling process. When code had been instrumented, call times of those procedures will be measured exactly. When only instrumented code should be considered in the output of the profiler, the command processor setting profiler-measure-noninstr can be set to off.
Scheme 48 optimizes tail calls. Thus, the profiler cannot “see” tail calls and in some situations, the output of the profiler may show that procedures directly call their “grandchildren”.
The profiler is based on taking samples of the current stack of continuations, the call-stack. Therefore it schedules the alarm interrupt at a regular interval specified by the profiler-interrupt-time command processor setting. Because the thread system uses the alarm interrupt as well, the profiler interrupt handler calls the handler of the thread system after processing the sample.
The profiler interrupt handler first captures the current continuation and follows the continuation-stack down to the continuation of the profile-thunk procedure, which called the thunk to be profiled. Each continuation with the corresponding code template is stored in a stack of stackentry records.
This *cur-stack* is compared from bottom to top with the *last-stack*, the stack captured while the prior sampling interrupt. The statistics gathered are stored in profinfo records.
For each stack-entry in the *cur-stack*, several possibilities exist in conjunction to the entry at the same depth in the *last-stack*:
there is no such entry: the continuation must be the result of a new call
both entries are the same continuation: nothing changed, the procedure is still running
entries are not the same continuation: the following entries up in the stack must have changed. If the templates of the current entries are the same, the continuation counts as the still same call to the procedure (but at another expression in the procedure). A such situation only counts as a new call if the continuation object has changed, but the continuation program-counter, arguments and the template stayed the same.
As we ascend in the call-stack, changes in the lower levels indicate that all entries above have to be new calls. This way, the profiler gathers information about how often a template is called by another template.
Additionally, every time a procedure is seen, we record this “occurrence”. If the procedure is a the top of the stack, it is currently running. Based on these numbers, the average interrupt time and the number of calls, we can estimate the self and child times.
While running, the profiler collects information about heap memory usage as well. After comparing the current with the last stack, the profiler knows which procedures finished, which procedures are new and which procedure called the new procedures. This information is used to distribute the difference in heap memory usage between the prior and the current sample. The profiler uses the memory-status primitive for retrieving available heap space and the number of garbage collector runs (gc-count). Difference in used memory between two samples is distributed by the following principles:
if gc-count increased, distribution cannot be done
if the same continuation is still at top, credit its template with all used memory between the two samplings
if there are stackentry-templates gone or new, distribute the used memory equally between them:
gone templates could have used some memory before “returning”
new templates could have used some memory while running
the caller of new templates could have used some memory between the calling of gone and new procedures
The byte-code optimizer profiler-instrumentation adds a call to the “profile-count” procedure of the profiler structure. This procedure is responsible for the exact call-times measurement.
After collection of the data, procedures are numbered and cycles are detected by ascending in the call tree. Time is being propagated from top to bottom, remembering self and child times. Most of the time, cycles are being considered as one procedure.
There are a number of settings that control the behavior of the command processor; most of them are booleans. They can be set using the ,set and ,unset commands.
The settings are as follows:
a longer prompt
retention of the continuation in effect at the point of error
confusion among some newcomers
With levels disabled one must issue a ,push command immediately following an error in order to retain the error continuation for debugging purposes; otherwise the continuation is lost as soon as the focus object changes. If you don't know anything about the available debugging tools, then levels might as well be disabled.
> ,set ask-before-loading will ask before loading modules > ,open random Load structure random (y/n)? y >
> ,set load-noisily will notify when loading modules and files > ,open random [random /usr/local/lib/scheme48/big/random.scm] >
There is a data inspector available via the ,inspect and ,debug commands. The inspector is particularly useful with procedures, continuations, and records. The command processor can be taken out of inspection mode by using the q command. When in inspection mode, input that begins with a letter or digit is read as a command, not as an expression. To see the value of a variable or number, do (begin exp) or use the ,run exp command.
In inspection mode the command processor prints out a menu of selectable components for the current focus object. To inspect a particular component, just type the corresponding number in the menu. That component becomes the new focus object. For example:
> ,inspect '(a (b c) d) (a (b c) d) [0] a [1] (b c) [2] d : 1 (b c) [0] b [1] c :
When a new focus object is selected the previous one is pushed onto a stack. You can pop the stack, reverting to the previous object, with the u command, or use the stack command to move to an earlier object.
Commands useful when in inspection mode:
u (up) pop object stack
m (more) print more of a long menu
(...) evaluate a form and select result
q quit
template select a closure or continuation's template (Templates are the static components of procedures; these are found inside of procedures and continuations, and contain the quoted constants and top-level variables referred to by byte-compiled code.)
d (down) move to the next continuation (current object must be a continuation)
menu print the selection menu for the focus object
Multiple selection commands (u, d, and menu indexes) may be put on a single line.
All ordinary commands are available when in inspection mode. Similarly, the inspection commands can be used when not in inspection mode. For example:
> (list 'a '(b c) 'd) '(a (b c) d) > ,1 '(b c) > ,menu [0] b [1] c >
If the current command level was initiated because of a breakpoint in the next level down, then ,debug will invoke the inspector on the continuation at the point of the error. The u and d (up and down) commands then make the inspected-value stack look like a conventional stack debugger, with continuations playing the role of stack frames. D goes to older or deeper continuations (frames), and u goes back up to more recent ones.
The exec package contains procedures that are used to execute the command processor's commands. A command ,foo is executed by applying the value of the identifier foo in the exec package to the (suitably parsed) command arguments.
,exec ,load filename
to load a file containing commands. If no command is given, the exec package becomes the execution package for future commands.
The required argument types are as follows:
filenames should be strings
other names and identifiers should be symbols
expressions should be s-expressions
commands (as for ,config and ,exec itself) should be lists of the form (command-name argument ...) where command-name is a symbol.
For example, the following two commands are equivalent:
,config ,load my-file.scm ,exec (config '(load "my-file.scm"))
The file scheme/vm/load-vm.scm in the source directory contains an example of an exec program.
If no-warnings appears as an option after the file name, no warnings about undefined external bindings (see Section 8.2) will be printed upon resuming the image. This is useful when the definitions of external bindings appear in shared objects that are only loaded after the resumption of the image.
Doing ,flush before building an image will reduce the amount of debugging information in the image, making for a smaller image file, but if an error occurs, the error message may be less helpful. Doing ,flush source maps before loading any programs used in the image will make it still smaller. See section 3.11 for more information.
maps - environment maps (local variable names, for inspector)
source - source code for continuations (displayed by inspector)
names - procedure names (as displayed by write and in error messages)
files - source file names
These commands refer to future compilations only, not to procedures that already exist. To have any effect, they must be done before programs are loaded. The default is to keep all four types.
Each command level has its own set of threads. These threads are suspended when a new level is entered and resumed when the owning level again becomes the current level. A thread that raises an error is not resumed unless explicitly restarted using the ,proceed command. In addition to any threads spawned by the user, each level has a thread that runs the command processor on that level. A new command-processor thread is started if the current one dies or is terminated. When a command level is abandoned for a lower level, or when a level is restarted using ,reset, all of the threads on that level are terminated and any dynamic-wind “after” thunks are run.
The following commands are useful when debugging multithreaded programs:
,translate /usr/gjc/ /zu/gjc/
will cause (load "/usr/gjc/foo.scm") to have the same effect as (load "/zu/gjc/foo.scm").
1 part of the GNU Binary Utilities: http://www.gnu.org/software/binutils/