The Cedar Spy is designed to be the main tool for analyzing the performance of programs in Cedar. It consists of of an array of means for viewing the execution of a program all presented in a single, consistent form. With the Spy, the programmer can see which procedures are consuming CPU cycles, which are causing page faults, which are using the allocator, or which are calling a particular procedure. When the programmer narrows his focus to just one process, the Spy will tell him where that process is spending its time, where it is waiting on page faults, where it is waiting on monitor locks, where it is waiting on condition variables, and when it is preempted by other processes. In addition, the programmer can measure precisely what he is interested in since the Spy provides a facility for setting breakpoints to determine where the Spy should start and stop its measurements. Hopefully a programmer will find that the Spy is the only tool he needs for the bulk of his performance analysis.

The main paradigm of the Spy is to record the call stack of an interesting process. The definition of "interesting" varies according to what the Spy is measuring. If the Spy is measuring page faults, it records the stack of the process that just page faulted. If the Spy is measuring CPU usage, it records the stack of the top-most active process at regular intervals. The only things recorded are the procedures in the call stack; parameters and local variables are not recorded.

All of the functionality provided by the Spy viewer can also be accessed programmatically through the interface "SpyClient". For documentation, see that interface.

The Spy is normally part of the Cedar command environment (brought over by Environment.df into the ///Commands/ directory). The released copy of the Spy can be obtained with the command:

Issuing the "Spy" command in a CommandTool will cause the Spy package to be loaded and a Spy viewer to appear at the bottom of the screen. (The Spy viewer looks like a magnifying glass laying on top of the word "Spy"). If you destroy the Spy viewer, you can obtain another one by typing another "Spy" command to the CommandTool.

The Spy provides the programmer with a number of parameters to specify what it will measure. These parameters allow the programmer to tailor the Spy somewhat to his particular needs. The parameters are changed by clicking them with the mouse; repeated clickings will cycle a parameter through all of the possible values. Most people will find that the default parameters provide a good starting point.

There are two main ways of starting and stopping the Spy: by bugging "Spy: {on}" and "Spy: {off}", or by setting breakpoints that determine programmatically where the Spy is to start and stop. Start and Stop breakpoints are set in exactly the same manner as given above for user breakpoints. The only difference is that if a Stop breakpoint is set on a the beginning procedure, the break will occur at the exit of the procedure rather than its entry.

Setting a Start or Stop breakpoint does not actually enable the Spy to run. Instead, the "Spy: {off}" switch will be changed to say "Break: {off}". The Start and Stop breaks are only enabled when the programmer has set the switch to "Break: {on}". This allows the programmer to specify all of the breaks he wants before the Spy starts measuring. Changing the switch to "Break: {off}" doesn't remove the breaks, it just disables them. Thus the user can reuse the breaks he has already set.

The breakpoint facility is designed so that the Spy is recording data as long as the number of Start breaks exceeds the number of Stop breaks. This allows breaks to be set in recursive procedures.

When "ClearBreaks!" is bugged, all of the Start and Stop breaks are removed and the on/off switch is changed to say "Spy: {off}".

Clicking "DisplayData!" will cause the data to be displayed in a new typescript. It will also automatically turn off the Spy if it is running. "DisplayData!" does not destroy the data stored. If some of the symbols were missing, the user can fetch them and click "DisplayData!" again. The second invocation will take advantage of the new symbols.

To the left of the "DisplayData!" button is a button called "cutoff". The "cutoff" button lets you specify how much information you want to be displayed. The number after the cutoff is the percentage of times a procedure must be in the call stack in order to be displayed. If a procedure is in the call stack fewer times than this, then it will not be displayed.

The Spy's output is divided into three main parts: a header, a breakdown of the processes, and a breakdown of the procedures. The header gives overall statistics about the execution of the Spy while the two breakdown sections are focussed on detailed data. The three sections are separated by double rows of tildas (~~~).

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Breakdown of interesting procedures.
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Breakdown of highly active procedures.
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

The procedures as a whole are indented according to the following rule: A procedure is indented immediately under the deepest procedure that completely contains all of the calls to it. Usually this just means that a procedure is indented under the procedure that calls it, but it means something different if a procedure is called from more than one place. Indentation can be used to eliminate whole sub-trees of the output. If you aren't interested in a procedure, you can ignore all of the procedures indented below it.

Occasionally, a procedure will be indented under a procedure that doesn't call it directly. (The names of such procedures are printed in italics for easy identification.) For instance, if A calls B which calls C, and A calls D which calls C, then C is indented under A rather than B or D. This is because only A completely contains all of the calls to C. One consequence of this scheme is that utility procedures that are called from many places will appear high in the hierarchy even though they are always low in the call stack. I consider this a feature, since if you are spending 50% of your time in the allocator, you want that fact to jump out at you, especially if it is buried in hundreds of little calls.

Procedures that are all at the same level of indentation are grouped into sets of disjoint procedures using exclamation points (!). All of the procedures that are connected by a line of exclamation points are disjoint. That is, none of the procedures in the set ever calls any of the other procedures in the set, either directly or indirectly. Sets of disjoint procedures are connected with periods (.) to help the reader keep track of indentation. Disjoint sets are just a hint. Procedures from different sets may be disjoint even though they are not indicated as such. However, procedures in the same disjoint set are guaranteed to be disjoint.

This indentation scheme may not be the best, but it does not hurt since it can always be ignored. The indentations do not add any information, they just summarize information already given by the calls from other procedures. However I will be glad to entertain suggestions for a better scheme.

1) First use `Watching: {CPU}'. This will tell you which processes and procedures are consuming CPU cycles. Look at `Total page faults' and `Total words allocated' in the header to see if there are a lot of page faults or allocations. If there are, you might want to run the Spy with `Watching: {pagefaults}' or `Watching: {wordsAllocated}'.

