[Cyan]<CedarChest7.0>Spy>SpyLogReaderImpl.mesa!4

SpyLogReaderImpl.mesa

Maxwell on December 14, 1983 2:25 pm

Russ Atkinson (RRA) February 19, 1987 11:30:07 am PST

Pier, December 12, 1985 10:51:00 am PST

McCreight, April 11, 1986 2:30:38 pm PST

Mike Spreitzer January 24, 1987 3:05:05 pm PST

Eric Nickell, November 25, 1986 4:04:34 pm PST

Doug Wyatt, February 10, 1987 2:34:45 pm PST

DIRECTORY

AMBridge USING [TVForPointerReferent],

AMTypes USING [TV, TVType, TypeToName],

BasicTime USING [GetClockPulses, Pulses, PulsesToMicroseconds, PulsesToSeconds],

IO USING [PutChar, PutF, PutF1, PutFR, PutRope, RopeFromROS, ROS, STREAM],

PrincOps USING [BytePC, CSegPrefix, EntryVectorItem, GFT, GlobalFrameHandle, LastAVSlot, NullPsbHandle, PsbHandle, PsbIndex],

PrincOpsUtils USING [PsbHandleToIndex],

PrintTV USING [Print],

Process USING [Priority],

Real USING [Round],

Rope USING [Cat, Equal, FromChar, ROPE],

RTSymbolDefs USING [CallableBodyIndex, SymbolTableBase],

RTSymbolOps USING [AcquireRope, BodyName],

RTSymbols USING [AcquireSTBFromGFH, ReleaseSTB],

RTTypesPrivate USING [GetCBTI, GetEp, GFHToName],

RuntimeError USING [UNCAUGHT],

SpyLog USING [active, Close, Entry, NextEntry, OpenForRead],

SpyOps USING [Call, Count, DataType, freqDivisor, LevelData, pageFaults, Procedure, ProcessRec, ProcessRef, ProcRec, runningTime, Stack, stackHeader, stackLength, StackType, wordsAllocated, wordsReclaimed],

ViewerIO USING [CreateViewerStreams];

SpyLogReaderImpl: PROGRAM

IMPORTS AMBridge, AMTypes, BasicTime, IO, PrincOpsUtils, PrintTV, Real, Rope, RTSymbolOps, RTSymbols, RTTypesPrivate, RuntimeError, SpyLog, SpyOps, ViewerIO

