DIRECTORY AMBridge USING [TVForPointerReferent], AMTypes USING [TV, TVType, TypeToName], BasicTime USING [GetClockPulses, Pulses, PulsesToMicroseconds, PulsesToSeconds], IO USING [card, char, CR, int, ROS, RopeFromROS, Put, PutChar, PutF, rope, STREAM, TAB], PrincOps USING [BytePC, CSegPrefix, EntryVectorItem, GFTIndex, GlobalFrameHandle, LastAVSlot, NullPsbHandle, PsbIndex, PsbHandle], PrincOpsUtils USING [PsbHandleToIndex], PrintTV USING [Print], Process USING [Priority], RealOps USING [RoundI], Rope USING [Cat, FromChar, Equal, ROPE], RTSymbolDefs USING [CallableBodyIndex, SymbolTableBase], RTSymbolOps USING [AcquireRope, BodyName], RTSymbols USING [AcquireSTBFromGFH, ReleaseSTB], RTTypesPrivate USING [GetCBTI, GetEp, GFHToName], SpyLog USING [active, Close, Entry, NextEntry, OpenForRead], SpyOps USING [Call, Count, DataType, GFHFromGFI, LevelData, pageFaults, Procedure, ProcessRef, ProcessRec, ProcRec, runningTime, Stack, stackHeader, stackLength, StackType, wordsAllocated, wordsReclaimed], ViewerIO USING [CreateViewerStreams]; SpyLogReaderImpl: PROGRAM IMPORTS AMBridge, AMTypes, BasicTime, IO, PrincOpsUtils, PrintTV, RealOps, Rope, RTSymbolOps, RTSymbols, RTTypesPrivate, SpyLog, SpyOps, ViewerIO EXPORTS SpyOps = BEGIN OPEN IO, SpyOps; ROPE: TYPE = Rope.ROPE; Error: SIGNAL = CODE; -- global variables and types -- processes: PUBLIC LIST OF ProcessRef _ NIL; modules: PUBLIC LIST OF Procedure _ NIL; current: SpyOps.DataType; DestroyLog: PUBLIC PROCEDURE = { NilLinks: PROC[proc: Procedure] RETURNS[BOOLEAN _ 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 PROCEDURE[typescript: IO.STREAM, datatype: SpyOps.DataType, spyOnSpyLog: BOOL] = BEGIN ignoreBefore: BasicTime.Pulses _ 0; IF typescript = NIL THEN typescript _ ViewerIO.CreateViewerStreams["Spy log"].out; typescript.Put[rope["(Please wait-- processing log.)\n\n"]]; current _ datatype; typeName _ ALL[NIL]; SELECT current FROM CPU => className _ NIL; process, breakProcess => { className _ "waiting"; typeName[0] _ "executing"; typeName[1] _ "pagefault"; typeName[2] _ "ML"; typeName[3] _ "CV"; typeName[4] _ "preempted"}; pagefaults => { className _ "pagefault"; typeName[1] _ "data"; typeName[2] _ "code"; typeName[3] _ "xfer"}; allocations, wordsAllocated => { className _ "allocation"; typeName[0] _ "safe"; typeName[1] _ "permanent"; typeName[2] _ "unsafe"}; userDefined => className _ "userBreaks"; ENDCASE => ERROR; typeData _ ALL[0]; IF useTrigger THEN { ignoreBefore _ FindTrigger[]; IF ignoreBefore = LOOPHOLE[0] THEN { typescript.Put[rope["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]; END; useTrigger: BOOLEAN _ FALSE; triggerExtent: BasicTime.Pulses; whichTrigger: NAT _ 1; SetTrigger: PROC[extent: BasicTime.Pulses, which: NAT _ 1, enable: BOOLEAN _ TRUE] = BEGIN useTrigger _ enable; triggerExtent _ extent; whichTrigger _ which; END; FindTrigger: PROC RETURNS[trigger: BasicTime.Pulses] = BEGIN count: NAT _ 0; entry: LONG POINTER TO SpyLog.Entry; SpyLog.OpenForRead[]; -- open for reading WHILE TRUE DO entry _ SpyLog.NextEntry[]; 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]; END; out: IO.STREAM; 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.ROPE; typeData: ARRAY StackType OF Count; className: Rope.ROPE; 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 recordSpyTime: BOOLEAN _ FALSE; spyTime: ARRAY [0..3] OF RECORD[ count: Count, time: BasicTime.Pulses]; ReadSpyLog: PROCEDURE[ignoreBefore: BasicTime.Pulses, spyOnSpyLog: BOOL] = BEGIN i: CARDINAL; data: BOOLEAN _ FALSE; dataSize: CARDINAL _ 0; first, last: BasicTime.Pulses _ 0; active: BOOLEAN _ 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 entry _ SpyLog.NextEntry[]; 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; out.PutF["%l uSeconds delta data\n", char['f]]}; IF e.process # process THEN { out.PutF[" Switch to process: %b\n", card[PrincOpsUtils.PsbHandleToIndex[e.process]]]; process _ e.process}; PrintTrace[e.gfi, 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; stack _ NIL; out _ NIL; END; PrintEntry: PROCEDURE[type, words: CARDINAL, data: LONG POINTER, time, delta: BasicTime.Pulses] = BEGIN value: AMTypes.TV; IF out = NIL THEN { out _ ViewerIO.CreateViewerStreams["auxilary spy log"].out; out.PutF["%l uSeconds delta data\n", char['f]]}; value _ AMBridge.TVForPointerReferent[data, LOOPHOLE[type]]; out.PutF["%9d%9d %g: \n", card[BasicTime.PulsesToMicroseconds[time]], card[BasicTime.PulsesToMicroseconds[delta]], rope[AMTypes.TypeToName[AMTypes.TVType[value]]]]; PrintTV.Print[value, out]; out.PutChar[IO.CR]; END; PrintTrace: PROCEDURE[gfi: PrincOps.GFTIndex, pc: PrincOps.BytePC, time, delta: BasicTime.Pulses] = BEGIN name: Rope.ROPE _ GetName[gfi, pc]; out.PutF["%9d%9d %g (gfi: %g, pc: %g)\n", card[BasicTime.PulsesToMicroseconds[time]], card[BasicTime.PulsesToMicroseconds[delta]], rope[name], card[gfi], card[pc]]; END; GetName: PROC[gfi: PrincOps.GFTIndex, pc: PrincOps.BytePC] RETURNS[name: Rope.ROPE] = BEGIN proc: Rope.ROPE; gfh: PrincOps.GlobalFrameHandle; stb: RTSymbolDefs.SymbolTableBase _ [x[e: NIL]]; gfh _ SpyOps.GFHFromGFI[gfi]; name _ RTTypesPrivate.GFHToName[gfh]; BEGIN ENABLE ANY => {IF stb # [x[e: NIL]] THEN RTSymbols.ReleaseSTB[stb]; 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]; END; RETURN[Rope.Cat[name, ".", proc]]; END; -- tree management -- Initialize: PROCEDURE = BEGIN 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; END; EnumerateProcs: PROCEDURE[userProc: PROC[Procedure] RETURNS[BOOLEAN]] RETURNS[last: Procedure] = BEGIN FOR m: LIST OF Procedure _ modules, m.rest WHILE m # NIL DO FOR p: LIST OF Call _ m.first.sons, p.rest WHILE p # NIL DO IF userProc[p.first.proc] THEN RETURN[p.first.proc]; ENDLOOP; ENDLOOP; RETURN[NIL]; END; -- adding a stack to the call tree -- stack: ProcStack; EnterStack: PROCEDURE[s: LONG POINTER TO SpyOps.Stack, n: CARDINAL] = BEGIN ENABLE Error => {error _ error + 1; CONTINUE}; 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 0 => notScheduled _ notScheduled + s.count; 1 => skips _ skips + s.count; ENDCASE => error _ error + s.count; RETURN}; 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; 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].gfi, s.frame[n].pc, s.count]; IF stack = NIL THEN stack _ NEW[ProcStackRec _ []]; stack.process _ process; AddFrame[stack, proc, 0]; WHILE TRUE DO IF n = 0 THEN EXIT ELSE n _ n - 1; proc.calls _ proc.calls + s.count; [proc.sons, newSon] _ AddSon[proc.sons, s.frame[n+1].pc, s.frame[n].gfi, s.frame[n].pc, s.count]; proc _ newSon; AddFrame[stack, proc, s.frame[n+1].pc]; IF Recursive[stack] THEN { Undo[stack, s.count]}; ENDLOOP; proc.count _ proc.count + s.count; IF s.type # 0 THEN { -- treat as a call even tho it's a count [proc.sons, newSon] _ AddSon[proc.sons, s.frame[0].pc, 0, s.type, s.count]; newSon.count _ newSon.count + s.count}; typeData[s.type] _ typeData[s.type] + s.count; stack.index _ 0; END; -- adding to the list of processes -- AddProcess: PROCEDURE[psb: PrincOps.PsbIndex] RETURNS[process: ProcessRef _ NIL] = BEGIN list: LIST OF ProcessRef _ processes; 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; IF process.psb = psb THEN RETURN[process]; 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; END; NewProcess: PROCEDURE[psb: PrincOps.PsbIndex] RETURNS[process: ProcessRef] = BEGIN process _ NEW[ProcessRec _ []]; noProcesses _ noProcesses + 1; process.psb _ psb; END; -- adding/deleting procedures from a LIST OF Call -- AddSon: PROC[list: LIST OF Call, from: CARDINAL, gfi: PrincOps.GFTIndex, pc, count: Count] RETURNS[newList: LIST OF Call, procedure: Procedure] = BEGIN procedure _ NIL; newList _ list; IF list = NIL OR from < list.first.pc THEN { procedure _ AddProcedure[gfi, pc]; newList _ CONS[[from, count, procedure], list]; noCalls _ noCalls + 1; RETURN[newList, procedure]}; WHILE list # NIL DO procedure _ list.first.proc; IF list.first.pc = from AND Equal[gfi, 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]}; IF list.rest = NIL OR from < list.rest.first.pc THEN { procedure _ AddProcedure[gfi, pc]; list.rest _ CONS[[from, count, procedure], list.rest]; noCalls _ noCalls + 1; RETURN[newList, procedure]}; list _ list.rest; ENDLOOP; ERROR; END; RemoveSon: PROC[proc: Procedure, pc: CARDINAL, list: LIST OF Call, count: Count] RETURNS[newList: LIST OF Call] = BEGIN prior: LIST OF Call; FOR s: LIST OF Call _ 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; RETURN[list]; ENDLOOP; END; GreaterThan: PROC[gfi: PrincOps.GFTIndex, pc: CARDINAL, proc: Procedure] RETURNS[BOOLEAN] = INLINE BEGIN IF gfi > proc.gfi THEN RETURN[TRUE]; IF gfi < proc.gfi THEN RETURN[FALSE]; IF pc > proc.exitPC THEN RETURN[TRUE]; RETURN[FALSE]; END; Equal: PROC[gfi: PrincOps.GFTIndex, pc: INT, proc: Procedure] RETURNS[BOOLEAN] = INLINE BEGIN entryPC, exitPC: INT; IF proc = NIL THEN RETURN[TRUE]; -- source IF gfi # proc.gfi THEN RETURN[FALSE]; IF pc < (entryPC _ proc.entryPC) THEN RETURN[FALSE]; IF pc > (exitPC _ proc.exitPC) THEN RETURN[FALSE]; RETURN[TRUE]; END; -- adding modules and procedures to the modules list -- AddProcedure: PROCEDURE[gfi: PrincOps.GFTIndex, pc: CARDINAL] RETURNS[procedure: Procedure] = BEGIN module: Procedure; list: LIST OF Call; module _ AddModule[gfi]; procedure _ NIL; list _ module.sons; IF list = NIL OR GreaterThan[gfi, 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; IF Equal[gfi, pc, procedure] THEN { procedure.refs _ procedure.refs + 1; RETURN[procedure]}; IF list.rest = NIL OR GreaterThan[gfi, 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; END; AddModule: PROCEDURE[gfi: PrincOps.GFTIndex] RETURNS[module: Procedure] = BEGIN list: LIST OF Procedure; module _ NIL; list _ modules; IF list = NIL OR gfi > list.first.gfi THEN { module _ NewModule[gfi]; modules _ CONS[module, list]; RETURN[module]}; WHILE list # NIL DO module _ list.first; IF gfi = module.gfi THEN RETURN[module]; IF list.rest = NIL OR gfi > list.rest.first.gfi THEN { module _ NewModule[gfi]; list.rest _ CONS[module, list.rest]; RETURN[module]}; list _ list.rest; ENDLOOP; ERROR; END; NewModule: PROCEDURE[gfi: PrincOps.GFTIndex] RETURNS[module: Procedure] = BEGIN module _ NEW[ProcRec _ []]; noModules _ noModules + 1; module.gfi _ gfi; module.name _ (IF gfi = 0 THEN className ELSE RTTypesPrivate.GFHToName[SpyOps.GFHFromGFI[gfi]]); END; NewProcedure: PROCEDURE[module: Procedure, pc: CARDINAL] RETURNS[procedure: Procedure _ NIL] = BEGIN name: ROPE; entryPC, exitPC: CARDINAL _ pc; IF module.gfi # 0 THEN [entryPC, exitPC] _ PcRange[module.gfi, pc]; procedure _ NEW[ProcRec _ []]; noProcs _ noProcs + 1; procedure.gfi _ module.gfi; procedure.entryPC _ entryPC; procedure.exitPC _ exitPC; IF module.gfi = 0 THEN name _ typeName[pc]; IF module.gfi = 0 AND name = NIL THEN { stream: IO.STREAM _ IO.ROS[]; stream.Put[rope["type"], card[pc]]; typeName[pc] _ name _ IO.RopeFromROS[stream]}; procedure.name _ Rope.Cat[module.name, Rope.FromChar['.], name]; procedure.named _ name # NIL; END; PcRange: PROCEDURE[gfi: PrincOps.GFTIndex, pc: CARDINAL] RETURNS[entry, exit: CARDINAL] = BEGIN procPC, min: CARDINAL _ pc; gfh: PrincOps.GlobalFrameHandle; ev: LONG POINTER TO PrincOps.CSegPrefix; entry _ 0; exit _ min _ 177777B; gfh _ SpyOps.GFHFromGFI[gfi]; ev _ LOOPHOLE[gfh.code]; FOR i: CARDINAL IN [0..ev.header.info.ngfi*32) DO IF ev.entry[i].initialpc > 77777B THEN EXIT; IF ev.entry[i].info.framesize > PrincOps.LastAVSlot THEN EXIT; min _ MIN[min, ev.entry[i].initialpc/SIZE[PrincOps.EntryVectorItem]]; IF i+1 >= min THEN EXIT; 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; END; -- 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: PROCEDURE[stack: ProcStack, proc: Procedure, pc: CARDINAL] = INLINE {stack.frame[stack.index] _ [proc, pc]; stack.index _ stack.index + 1}; Recursive: PROCEDURE[stack: ProcStack] RETURNS[BOOLEAN] = INLINE BEGIN 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]; END; Undo: PROCEDURE[stack: ProcStack, count: Count] = BEGIN 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; END; ClearContainers: PROCEDURE = BEGIN FOR m: LIST OF Procedure _ modules, m.rest WHILE m # NIL DO FOR p: LIST OF Call _ m.first.sons, p.rest WHILE p # NIL DO p.first.proc.container _ NIL; ENDLOOP; ENDLOOP; END; SetAllContainers: PROCEDURE = BEGIN SetAllParents[]; FOR a: LIST OF ProcessRef _ processes, a.rest WHILE a # NIL DO FOR s: LIST OF Call _ a.first.sons, s.rest WHILE s # NIL DO s.first.proc.container _ s.first.proc; ENDLOOP; ENDLOOP; FOR a: LIST OF ProcessRef _ processes, a.rest WHILE a # NIL DO FOR p: LIST OF Call _ a.first.sons, p.rest WHILE p # NIL DO SetContainers[p.first.proc.sons]; ENDLOOP; ENDLOOP; FOR m: LIST OF Procedure _ modules, m.rest WHILE m # NIL DO FOR p: LIST OF Call _ 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; ENDLOOP; END; SetAllParents: PROC = BEGIN proc: Procedure; found: BOOLEAN; FOR m: LIST OF Procedure _ modules, m.rest WHILE m # NIL DO FOR p: LIST OF Call _ m.first.sons, p.rest WHILE p # NIL DO proc _ p.first.proc; -- for each procedure . . . FOR s: LIST OF Call _ proc.sons, s.rest WHILE s # NIL DO found _ 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; IF ~found THEN s.first.proc.parents _ CONS[proc, s.first.proc.parents]; ENDLOOP; ENDLOOP; ENDLOOP; END; SetContainers: PROCEDURE[sons: LIST OF Call] = BEGIN FOR s: LIST OF Call _ sons, s.rest DO IF s = NIL THEN EXIT; IF s.first.proc.container # NIL THEN LOOP; s.first.proc.container _ Container[s.first.proc]; IF s.first.proc.container = NIL THEN LOOP; SetContainers[s.first.proc.sons]; ENDLOOP; END; Container: PROCEDURE[proc: Procedure] RETURNS[c: Procedure _ NIL] = BEGIN 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 f.first.container _ Container[f.first]; IF f.first.container = 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; END; Intersection: PROCEDURE[a, b: Procedure] RETURNS[Procedure] = BEGIN DO 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; END; PrintStatistics: PROCEDURE[stream: IO.STREAM] = BEGIN seconds: INTEGER; IF wakeups = 0 THEN RETURN; seconds _ MAX[1, RealOps.RoundI[BasicTime.PulsesToSeconds[SpyOps.runningTime]]]; stream.PutF["Spy ran for %g minutes %g seconds.\n", card[seconds/60], card[seconds MOD 60]]; stream.Put[rope["Total wakeups = "], card[wakeups]]; stream.Put[rope[" ("], card[wakeups/seconds], rope[" per second).\n"]]; IF current # pagefaults THEN { stream.Put[rope["Total page faults = "], card[SpyOps.pageFaults]]; stream.Put[rope[" ("], card[SpyOps.pageFaults/seconds], rope[" per second).\n"]]}; stream.Put[rope["Total words allocated = "], card[SpyOps.wordsAllocated]]; stream.Put[rope[" ("], card[SpyOps.wordsAllocated/seconds], rope[" per second).\n"]]; stream.Put[rope["Total words reclaimed = "], card[SpyOps.wordsReclaimed]]; stream.Put[rope[" ("], card[SpyOps.wordsReclaimed/seconds], rope[" per second).\n"]]; stream.Put[rope["\nScheduled Process-Priority Summary:\n"]]; IF notScheduled # 0 THEN { stream.Put[rope[" processor idle"]]; PrintCount[stream, notScheduled, 0, wakeups]}; IF skips # 0 THEN { stream.Put[rope[" processor waiting on disk"]]; PrintCount[stream, skips, 0, wakeups]}; FOR i: Process.Priority IN Process.Priority DO IF levelData[i] = 0 THEN LOOP; stream.Put[rope[" priority "], rope[LevelName[i]]]; PrintCount[stream, levelData[i], 0, wakeups]; ENDLOOP; stream.Put[char[CR]]; IF className # NIL THEN { header: Rope.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 typeName[i] = NIL OR typeData[i] = 0 THEN LOOP; IF ~headerPrinted THEN { stream.Put[rope[header]]; headerPrinted _ TRUE}; IF current IN [process..breakProcess] AND i # 0 THEN stream.Put[rope[" waiting "], rope[typeName[i]]] ELSE stream.Put[rope[" "], IF typeName[i] # NIL THEN rope[typeName[i]] ELSE int[i]]; PrintCount[stream, typeData[i], 0, wakeups]; ENDLOOP; stream.Put[char[CR]]}; END; PrintInstructions: PROCEDURE[stream: IO.STREAM] = BEGIN stream.Put[rope["Instructions (see SpyDoc.tioga for more information):"], char[CR]]; stream.Put[char[TAB], rope["Indentation is used to show containment."], char[CR]]; stream.Put[char[TAB], rope["Periods are used to keep track of procedures at the same level of indentation."], char[CR]]; stream.Put[char[TAB], rope["Exclamation points (!) are used to group together sets of disjoint procedures."], char[CR]]; stream.Put[char[TAB], rope["Italics are used to indicate procedures with more than one parent."], char[CR]]; stream.Put[char[TAB], rope["Bold is used to indicate procedures which actually had allocations or page faults."], char[CR]]; stream.Put[char[TAB], rope["Impl.Proc = x, y (o%) (z%):"], char[CR]]; stream.Put[char[TAB], rope[" x = counts in Impl.Proc."], char[CR]]; stream.Put[char[TAB], rope[" y = counts in procedures called from Impl.Proc."], char[CR]]; stream.Put[char[TAB], rope[" o = x/ total % (only displayed if > 1%)."], char[CR]]; stream.Put[char[TAB], rope[" z = (x + y)/ total = % time IN THE CALL STACK."], char[CR]]; stream.Put[char[CR]]; END; PrintLogStatistics: PROCEDURE[stream: IO.STREAM] = BEGIN allocated: Count; stream.Put[rope["Statistics on execution of Cedar Spy:"], char[CR]]; IF spyTime[0].count > 0 THEN { stream.Put[ char[TAB], card[spyTime[0].count], rope[" spy samples averaged "]]; PrintTime[stream, BasicTime.PulsesToMicroseconds[spyTime[0].time]/spyTime[0].count]}; IF spyTime[1].count > 0 THEN { stream.Put[ char[TAB], card[spyTime[1].count], rope[" spy samples averaged "]]; PrintTime[stream, BasicTime.PulsesToMicroseconds[spyTime[1].time]/spyTime[1].count]}; IF spyTime[2].count > 0 THEN { stream.Put[ char[TAB], card[spyTime[2].count], rope[" spy samples averaged "]]; PrintTime[stream, BasicTime.PulsesToMicroseconds[spyTime[2].time]/spyTime[2].count]}; IF spyTime[3].count > 0 THEN { stream.Put[ char[TAB], card[spyTime[3].count], rope[" spy samples averaged "]]; PrintTime[stream, BasicTime.PulsesToMicroseconds[spyTime[3].time]/spyTime[3].count]}; IF readLog IN (0..10000000] THEN {-- to avoid wrap around stream.Put[ char[TAB], rope["Processed log in "]]; PrintTime[stream, BasicTime.PulsesToMicroseconds[readLog]]}; stream.Put[ rope["\tTotal samples read from log = "], card[processed], rope[".\n"]]; IF overflow > 0 THEN stream.Put[char[TAB], card[overflow], rope[" SAMPLES WITH STACKS OF >= 75 FRAMES!\n"]]; IF error > 0 THEN stream.Put[char[TAB], card[error], rope[" SAMPLES WERE CUT SHORT BECAUSE OF ERRORS!\n"]]; IF processed > 0 THEN stream.Put[rope["\tAverage stack depth = "], card[stackDepth/processed], rope[".\n"]]; stream.Put[rope["\tNo. modules allocated = "], card[noModules], rope[".\n"]]; stream.Put[rope["\tNo. procedures allocated = "], card[noProcs], rope[".\n"]]; allocated _ noProcesses*SIZE[ProcessRec] + noCalls*SIZE[Call] + noModules*SIZE[ProcRec] + noProcs*SIZE[ProcRec]; stream.Put[rope["\tTotal words allocated = "], card[allocated], rope[".\n"]]; stream.Put[char[CR]]; END; perCentCR: ROPE = Rope.Cat["%).", Rope.FromChar[CR]]; LevelName: PROCEDURE[l: Process.Priority] RETURNS[ROPE] = INLINE {RETURN[SELECT l FROM 0 => "monitoring", 3 => "foreground", 1 => "background", 4 => "pagefaultLow", 2 => "normal", 5 => "pagefaultHigh", ENDCASE => "interrupt"]}; PrintCount: PROCEDURE[stream: IO.STREAM, c, sonC: Count, total: Count] = BEGIN IF c = 0 AND sonC = 0 THEN {stream.Put[char[CR]]; RETURN}; stream.Put[rope[" = "], card[c]]; IF sonC # 0 THEN stream.Put[rope[", "], card[sonC]]; IF total = 0 THEN {stream.Put[char[CR]]; RETURN}; IF (c*100/total) > 1 AND sonC # 0 THEN PerCent[stream, c, total]; PerCent[stream, c+sonC, total]; stream.Put[char['.], char[CR]]; END; PerCent: PROCEDURE[stream: IO.STREAM, x, y: Count] = BEGIN q, r: Count; IF y = 0 THEN y _ 1; q _ (x*1000)/y; r _ q MOD 10; q _ q/10; IF q = 0 AND r = 0 AND x # 0 THEN r _ 1; -- to avoid 0.0% stream.Put[rope[" ("], card[q], char['.]]; stream.Put[card[r], rope["%)"]]; END; PrintTime: PROCEDURE[stream: IO.STREAM, ticks: LONG CARDINAL] = BEGIN secs,mSecs,uSecs: LONG CARDINAL; uSecs _ ticks; secs _ uSecs/1000000; uSecs _ uSecs - secs*1000000; mSecs _ uSecs/1000; uSecs _ uSecs - mSecs*1000; IF secs # 0 OR mSecs > 10 THEN stream.PutF["%g.%g seconds.", card[secs], card[mSecs]] ELSE stream.PutF["%g.%g milliseconds.", card[mSecs], card[uSecs]]; END; Find: PROCEDURE[name: ROPE] RETURNS[Procedure] = BEGIN list: LIST OF Procedure _ modules; FOR m: LIST OF Procedure _ list, m.rest DO IF m = NIL THEN EXIT; IF Rope.Equal[name, m.first.name] THEN RETURN[m.first]; IF list # modules THEN LOOP; FOR p: LIST OF Call _ m.first.sons, p.rest DO IF p = NIL THEN EXIT; IF Rope.Equal[name, p.first.proc.name] THEN RETURN[p.first.proc]; ENDLOOP; ENDLOOP; RETURN[NIL]; END; END.. CountStorage: PROC RETURNS[process, mods, procs, sons: INTEGER, total:LONG INTEGER] = BEGIN process _ mods _ procs _ sons _ 0; FOR m: LIST OF Procedure _ modules, m.rest DO IF m = NIL THEN EXIT; mods _ mods + 1; FOR p: LIST OF Call _ m.first.sons, p.rest DO IF p = NIL THEN EXIT; sons _ sons + 1; procs _ procs + 1; FOR s: LIST OF Call _ p.first.proc.sons, s.rest DO IF s = NIL THEN EXIT; sons _ sons + 1; ENDLOOP; ENDLOOP; ENDLOOP; FOR p: LIST OF ProcessRef _ processes, p.rest DO IF p = NIL THEN EXIT; process _ process + 1; FOR s: LIST OF Call _ p.first.sons, s.rest DO IF s = NIL THEN EXIT; sons _ sons + 1; ENDLOOP; ENDLOOP; total _ process*SIZE[ProcessRec] + (mods + procs)*SIZE[ProcRec] + sons*SIZE[Call]; END; ¢SpyLogReaderImpl.mesa last modified by: John Maxwell on December 14, 1983 2:25 pm procedures listed in top down order ********************************************* reading the section of the log just before a trigger ********************************************* ********************************************* building a call tree from the trace log ********************************************* public statistics private statistics IF UserInput.userAbort THEN EXIT; IF active THEN SpyLog.Open[TRUE]; IF UserInput.userAbort THEN ERROR SpyOps.UserAborted; INVARIANT: exactly n proc.calls or proc.count should be incremented. -- add the first frame to the appropriate process list -- [level: 7, n: 0] is the code for an overflow are we at the end of the stack? add the current frame to the current node proc.marked _ TRUE; add in the leaf counts should we add it to the beginning of the list? is this the process we want? should the process follow this one? INVARIANT: the lists remain sorted INVARIANT: exactly one LIST OF Call.calls will be incremented should we add it to the beginning of the list? is this the procedure we want? should the procedure follow this one? INVARIANT: the lists remain sorted INVARIANT: exactly one LIST OF Call.calls will be decremented 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; INVARIANT: the lists remain sorted INVARIANT: exactly one ref will be incremented should we add it to the beginning of the list? is this the procedure we want? should the procedure follow this one? INVARIANT: the lists remain sorted should we add it to the beginning of the list? is this the module we want? should the module follow this one? heuristics to see if we are at the end of the entry vector determine the entry and exit PCs. ********************************************* determining the precedence relationships ********************************************* set the root containers chase down the trees catch all of the ones we missed . . . add self to son's parent list determine the intersection of the procedures that references proc ********************************************* some printing ********************************************* print general statistics print how the processor was used print breakdown by types: ********************************************* debugging facilities ********************************************* Ê$³˜Jšœ™Jšœ;™;J˜šÏk ˜ Jšœ œ˜&Jšœœœ˜'Jšœ œA˜PJš œœœœ)œœ˜XJšœ œt˜‚Jšœ'˜'Jšœ˜Jšœœ ˜Jšœœ ˜Jšœœœ˜(Jšœ œ&˜8Jšœ œ˜*Jšœ œ!˜0Jšœœ˜1Jšœœ0˜Jšœ˜Jš˜Jšœ"™"Jšœ.™.J˜Jšœœœ˜J˜Jšœ œ˜J˜Jšœ.™.šœœœ'œ˜=J˜%Jšœ œœœ˜&J˜Jšœœ˜,J˜Jšœ ˜—šœœ˜J˜Jšœ™šœœ˜#J˜$Jšœ ˜—Jšœ%™%šœ œœ,œ˜GJ˜%Jšœ œœœ˜%J˜Jšœ œ˜/J˜Jšœ ˜—J˜Jšœ˜—Jšœ˜Jšœ˜J˜—šŸ œ œ˜-Jšœ˜Jš˜Jšœ"™"Jšœœœ ˜Jšœ œ˜ J˜Jšœ.™.šœœœœ˜,J˜Jšœ œ˜Jšœ ˜—šœœ˜J˜Jšœ™Jšœœœ ˜(Jšœ"™"šœ œœœ˜6J˜Jšœ œ˜$Jšœ ˜—J˜Jšœ˜—Jšœ˜Jšœ˜J˜—šŸ œ œ˜-Jšœ˜Jš˜Jšœ œ˜J˜J˜Jšœœ œ œ3˜`Jšœ˜J˜—šŸ œ œœ˜9Jšœœ˜%Jš˜Jšœœ˜ Jšœœ˜Jšœœ-˜CJšœ œ˜J˜J˜J˜J˜Jšœœ˜+šœœœœ˜'Jš œœœœœ˜J˜#Jšœœ˜.—J˜@Jšœœ˜Jšœ˜J˜—šŸœ œœ˜9Jšœœ˜ Jš˜Jšœ œ˜J˜ Jšœœœœ˜(J˜ J˜J˜Jšœœ ˜šœœœ˜1Jšœ:™:Jšœ œœ˜,Jšœ2œœ˜>Jšœœœ˜EJšœ œœ˜Jšœ!™!J˜!Jšœœœ˜7Jšœ œœ˜4Jšœ˜—J˜Jšœ˜—J˜Jšž˜J˜Jšœ œœ˜#šœœœ˜Jšœœ˜Jšœœ˜šœœœœ˜/Jšœœ˜Jšœœ˜J˜——šŸœ œ(œ˜MJ˜GJ˜—šŸ œ œœœ˜9Jšœ˜ Jšœœœœ˜&š œœ œœ˜3Jšœ7œœœ˜KJšœ˜—Jšœœ˜Jšœ˜J˜—šŸœ œ"˜1Jš˜J˜Jšœœœ˜J˜(š œœ œœ˜3J˜J˜TJ˜ Jšœœœ˜3Jšœ˜—Jšœ˜Jšœ˜—J˜Jšœ-™-Jšœ)™)Jšœ-™-J˜šŸœ œ˜Jš˜š œœœœœ˜;š œœœœœ˜;Jšœœ˜Jšœ˜—Jšœ˜—Jšœ˜J˜—šŸœ œ˜Jš˜J˜Jšœ™š œœœ œœ˜>š œœœœœ˜;J˜&Jšœ˜—Jšœ˜—Jšœ™š œœœ œœ˜>š œœœœœ˜;J˜!Jšœ˜—Jšœ˜—Jšœ™š œœœœœ˜;š œœœœœ˜;Jšœœœœ˜*J˜1Jšœœœ'˜KJšœ˜—Jšœ˜—Jšœ˜J˜—šŸ œœ˜J˜Jšœœ˜š œœœœœ˜;š œœœœœ˜;Jšœž˜0š œœœœœ˜8Jšœœ˜Jšœœœ˜š œœœ*œ˜HJšœœ œœ˜,Jšœ˜—Jšœ#™#Jšœœœ˜GJšœ˜—Jšœ˜—Jšœ˜—Jšœ˜J˜—šŸ œ œœœ˜.Jš˜šœœœ˜%Jšœœœœ˜Jšœœœœ˜*J˜1Jšœœœœ˜*J˜!Jšœ˜—Jšœ˜J˜—šŸ œ œ˜&Jšœœ˜Jš˜JšœA™AJšœœ˜š œœœ"œœ˜@Jšœœœž˜4Jšœœœ(˜GJšœœœœ˜&Jšœœœœ˜$Jšœ˜Jš œœœœœ ž˜DJšœ˜—Jšœœ˜Jšœ˜J˜—šŸ œ œœ ˜=Jš˜šœœœœ˜šœ˜$Jšœœœ˜"Jšœœœ˜Jšœ˜—šœ˜$Jšœœœ˜"Jšœœœ˜Jšœ˜—Jš œœœœœ˜7J˜J˜Jšœ˜—Jšœ˜J˜—J˜Jšœ-™-Jšœ™Jšœ-™-J˜šŸœ œ œœ˜/Jš˜Jšœ œ˜Jšœ œœ˜Jšœ™Jšœ œC˜P˜4Jšœœ˜(—J˜4J˜Gšœœ˜J˜CJ˜R—J˜KJ˜UJ˜KJ˜UJšœ ™ J˜<šœœ˜J˜%J˜.—šœ œ˜J˜0J˜'—šœœ˜.Jšœœœ˜J˜4J˜-Jšœ˜—Jšœœ˜J™šœ œœ˜Jšœ œ˜Jšœœœ˜šœ ˜Jšœ;˜;J˜MJšœ.˜5—šœœ ˜ Jš œœœœœ˜2šœœ˜J˜Jšœœ˜—šœ œœ˜/Jšœ2˜6Jš œœœœœ ˜U—Jšœ,˜,Jšœ˜—Jšœœ˜—Jšœ˜J˜—šŸœ œ œœ˜1Jš˜JšœOœ˜TJšœœ:œ˜RJšœœ`œ˜xJšœœ`œ˜xJšœœTœ˜lJšœœdœ˜|Jšœœ-œ˜EJšœœ,œ˜DJšœœCœ˜[Jšœœ<œ˜TJšœœBœ˜ZJšœœ˜Jšœ˜J˜—šŸœ œ œœ˜3Jš˜J˜Jšœ?œ˜DJšœœ˜˜ Jšœœ˜"J˜ —J˜UJšœœ˜˜ Jšœœ˜"J˜ —J˜UJšœœ˜˜ Jšœœ˜"J˜ —J˜UJšœœ˜˜ Jšœœ˜"J˜ —J˜UJšœ œœž˜9˜ Jšœœ˜&—J˜=˜ J˜H—Jšœ˜šœœ˜&J˜1—Jšœ ˜šœœ˜#J˜6—Jšœ˜J˜VJ˜NJ˜Nšœœœ ˜@Jšœ œœ ˜1—J˜MJšœœ˜Jšœ˜—J˜šœ œ!œ˜5J˜—šŸ œ œœœ˜9šœœœ˜J˜&J˜(J˜)Jšœ˜J˜——šŸ œ œ œœ"˜IJš˜Jš œœ œœœ˜:J˜!Jšœ œ$˜4Jšœ œœœ˜1Jšœœ œ˜AJ˜Jšœœ˜Jšœ˜J˜—šŸœ œ œœ˜5Jš˜J˜ Jšœœ˜J˜Jšœœ˜ J˜ Jš œœœœž˜9J˜*J˜ Jšœ˜J˜—š Ÿ œ œ œœ œœ˜?Jš˜Jšœœœ˜ J˜J˜J˜J˜J˜šœ œ ˜Jšœ7˜;Jšœ>˜B—Jšœ˜—J˜Jšœ-™-Jšœ™Jšœ-™-J˜šŸœ œœœ ˜0Jš˜Jšœœœ˜"šœœœ˜*Jšœœœœ˜Jšœ œœ ˜7Jšœœœ˜šœœœ˜-Jšœœœœ˜Jšœ%œœ˜AJšœ˜—Jšœ˜—Jšœœ˜ Jšœ˜J˜—Jšœ˜J˜J˜š Ÿ œœœœœœ˜UJš˜J˜"šœœœ˜-Jšœœœœ˜J˜šœœœ˜-Jšœœœœ˜J˜J˜šœœœ"˜2Jšœœœœ˜J˜Jšœ˜—Jšœ˜—Jšœ˜—šœœœ ˜0Jšœœœœ˜J˜šœœœ˜-Jšœœœœ˜J˜Jšœ˜—Jšœ˜—šœœ˜#Jšœœœ ˜1—Jšœ˜—J˜J˜J˜—…—l„šÙ