2) If the Spy can't find the symbols it needs when it prints its log, it will print the data with numbers instead of procedure names. You do not need to run your experiment again to get the procedure names -- just acquire the symbols (by adding appropriate debug search rules, for instance) and click 'DisplayData!' again.

3) If the processor hog is a single process, use 'Watching: {breakProcess}' to gather more information about that process. Select the name of a top level procedure in the Spy's typescript and then click 'SetStartBreak!' and 'SetStopBreak!'. Then run your experiment again. When the first break is hit, the Spy will start monitoring the process that was calling the procedure.

4) If you suspect that things are running slowly because a procedure is being called too often, set a user break (click 'SetUserBreak!') on the procedure and run the experiment again. This will show how many times the procedure gets called and who called it.

We know from Heisenberg that no tool could measure an event without influencing it. However, if you have an idea of how the tool measures, you may be able to factor out its influence. Most programmers should be able to use the Spy without understanding how it gathers data. But those who are really particular about accurate data (or where the data is likely to be inaccurate) should read this section.

The Spy works by a) choosing a process, b) making up a "stack" of GFI's and PC's for that process, and c) writing the stack into a special log which interfaces to the disk. A process is chosen according to the parameters set by the programmer at the beginning of the session. If the programmer tells the Spy to watch pagefaults then processes that cause pagefaults will be logged. If the programmer tells the Spy to watch user-defined breaks, then processes that cause breaks will be logged.

If the programmer tells the Spy to watch the CPU, then the Spy will wake up at regular intervals and log the top process on the ready list. It finds the "top process" by checking priority levels from top to bottom looking for a process that is ready and able to run (A process would not be able to run if there were no state vector at its level). There are two ways to wake up at regular intervals: use a special IntervalTimer or wake up on the vertical retrace. The IntervalTimer the best way to wakeup but it isn't always available. So sometimes the Spy wakes up on the vertical retrace.

There are some bad side effects of waking up on the vertical retrace. Since timeouts are all synchronized to the vertical retrace, actions that are triggered by timeouts may appear to be running far more than they actually are. To counter this, the Spy tries to guess which processes run off of the vertical retrace. When it is first run, it scans the process table looking for processes that have very short timeouts. If it finds any, it saves them in a table. When it scans the ready list it skips over those processes if they are still at the pc locations that they were when they were waiting. This heuristic is only partically effective, but it is better than nothing.

Once the Spy has decided which process to record, it builds a stack by chasing up the frame links and writing down the GFI's and PC's. If the stack has more that 75 frames, it aborts its work and writes an error entry in the log (if this ever occurs, it is noted under "Statistics on the execution of the Spy"). Otherwise it writes the stack it constructed into the log.

The log consists of two pinned buffers backed up by a file named "Spy.log". The Spy will write in one buffer until it is full and then write in the other. As it writes into the second, a background process writes the first one to the disk and remaps it to the next section of the file. A background process is used since the Spy cannot page fault. The background process may appear in the Spy's output. If it does, it will have the name "SpyLogImpl.NewBuffer".

Occasionally, the disk will be so busy that the first buffer will not be ready for the Spy when it has finished filling the second. When this happens the Spy just hangs until the first buffer is ready. If the Spy is watching the CPU, this means that it may miss a few ticks of the vertical retrace. You can get some idea of how many ticks were missed by looking at the average number of counts per second that is given at the beginning of the output. If the average is less that 80, some information was lost. If you suspect that this is a problem, set SpyKernelImpl.monitor to TRUE and SpyLogReaderImpl.recordSpyTime to TRUE. From then on the Spy will record the distribution of delays between counts under the header "Statistics on the execution of the Spy".