EXPORTS SpyOps = {

OPEN SpyOps;

CallList: TYPE = LIST OF Call;

GlobalFrameHandle: TYPE = PrincOps.GlobalFrameHandle;

ROPE: TYPE = Rope.ROPE;

STREAM: TYPE = IO.STREAM;

Error: SIGNAL = CODE;

global variables and types

processes: PUBLIC LIST OF ProcessRef ← NIL;

modules: PUBLIC LIST OF Procedure ← NIL;

current: SpyOps.DataType;

procedures listed in top down order

DestroyLog: PUBLIC PROC = {

NilLinks: PROC [proc: Procedure] RETURNS [BOOL ← FALSE] = {

proc.container ← NIL;

proc.parents ← NIL;

proc.sons ← NIL};

[] ← EnumerateProcs[NilLinks];

FOR modules ← modules, modules.rest WHILE modules # NIL DO

modules.first.container ← NIL;

modules.first.parents ← NIL;

modules.first.sons ← NIL;

ENDLOOP;

FOR processes ← processes, processes.rest WHILE processes # NIL DO

processes.first.sons ← NIL;

ENDLOOP;

processes ← NIL;

modules ← NIL;

SpyLog.Close[];

};

ReadLog: PUBLIC PROC
[typescript: STREAM, datatype: SpyOps.DataType, spyOnSpyLog: BOOL] = {

ignoreBefore: BasicTime.Pulses ← 0;

IF typescript = NIL THEN typescript ← ViewerIO.CreateViewerStreams["Spy log"].out;

IO.PutRope[typescript, "(Please wait-- processing log.)\n\n"];

current ← datatype;

typeName ← [

"executing",

"pageFault",

"waitingML",

"waitingCV",

"preempted",

"waitingSV",

"unknown",

"data",

"code",

"xfer",

"safe",

"permanent",

"unsafe",

"userBreak"];

SELECT current FROM

CPU => className ← NIL;

process, breakProcess => className ← "waiting";

pagefaults => className ← "pagefault";

allocations, wordsAllocated => className ← "allocation";

userDefined => className ← "userBreaks";

ENDCASE => ERROR;

typeData ← ALL[0];

IF useTrigger THEN {

ignoreBefore ← FindTrigger[];

IF ignoreBefore = LOOPHOLE[0] THEN {

IO.PutRope[typescript, "No trigger encountered.\n\n"]; RETURN};

IF triggerExtent > ignoreBefore

THEN ignoreBefore ← 0

ELSE ignoreBefore ← ignoreBefore - triggerExtent};

ReadSpyLog[ignoreBefore, spyOnSpyLog];

SetAllContainers[];

PrintStatistics[typescript];

PrintInstructions[typescript];

PrintLogStatistics[typescript];

};

reading the section of the log just before a trigger

useTrigger: BOOL ← FALSE;

triggerExtent: BasicTime.Pulses;

whichTrigger: NAT ← 1;

SetTrigger: PROC [extent: BasicTime.Pulses, which: NAT ← 1, enable: BOOL ← TRUE] = {

useTrigger ← enable;

triggerExtent ← extent;

whichTrigger ← which;

};

FindTrigger: PROC RETURNS [trigger: BasicTime.Pulses] = {

entry: LONG POINTER TO SpyLog.Entry;

SpyLog.OpenForRead[]; -- open for reading

WHILE TRUE DO

entry ← SpyLog.NextEntry[];

IF entry = NIL THEN EXIT;

WITH e: entry SELECT FROM

endOfLog => EXIT;

data => {

stack: LONG POINTER TO SpyOps.Stack ← LOOPHOLE[@e.data];

IF stack.type # LAST[SpyOps.StackType] THEN LOOP;

count ← count + 1;

IF count < whichTrigger THEN LOOP;

RETURN [e.timestamp]};

ENDCASE;

ENDLOOP;

RETURN [0];

};

building a call tree from the trace log

public statistics

wakeups: PUBLIC Count ← 0; -- Number of times that Spy counted something

notScheduled: PUBLIC SpyOps.Count ← 0; -- no interesting process sceduled

skips: PUBLIC SpyOps.Count ← 0; -- waiting on disk

levelData: PUBLIC SpyOps.LevelData ← ALL[0];

typeName: ARRAY StackType OF ROPE;

typeData: ARRAY StackType OF Count;

className: ROPE;

private statistics

processed: Count ← 0; -- Number of stacks in the log

overflow: Count ← 0; -- # of samples with stacks >= SpyOps.stackLength

error: Count ← 0; -- # of samples with stacks >= SpyOps.stackLength

stackDepth: Count ← 0; -- sum of stack depths

noCalls, noProcesses, noProcs, noModules: Count ← 0;

readLog: BasicTime.Pulses; -- elapsed time to read log

out: STREAM;

recordSpyTime: BOOL ← FALSE;

spyTime: ARRAY [0..3] OF RECORD[

time: BasicTime.Pulses];

ReadSpyLog: PROC [ignoreBefore: BasicTime.Pulses, spyOnSpyLog: BOOL] = {

i: CARDINAL;

data: BOOL ← FALSE;

dataSize: CARDINAL ← 0;

first, last: BasicTime.Pulses ← 0;

active: BOOL ← SpyLog.active;

t1, delta, dataTime: BasicTime.Pulses;

entry: LONG POINTER TO SpyLog.Entry;

process: PrincOps.PsbHandle ← PrincOps.NullPsbHandle;

Initialize[];

SpyLog.OpenForRead[]; -- open for reading

readLog ← 0;

t1 ← BasicTime.GetClockPulses[];

WHILE TRUE DO

IF UserInput.userAbort THEN EXIT;

entry ← SpyLog.NextEntry[];

IF entry = NIL THEN EXIT;

WITH e: entry SELECT FROM

endOfLog => EXIT;

nullEntry => LOOP;

trace =>

IF recordSpyTime

THEN {

IF ~data THEN last ← e.timestamp;

IF data THEN {

delta ← e.timestamp - last;

IF delta > 10000000 THEN {data ← FALSE; RETURN};

SELECT delta FROM

<= 10 => i ← 0; <= 100 => i ← 1;

<= 1000 => i ← 2; ENDCASE => i ← 3;

spyTime[i].count ← spyTime[i].count + 1;

spyTime[i].time ← spyTime[i].time + delta;

};

data ← FALSE;

}

ELSE {

IF first = 0 THEN first ← e.timestamp;

IF last = 0 THEN delta ← 0 ELSE delta ← e.timestamp - last;

IF out = NIL THEN {

out ← ViewerIO.CreateViewerStreams["auxilary spy log"].out;

IO.PutF1[out, "%l uSeconds delta data\n", [character['f]]];

};

IF e.process # process THEN {

IO.PutF1[out, " Switch to process: %b\n", [cardinal[PrincOpsUtils.PsbHandleToIndex[e.process]]]];

process ← e.process;

};

PrintTrace[e.gfh, e.pc, e.timestamp - first, delta];

last ← e.timestamp;

};

data => {

stack: LONG POINTER TO SpyOps.Stack;

IF useTrigger AND e.timestamp < ignoreBefore THEN LOOP;

IF e.rttype # SpyOps.Stack.CODE THEN {

IF first = 0 THEN first ← e.timestamp;

IF last = 0 THEN delta ← 0 ELSE delta ← e.timestamp - last;

PrintEntry[e.rttype, e.size, @e.data, e.timestamp - first, delta];

last ← e.timestamp;

LOOP;

};

stack ← LOOPHOLE[@e.data];

IF useTrigger AND stack.type = LAST[SpyOps.StackType] THEN EXIT;

EnterStack[LOOPHOLE[@e.data], (e.size - SpyOps.stackHeader)/2];

dataSize ← e.size + 4;

dataTime ← e.timestamp;

data ← TRUE;

};

ENDCASE => SIGNAL Error;

ENDLOOP;

readLog ← BasicTime.GetClockPulses[]-t1;

IF active THEN SpyLog.Open[TRUE];

IF UserInput.userAbort THEN ERROR SpyOps.UserAborted;

stack ← NIL;

out ← NIL;

};

PrintEntry: PROC
[type, words: CARDINAL, data: LONG POINTER, time, delta: BasicTime.Pulses] = {

value: AMTypes.TV;

IF out = NIL THEN {

out ← ViewerIO.CreateViewerStreams["auxilary spy log"].out;

IO.PutF1[out, "%l uSeconds delta data\n", [character['f]]];

};

value ← AMBridge.TVForPointerReferent[data, LOOPHOLE[type]];

IO.PutF[out, "%9d%9d %g: \n",

[cardinal[BasicTime.PulsesToMicroseconds[time]]],

[cardinal[BasicTime.PulsesToMicroseconds[delta]]],

[rope[AMTypes.TypeToName[AMTypes.TVType[value]]]]];

PrintTV.Print[value, out];

IO.PutChar[out, '\n];

};

PrintTrace: PROC
[gfh: GlobalFrameHandle, pc: PrincOps.BytePC, time, delta: BasicTime.Pulses] = {

IO.PutF[out, "%9d%9d %g (gfh: %g, pc: %g)\n",

[cardinal[BasicTime.PulsesToMicroseconds[time]]],

[cardinal[BasicTime.PulsesToMicroseconds[delta]]],

[rope[name]], [cardinal[LOOPHOLE[gfh, CARDINAL]]], [cardinal[pc]]];

};

GetName: PROC [gfh: GlobalFrameHandle, pc: PrincOps.BytePC]
RETURNS [name: ROPE ← NIL] = {

proc: ROPE;

stb: RTSymbolDefs.SymbolTableBase ← [x[e: NIL]];

name ← RTTypesPrivate.GFHToName[gfh ! RuntimeError.UNCAUGHT => GO TO badNews];

{

ENABLE {

RuntimeError.UNCAUGHT => {

IF stb # [x[e: NIL]] THEN {RTSymbols.ReleaseSTB[stb]; stb ← [x[e: NIL]]};

CONTINUE;

};

UNWIND => {

IF stb # [x[e: NIL]] THEN {RTSymbols.ReleaseSTB[stb]; stb ← [x[e: NIL]]};

CONTINUE;

};

ep: CARDINAL;

cbti: RTSymbolDefs.CallableBodyIndex;

stb ← RTSymbols.AcquireSTBFromGFH[gfh];

[ep,] ← RTTypesPrivate.GetEp[[pc], gfh, stb];

cbti ← RTTypesPrivate.GetCBTI[stb, ep];

proc ← RTSymbolOps.AcquireRope[stb, RTSymbolOps.BodyName[stb, cbti]];

RTSymbols.ReleaseSTB[stb];

};

name ← Rope.Cat[name, ".", proc];

EXITS badNews =>

name ← IO.PutFR["%bB.%bB", [cardinal[LOOPHOLE[gfh, CARDINAL]]], [cardinal[pc]] ];

};

tree management

Initialize: PROC = {

processes ← NIL;

modules ← NIL;

stackDepth ← 0;

processed ← overflow ← error ← 0;

wakeups ← notScheduled ← skips ← 0;

noProcesses ← noCalls ← noProcs ← noModules ← 0;

spyTime ← ALL[[0, 0]];

levelData ← ALL[0];

stack ← NIL;

};

EnumerateProcs: PROC [userProc: PROC [Procedure] RETURNS [BOOL]]
RETURNS [last: Procedure] = {

FOR m: LIST OF Procedure ← modules, m.rest WHILE m # NIL DO

FOR p: CallList ← m.first.sons, p.rest WHILE p # NIL DO

IF userProc[p.first.proc] THEN RETURN [p.first.proc];

ENDLOOP;

RETURN [NIL];

};

adding a stack to the call tree

stack: ProcStack;

EnterStack: PROC [s: LONG POINTER TO SpyOps.Stack, n: CARDINAL] = {

ENABLE Error => {error ← error + 1; CONTINUE};

INVARIANT: exactly n proc.calls or proc.count should be incremented.

process: ProcessRef ← NIL;

proc, newSon: Procedure ← NIL;

processed ← processed + 1;

wakeups ← wakeups + s.count;

IF s.level = 0 AND n = 0 THEN {

SELECT s.type FROM

ready => notScheduled ← notScheduled + s.count;

pageFault => skips ← skips + s.count;

ENDCASE => error ← error + s.count;

RETURN;

};

add the first frame to the appropriate process list

process ← AddProcess[s.process];

process.calls ← process.calls + s.count;

stackDepth ← stackDepth + n;

IF process.level[0] # s.level THEN

FOR i: CARDINAL IN [0..4] DO

IF process.level[i] = s.level THEN EXIT;

IF process.level[i] # 0 THEN LOOP;

process.level[i] ← s.level;

EXIT; ENDLOOP;

levelData[s.level] ← levelData[s.level] + s.count;

[level: 7, n: 0] is the code for an overflow

IF s.level = 7 THEN {overflow ← overflow + s.count; RETURN};

IF n = 0 THEN RETURN ELSE n ← n - 1;

[process.sons, proc] ←

AddSon[process.sons, 0, s.frame[n].gfh, s.frame[n].pc, s.count];

IF proc = NIL THEN {stack ← NIL; RETURN};

IF stack = NIL THEN stack ← NEW[ProcStackRec ← []];

stack.process ← process;

AddFrame[stack, proc, 0];

WHILE TRUE DO

are we at the end of the stack?

IF n = 0 THEN EXIT ELSE n ← n - 1;

proc.calls ← proc.calls + s.count;

add the current frame to the current node

[proc.sons, newSon] ←

AddSon[proc.sons, s.frame[n+1].pc, s.frame[n].gfh, s.frame[n].pc, s.count];

proc ← newSon;

IF proc = NIL THEN EXIT;

AddFrame[stack, proc, s.frame[n+1].pc];

IF Recursive[stack] THEN Undo[stack, s.count];

ENDLOOP;

IF proc # NIL THEN {

add in the leaf counts

proc.count ← proc.count + s.count;

proc.countLocs ← AddCountLocs[list: proc.countLocs, pc: s.frame[0].pc, count: s.count];

IF s.type # ready THEN {

treat as a call even tho it's a count

[proc.sons, newSon] ← AddSon[proc.sons, s.frame[0].pc, NIL, ORD[s.type], s.count];

IF newSon # NIL THEN newSon.count ← newSon.count + s.count;

};

typeData[s.type] ← typeData[s.type] + s.count;

stack.index ← 0;

};

adding to the list of processes

AddProcess: PROC [psb: PrincOps.PsbIndex] RETURNS [process: ProcessRef ← NIL] = {

list: LIST OF ProcessRef ← processes;

should we add it to the beginning of the list?

IF list = NIL OR psb < list.first.psb THEN {

process ← NewProcess[psb];

processes ← CONS[process, processes];

RETURN [process];

};

WHILE list # NIL DO

process ← list.first;

is this the process we want?

IF process.psb = psb THEN RETURN [process];

should the process follow this one?

IF list.rest = NIL OR psb < list.rest.first.psb THEN {

process ← NewProcess[psb];

list.rest ← CONS[process, list.rest];

RETURN [process];

};

list ← list.rest;

ENDLOOP;

ERROR;

};

NewProcess: PROC [psb: PrincOps.PsbIndex] RETURNS [process: ProcessRef] = {

process ← NEW[ProcessRec ← []];

noProcesses ← noProcesses + 1;

process.psb ← psb;

};

adding/deleting procedures from a LIST OF Call

AddSon: PROC
[list: CallList, from: CARDINAL, gfh: GlobalFrameHandle, pc, count: Count]
RETURNS [newList: CallList, procedure: Procedure] = {

INVARIANT: the lists remain sorted

INVARIANT: exactly one LIST OF Call.calls will be incremented

procedure ← NIL;

newList ← list;

should we add it to the beginning of the list?

IF list = NIL OR from < list.first.pc THEN {

procedure ← AddProcedure[gfh, pc];

IF procedure = NIL THEN RETURN [NIL, NIL];

newList ← CONS[[from, count, procedure], list];

noCalls ← noCalls + 1;

RETURN [newList, procedure];

};

WHILE list # NIL DO

procedure ← list.first.proc;

is this the procedure we want?

IF list.first.pc = from AND Equal[gfh, pc, procedure] THEN {

IF list.first.calls = 0 THEN list.first.proc.refs ← list.first.proc.refs + 1;

list.first.calls ← list.first.calls + count;

RETURN [newList, procedure];

};

should the procedure follow this one?

IF list.rest = NIL OR from < list.rest.first.pc THEN {

procedure ← AddProcedure[gfh, pc];

IF procedure = NIL THEN RETURN [NIL, NIL];

list.rest ← CONS[[from, count, procedure], list.rest];

noCalls ← noCalls + 1;

RETURN [newList, procedure];

};

list ← list.rest;

ENDLOOP;

ERROR;

};

RemoveSon: PROC [proc: Procedure, pc: CARDINAL, list: CallList, count: Count]
RETURNS [newList: CallList] = {

INVARIANT: the lists remain sorted

INVARIANT: exactly one LIST OF Call.calls will be decremented

prior: CallList;

FOR s: CallList ← list, s.rest DO

IF s = NIL THEN SIGNAL Error; -- where is it?

IF s.first.proc # proc OR s.first.pc # pc THEN {prior ← s; LOOP};

IF s.first.calls = 0 THEN RETURN [list];

s.first.calls ← s.first.calls - count;

IF s.first.calls = 0 THEN s.first.proc.refs ← s.first.proc.refs - 1;

IF s.first.calls > 0 THEN RETURN[list];

s.first.proc.refs ← s.first.proc.refs - 1;

IF s = list THEN RETURN[list.rest];

prior.rest ← s.rest;

RETURN [list];

ENDLOOP;

};

GreaterThan: PROC [gfh: GlobalFrameHandle, pc: CARDINAL, proc: Procedure] RETURNS [BOOL] = INLINE {

IF gfh # proc.gfh THEN

RETURN [LOOPHOLE[gfh, CARDINAL] > LOOPHOLE[proc.gfh, CARDINAL]];

RETURN [pc > proc.exitPC];

};

Equal: PROC [gfh: GlobalFrameHandle, pc: INT, proc: Procedure]
RETURNS [BOOL] = INLINE {

entryPC, exitPC: INT;

IF proc = NIL THEN RETURN [TRUE]; -- source

IF gfh # proc.gfh THEN RETURN [FALSE];

IF pc < (entryPC ← proc.entryPC) THEN RETURN [FALSE];

IF pc > (exitPC ← proc.exitPC) THEN RETURN [FALSE];

RETURN [TRUE];

};

AddCountLocs: PROC [list: CallList, pc: CARDINAL, count: Count]
RETURNS [new: CallList] ~ {

Insert: PROC [list: CallList] ~ {

SELECT TRUE FROM

list.rest=NIL OR pc<list.rest.first.pc => list.rest ← CONS[call, list.rest];

pc=list.rest.first.pc => list.rest.first.calls ← list.rest.first.calls+count;

ENDCASE => Insert[list.rest];

};

call: Call ~ [pc: pc, calls: count];

IF list=NIL OR pc<list.first.pc THEN RETURN [CONS[call, list]];

Insert[new ← list];

};

adding modules and procedures to the modules list

AddProcedure: PROC [gfh: GlobalFrameHandle, pc: CARDINAL]
RETURNS [procedure: Procedure ← NIL] = {

INVARIANT: the lists remain sorted

INVARIANT: exactly one ref will be incremented

module: Procedure;

list: CallList;

module ← AddModule[gfh];

IF module = NIL THEN RETURN;

list ← module.sons;

should we add it to the beginning of the list?

IF list = NIL OR GreaterThan[gfh, pc, list.first.proc] THEN {

procedure ← NewProcedure[module, pc];

IF procedure = NIL THEN SIGNAL Error;

procedure.refs ← 1;

module.sons ← CONS[[0, 0, procedure], list];

noCalls ← noCalls + 1;

RETURN [procedure];

};

WHILE list # NIL DO

procedure ← list.first.proc;

is this the procedure we want?

IF Equal[gfh, pc, procedure] THEN {

procedure.refs ← procedure.refs + 1;

RETURN [procedure];

};

should the procedure follow this one?

IF list.rest = NIL OR GreaterThan[gfh, pc, list.rest.first.proc] THEN {

procedure ← NewProcedure[module, pc];

IF procedure = NIL THEN SIGNAL Error;

procedure.refs ← 1;

list.rest ← CONS[[0, 0, procedure], list.rest];

noCalls ← noCalls + 1;

RETURN [procedure];

};

list ← list.rest;

ENDLOOP;

ERROR;

};

AddModule: PROC [gfh: GlobalFrameHandle] RETURNS [module: Procedure ← NIL] = {

INVARIANT: the lists remain sorted

list: LIST OF Procedure ← modules;

ValidateGFH[gfh ! RuntimeError.UNCAUGHT => GO TO badGuy];

should we add it to the beginning of the list?

IF list = NIL OR LOOPHOLE[gfh, CARDINAL] > LOOPHOLE[list.first.gfh, CARDINAL] THEN {

module ← NewModule[gfh];

modules ← CONS[module, list];

RETURN [module];

};

WHILE list # NIL DO

module ← list.first;

is this the module we want?

IF gfh = module.gfh THEN RETURN [module];

should the module follow this one?

IF list.rest = NIL
OR LOOPHOLE[gfh, CARDINAL] > LOOPHOLE[list.rest.first.gfh, CARDINAL] THEN {

module ← NewModule[gfh];

list.rest ← CONS[module, list.rest];

RETURN [module];

};

list ← list.rest;

ENDLOOP;

ERROR;

EXITS badGuy => RETURN [NIL];

};

ValidateGFH: PROC [gfh: GlobalFrameHandle] = {

IF gfh # PrincOps.GFT[gfh.gfi].framePtr THEN ERROR;

};

NewModule: PROC [gfh: GlobalFrameHandle] RETURNS [module: Procedure] = {

module ← NEW[ProcRec ← []];

noModules ← noModules + 1;

module.gfh ← gfh;

module.name ← (IF gfh = NIL THEN className ELSE RTTypesPrivate.GFHToName[gfh]);

};

NewProcedure: PROC [module: Procedure, pc: CARDINAL]
RETURNS [procedure: Procedure ← NIL] = {

entryPC, exitPC: CARDINAL ← pc;

IF module.gfh # NIL THEN [entryPC, exitPC] ← PcRange[module.gfh, pc];

procedure ← NEW[ProcRec ← []];

noProcs ← noProcs + 1;

procedure.gfh ← module.gfh;

procedure.entryPC ← entryPC;

procedure.exitPC ← exitPC;

IF module.gfh = NIL THEN {

pcType: StackType ← VAL[pc];

name ← typeName[pcType];

IF name = NIL THEN {

stream: STREAM ← IO.ROS[];

IO.PutF1[stream, "type%g", [cardinal[pc]]];

typeName[pcType] ← name ← IO.RopeFromROS[stream];

};

procedure.name ← Rope.Cat[module.name, Rope.FromChar['.], name];

procedure.named ← name # NIL;

};

PcRange: PROC [gfh: GlobalFrameHandle, pc: CARDINAL]
RETURNS [entry, exit: CARDINAL] = {

procPC, min: CARDINAL ← pc;

ev: LONG POINTER TO PrincOps.CSegPrefix ← LOOPHOLE[gfh.code];

entry ← 0;

exit ← min ← 177777B;

FOR i: CARDINAL IN [0..ev.header.info.ngfi*32) DO

heuristics to see if we are at the end of the entry vector

IF ev.entry[i].initialpc > 77777B THEN EXIT;

IF ev.entry[i].info.framesize > PrincOps.LastAVSlot THEN EXIT;

min ← MIN[min, CARDINAL[ev.entry[i].initialpc/SIZE[PrincOps.EntryVectorItem]]];

IF i+1 >= min THEN EXIT;

determine the entry and exit PCs.

procPC ← ev.entry[i].initialpc*2;

IF entry < procPC AND procPC <= pc THEN entry ← procPC;

IF pc < procPC AND procPC < exit THEN exit ← procPC;

ENDLOOP;

exit ← exit - 1;

};

handling marked stacks

ProcStack: TYPE = REF ProcStackRec;

ProcStackRec: TYPE = RECORD[

process: ProcessRef ← NIL,

index: CARDINAL ← 0,

frame: ARRAY [0..SpyOps.stackLength) OF RECORD [

proc: Procedure ← NIL,

pc: CARDINAL ← 0]];

AddFrame: PROC [stack: ProcStack, proc: Procedure, pc: CARDINAL] = INLINE {

stack.frame[stack.index] ← [proc, pc];

stack.index ← stack.index + 1;

};

Recursive: PROC [stack: ProcStack] RETURNS [BOOL] = INLINE {

IF stack.index = 0 THEN RETURN [FALSE];

FOR i: CARDINAL DECREASING IN [0..stack.index-1) DO

IF stack.frame[i].proc = stack.frame[stack.index-1].proc THEN RETURN [TRUE];

ENDLOOP;

RETURN [FALSE];

};

Undo: PROC [stack: ProcStack, count: Count] = {

first, proc: Procedure;

IF stack.index = 0 THEN RETURN;

first ← stack.frame[stack.index-1].proc;

FOR i: CARDINAL DECREASING IN [0..stack.index-1) DO

proc ← stack.frame[i].proc;

proc.sons ← RemoveSon[stack.frame[i+1].proc, stack.frame[i+1].pc, proc.sons, count];

proc.calls ← proc.calls - count;

IF proc = first THEN {stack.index ← i + 1; RETURN};

ENDLOOP;

ERROR;

};

determining the precedence relationships

ClearContainers: PROC = {

FOR m: LIST OF Procedure ← modules, m.rest WHILE m # NIL DO

FOR p: CallList ← m.first.sons, p.rest WHILE p # NIL DO

p.first.proc.container ← NIL;

ENDLOOP;

};

SetAllContainers: PROC = {

SetAllParents[];

set the root containers

FOR a: LIST OF ProcessRef ← processes, a.rest WHILE a # NIL DO

FOR s: CallList ← a.first.sons, s.rest WHILE s # NIL DO

s.first.proc.container ← s.first.proc;

ENDLOOP;

chase down the trees

FOR a: LIST OF ProcessRef ← processes, a.rest WHILE a # NIL DO

FOR p: CallList ← a.first.sons, p.rest WHILE p # NIL DO

SetContainers[p.first.proc.sons];

ENDLOOP;

catch all of the ones we missed

FOR m: LIST OF Procedure ← modules, m.rest WHILE m # NIL DO

FOR p: CallList ← m.first.sons, p.rest WHILE p # NIL DO

IF p.first.proc.container # NIL THEN LOOP;

p.first.proc.container ← Container[p.first.proc];

IF p.first.proc.container = NIL THEN p.first.proc.container ← p.first.proc;

ENDLOOP;

};

SetAllParents: PROC = {

FOR m: LIST OF Procedure ← modules, m.rest WHILE m # NIL DO

FOR p: CallList ← m.first.sons, p.rest WHILE p # NIL DO

proc: Procedure ← p.first.proc; -- for each procedure . . .

FOR s: CallList ← proc.sons, s.rest WHILE s # NIL DO

found: BOOL ← FALSE;

IF s.first.calls = 0 THEN LOOP;

FOR f: LIST OF Procedure ← s.first.proc.parents, f.rest WHILE f # NIL DO

IF f.first = proc THEN {found ← TRUE; EXIT};

ENDLOOP;

. . . add self to son's parent list

IF ~found THEN s.first.proc.parents ← CONS[proc, s.first.proc.parents];

ENDLOOP;

};

SetContainers: PROC [sons: CallList] = {

FOR s: CallList ← sons, s.rest WHILE s # NIL DO

p: Procedure ← s.first.proc;

IF p.container # NIL THEN LOOP;

p.container ← Container[p];

IF p.container = NIL THEN LOOP;

SetContainers[p.sons];

ENDLOOP;

};

Container: PROC [proc: Procedure] RETURNS [c: Procedure ← NIL] = {

determine the intersection of the procedures that references proc

proc.marked ← TRUE;

FOR f: LIST OF Procedure ← proc.parents, f.rest WHILE f # NIL DO

IF f.first.marked THEN LOOP; -- already traversed it

IF f.first.container = NIL THEN {

cf: Procedure ← f.first.container ← Container[f.first];

IF cf = NIL THEN LOOP;

};

IF c = NIL THEN {c ← f.first; LOOP};

c ← Intersection[c, f.first];

IF c = NIL THEN {proc.marked ← FALSE; RETURN [proc]}; -- no container

ENDLOOP;

proc.marked ← FALSE;

};

Intersection: PROC [a, b: Procedure] RETURNS [Procedure] = {

IF a = b THEN RETURN [a];

FOR c: Procedure ← a, c.container DO

IF c.container = b THEN RETURN [b];

IF c.container = c THEN EXIT;

ENDLOOP;

FOR c: Procedure ← b, c.container DO

IF c.container = a THEN RETURN [a];

IF c.container = c THEN EXIT;

ENDLOOP;

IF a = a.container OR b = b.container THEN RETURN [NIL];

a ← a.container;

b ← b.container;

ENDLOOP;

};

some printing

PrintStatistics: PROC [stream: STREAM] = {

seconds: INTEGER;

IF wakeups = 0 THEN RETURN;

print general statistics

seconds ← MAX[Real.Round[BasicTime.PulsesToSeconds[SpyOps.runningTime]], 1];

IO.PutF[stream, "Spy ran for %g minutes %g seconds.\n",

[cardinal[seconds / 60]], [cardinal[seconds MOD 60]]];

SELECT current FROM

CPU, process, breakProcess, allocations, wordsAllocated =>

IO.PutF1[stream, "Sampling frequency divisor was %g.\n", [integer[freqDivisor]]];

pagefaults, userDefined => NULL;

ENDCASE => ERROR;

IO.PutF1[stream, "Total wakeups = %g", [cardinal[wakeups]]];

IO.PutF1[stream, " (%g per second).\n", [cardinal[wakeups/seconds]]];

IF current # pagefaults THEN {

IO.PutF1[stream, "Total page faults = %g", [cardinal[SpyOps.pageFaults]]];

IO.PutF1[stream, " (%g per second).\n", [cardinal[SpyOps.pageFaults/seconds]]];

};

IO.PutF1[stream, "Total words allocated = %g", [cardinal[SpyOps.wordsAllocated]]];

IO.PutF1[stream, " (%g per second).\n", [cardinal[SpyOps.wordsAllocated/seconds]]];

IO.PutF1[stream, "Total words reclaimed = %g", [cardinal[SpyOps.wordsReclaimed]]];

IO.PutF1[stream, " (%g per second).\n", [cardinal[SpyOps.wordsReclaimed/seconds]]];

print how the processor was used

IO.PutRope[stream, "\nScheduled Process-Priority Summary:\n"];

IF notScheduled # 0 THEN {

IO.PutRope[stream, " processor idle"];

PrintCount[stream, notScheduled, 0, wakeups];

};

IF skips # 0 THEN {

IO.PutRope[stream, " processor waiting on disk"];

PrintCount[stream, skips, 0, wakeups];

};

FOR i: Process.Priority IN Process.Priority DO

IF count # 0 THEN {

IO.PutF1[stream, " priority %g", [rope[LevelName[i]]]];

PrintCount[stream, count, 0, wakeups];

};

ENDLOOP;

IO.PutRope[stream, "\n"];

print breakdown by types:

IF className # NIL THEN {

header: ROPE;

headerPrinted: BOOL ← FALSE;

SELECT current FROM

pagefaults => header ← "Breakdown By Type Of Pagefault:\n";

allocations, wordsAllocated => header ← "Breakdown By Type Of Allocation:\n";

ENDCASE => header ← "Breakdown By Type Of Action:\n";

FOR i: StackType IN StackType DO

IF name = NIL OR typeData[i] = 0 THEN LOOP;

IF ~headerPrinted THEN {

IO.PutRope[stream, header];

headerPrinted ← TRUE;

};

IF current IN [process..breakProcess] THEN {

IO.PutRope[stream, " "];

IO.PutRope[stream, name];

};

PrintCount[stream, typeData[i], 0, wakeups];

ENDLOOP;

IO.PutRope[stream, "\n"];

};

PrintInstructions: PROC [stream: STREAM] = {

IO.PutRope[stream, "Instructions (see SpyDoc.tioga for more information):
\tIndentation is used to show containment.
\tPeriods are used to keep track of procedures at the same level of indentation.
\tExclamation points (!) are used to group together sets of disjoint procedures.
\tItalics are used to indicate procedures with more than one parent.
\tBold is used to indicate procedures with allocations or page faults.
\tImpl.Proc = x, y (o%) (z%):
\t x = counts in Impl.Proc.
\t y = counts in procedures called from Impl.Proc.
\t o = x/ total % (only displayed if > 1%).
\t z = (x + y)/ total = % time in the call stack.

"];

};

PrintLogStatistics: PROC [stream: STREAM] = {

allocated: Count ← noProcesses*SIZE[ProcessRec] + noCalls*SIZE[Call] +

noModules*SIZE[ProcRec] + noProcs*SIZE[ProcRec];

IO.PutRope[stream, "Statistics on execution of Cedar Spy:\n"];

FOR i: NAT IN [0..3] DO

IF count > 0 THEN {

IO.PutF1[stream, "\t%g spy samples averaged ", [cardinal[count]]];

PrintTime[stream, spyTime[i].time/count];

};

ENDLOOP;

IF LOOPHOLE[readLog, INT] > 0 THEN {

to avoid wrap around

IO.PutRope[stream, "\tProcessed log in "];

PrintTime[stream, readLog];

};

IO.PutF1[stream, " Total samples read from log = %g.\n", [cardinal[processed]]];

IF overflow > 0 THEN

IO.PutF[stream,
"\t%g SAMPLES WITH STACKS OF >= %g FRAMES!\n",
[cardinal[error]], [cardinal[SpyOps.stackLength]]];

IF error > 0 THEN

IO.PutF1[stream, "\t%g SAMPLES WERE CUT SHORT BECAUSE OF ERRORS!\n", [cardinal[error]]];

IF processed > 0 THEN

IO.PutF1[stream, "\tAverage stack depth = %g.\n", [cardinal[stackDepth/processed]]];

IO.PutF1[stream, "\tNo. modules allocated = %g.\n", [cardinal[noModules]]];

IO.PutF1[stream, "\tNo. procedures allocated = %g.\n", [cardinal[noProcs]]];

IO.PutF1[stream, "\tTotal words allocated = %g.\n\n", [cardinal[allocated]]];

};

LevelName: ARRAY Process.Priority OF ROPE ← [

"idle", "background", "normal", "foreground",

"foreforeground", "faultHandlers", "realTime", "swat"];

PrintCount: PUBLIC PROC [stream: STREAM, c, sonC: Count, total: Count] = {

IF c = 0 AND sonC = 0 THEN {IO.PutRope[stream, "\n"]; RETURN};

IO.PutF1[stream, " = %g", [cardinal[c]]];

IF sonC # 0 THEN IO.PutF1[stream, ", %g", [cardinal[sonC]]];

IF total = 0 THEN {IO.PutRope[stream, "\n"]; RETURN};

IF (c*100/total) > 1 AND sonC # 0 THEN PerCent[stream, c, total];

PerCent[stream, c+sonC, total];

IO.PutRope[stream, ".\n"];

};

PerCent: PUBLIC PROC [stream: STREAM, x, y: Count] = {

q, r: Count;

sign: INT ← 1;

IF y = 0 THEN y ← 1;

q ← Real.Round[(REAL[x]*1000.0)/REAL[y]];

IF q < 0 THEN {sign ← -1; q ← -q};

r ← IF q = 0 AND x # 0 THEN 1 ELSE (q MOD 10); -- to avoid 0.0%

q ← (q/10);

IO.PutF[stream, " (%g.%g%%)", [integer[sign*q]], [cardinal[r]] ];

};

PrintTime: PROC [stream: STREAM, pulses: BasicTime.Pulses] = {

micros: CARD ← BasicTime.PulsesToMicroseconds[pulses];

secs: CARD ← micros / 1000000;

uSecs: CARD ← micros MOD 1000;

mSecs: CARD ← (micros MOD 1000000) / 1000;

IF secs # 0 OR mSecs > 10

THEN IO.PutF[stream, "%g.%g seconds.", [cardinal[secs]], [cardinal[mSecs]]]

ELSE IO.PutF[stream, "%g.%g milliseconds.", [cardinal[mSecs]], [cardinal[uSecs]]];

};

debugging facilities

Find: PROC [name: ROPE] RETURNS [Procedure] = {

list: LIST OF Procedure ← modules;

FOR m: LIST OF Procedure ← list, m.rest WHILE m # NIL DO

IF Rope.Equal[name, m.first.name] THEN RETURN [m.first];

IF list # modules THEN LOOP;

FOR p: CallList ← m.first.sons, p.rest WHILE p # NIL DO

IF Rope.Equal[name, p.first.proc.name] THEN RETURN [p.first.proc];

ENDLOOP;

RETURN [NIL];

};

}..