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; processes: PUBLIC LIST OF ProcessRef _ NIL; modules: PUBLIC LIST OF Procedure _ NIL; current: SpyOps.DataType; 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]; }; 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] = { count: NAT _ 0; 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]; }; 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; 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[ count: Count, 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 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; 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] = { name: ROPE _ GetName[gfh, pc]; 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]] ]; }; 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; ENDLOOP; RETURN [NIL]; }; stack: ProcStack; EnterStack: PROC [s: LONG POINTER TO SpyOps.Stack, n: CARDINAL] = { 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 ready => notScheduled _ notScheduled + s.count; pageFault => 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].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 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].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 { 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 { [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; }; AddProcess: PROC [psb: PrincOps.PsbIndex] RETURNS [process: ProcessRef _ NIL] = { 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; }; NewProcess: PROC [psb: PrincOps.PsbIndex] RETURNS [process: ProcessRef] = { process _ NEW[ProcessRec _ []]; noProcesses _ noProcesses + 1; process.psb _ psb; }; AddSon: PROC [list: CallList, from: CARDINAL, gfh: GlobalFrameHandle, pc, count: Count] RETURNS [newList: CallList, procedure: Procedure] = { procedure _ NIL; newList _ 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; 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]; }; 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] = { 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; 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 _ 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 GO TO badGuy]; 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; IF gfh = module.gfh THEN RETURN [module]; 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] = { name: ROPE _ 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 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; 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; }; 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; }; 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; ENDLOOP; }; SetAllContainers: PROC = { SetAllParents[]; 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; ENDLOOP; 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; ENDLOOP; 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; 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; IF ~found THEN s.first.proc.parents _ CONS[proc, s.first.proc.parents]; ENDLOOP; ENDLOOP; 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] = { 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] = { 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; }; PrintStatistics: PROC [stream: STREAM] = { seconds: INTEGER; IF wakeups = 0 THEN RETURN; 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]]]; 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 count: CARD _ levelData[i]; IF count # 0 THEN { IO.PutF1[stream, " priority %g", [rope[LevelName[i]]]]; PrintCount[stream, count, 0, wakeups]; }; ENDLOOP; IO.PutRope[stream, "\n"]; 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 name: ROPE _ typeName[i]; 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 count: INT _ spyTime[i].count; 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 { 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]]]; }; 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; ENDLOOP; RETURN [NIL]; }; }.. SpyLogReaderImpl.mesa Copyright Σ 1985, 1986, 1987 by Xerox Corporation. All rights reserved. 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 global variables and types 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; tree management adding a stack to the call tree 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 add in the leaf counts treat as a call even tho it's a count adding to the list of processes should we add it to the beginning of the list? is this the process we want? should the process follow this one? adding/deleting procedures from a LIST OF Call 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; adding modules and procedures to the modules list 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. handling marked stacks 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: to avoid wrap around debugging facilities Κ$˜codešœ™KšœH™HKšœ$™$K™5K™'K™(K™.K™.K™,—˜šΟk ˜ Kšœ œ˜&Kšœœœ˜'Kšœ œA˜PKšœœ5œœ˜JKšœ œ'œE˜}Kšœœ˜'Kšœœ ˜Kšœœ ˜Kšœœ ˜Kšœœœ˜(Kšœ œ&˜8Kšœ œ˜*Kšœ œ!˜0Kšœœ˜1Kšœ œœ˜Kšœœ0˜K˜šœ ˜ Kšœ ˜ Kšœ ˜ Kšœ ˜ Kšœ ˜ Kšœ ˜ Kšœ ˜ Kšœ ˜ Kšœ˜Kšœ˜Kšœ˜Kšœ˜Kšœ ˜ Kšœ ˜ Kšœ ˜ —K˜šœ ˜Kšœœ˜Kšœ/˜/Kšœ&˜&Kšœ8˜8Kšœ(˜(Kšœœ˜—Kšœ œ˜šœ œ˜K˜šœœœ˜$Kšœ5œ˜?—šœ˜ Kšœ˜Kšœ0˜4——Kšœ&˜&K˜K˜K˜K˜Kšœ˜—K˜—šœ5™5Kšœ œœ˜K˜ Kšœœ˜K˜š ž œœ#œœœ˜TKšœ˜Kšœ˜Kšœ˜Kšœ˜K˜—šž œœœ ˜9Kšœœ˜Kšœœœœ˜$KšœΟc˜)šœœ˜ Kšœ˜Kšœ œœœ˜šœ œ˜Kšœ œ˜˜ Kš œœœœœ ˜8Kšœœœœ˜1K˜Kšœœœ˜"Kšœ˜—Kšœ˜—Kšœ˜—Kšœ˜ Kšœ˜—K˜—šœ(™(šœ™Kšœ œ Ÿ-˜HKšœœŸ"˜IKšœœŸ˜2Kšœ œœ˜,Kšœ œ œœ˜#Kšœ œ œ˜#Kšœ œ˜K˜—šœ™KšœŸ˜4KšœŸ1˜FKšœŸ1˜CKšœŸ˜-K˜4KšœŸ˜6K˜Kšœœ˜ Kšœœœ˜šœ œœœ˜ K˜K˜K˜——šž œœ/œ˜HKšœœ˜ Kšœœœ˜Kšœ œ˜K˜"Kšœœ˜K˜&Kšœœœœ˜$Kšœ5˜5K˜ KšœŸ˜)K˜ K˜ šœœ˜ Kšœ!™!K˜Kšœ œœœ˜šœ œ˜Kšœ œ˜Kšœ œ˜šœ˜šœ˜šœ˜Kšœœ˜!šœœ˜K˜Kšœœ œœ˜0šœœ˜K˜!Kšœœ ˜#—K˜(K˜*K˜—Kšœœ˜ Kšœ˜—šœ˜Kšœ œ˜&Kšœ œ œ˜;šœœœ˜Kšœ;˜;Kšœ?˜AKšœ˜—šœœ˜Kšœt˜vK˜K˜—K˜4K˜K˜———˜ Kšœœœœ˜$Kšœ œœœ˜7šœœœ˜&Kšœ œ˜&Kšœ œ œ˜;K˜CKšœ˜Kšœ˜Kšœ˜—Kšœœ ˜Kš œ œœœœ˜@Kšœ œ,˜?K˜K˜Kšœœ˜ Kšœ˜—Kšœœ˜—Kšœ˜—K˜(Kšœ!™!Kšœ5™5Kšœœ˜ Kšœœ˜ Kšœ˜K˜—š ž œœœœœ$˜_Kšœœ˜šœœœ˜Kšœ;˜;Kšœ>˜@Kšœ˜—Kšœ,œ˜<šœ˜ K˜2K˜3K˜3—Kšœ˜Kšœ˜Kšœ˜K˜—šž œœP˜aKšœœ˜šœ.˜0K˜2K˜3Kšœœœ˜C—Kšœ˜K˜—š žœœ/œœœ˜ZKšœœ˜ Kšœ*œ˜0Kšœ3œœœ ˜Nšœ˜šœ˜šœ œ˜Kšœ œœ)œ˜IKšœ˜ Kšœ˜—šœ˜ Kšœ œœ)œ˜IKšœ˜ Kšœ˜—K˜—Kšœœ˜ K˜%Kšœ'˜'K˜-K˜'K˜EK˜Kšœ˜—Kšœ!˜!šœ ˜Kšœœœœ˜Q—Kšœ˜—K˜—šœ™šž œœ˜Kšœ œ˜Kšœ œ˜K˜K˜!K˜#K˜0Kšœ œ ˜Kšœ œ˜Kšœœ˜ Kšœ˜K˜—š žœœ œ œœœ˜^š œœœœœ˜;šœ$œœ˜7Kšœœœ˜5Kšœ˜—Kšœ˜—Kšœœ˜ Kšœ˜—K˜—šœ™˜K˜—š ž œœœœœœ˜CKšœœ˜.KšœD™DKšœœ˜Kšœœ˜K˜K˜šœ œœ˜šœ˜Kšœ/˜/Kšœ%˜%Kšœ˜#Kšœ˜—Kšœ˜—KšŸ3™3K˜ K˜(K˜šœœ˜#šœœœ˜Kšœœœ˜(Kšœœœ˜"K˜Kšœœ˜——K˜2KšŸ,™,Kšœ œ!œ˜=Kšœœœœ ˜$˜K˜@—Kš œœœ œœ˜)Kšœ œœ œ˜3K˜K˜šœœ˜ Kšœ™Kšœœœœ ˜"K˜"Kšœ)™)˜K˜K—K˜Kšœœœœ˜K˜'Kšœœ˜.Kšœ˜—šœœœ˜Kšœ™K˜"K˜Wšœœ˜Kšœ%™%Kšœ7œœ˜RKšœ œœ'˜;K˜—K˜—Kšœ.˜.K˜Kšœ˜—K˜—šœ™šž œœœœ˜QKšœœœ˜%Kšœ.™.šœœœœ˜,K˜Kšœ œ˜%Kšœ ˜Kšœ˜—šœœ˜K˜Kšœ™Kšœœœ ˜+Kšœ#™#šœ œœœ˜6K˜Kšœ œ˜%Kšœ ˜Kšœ˜—K˜Kšœ˜—Kšœ˜Kšœ˜K˜—šž œœœ˜KKšœ œ˜K˜K˜Kšœ˜—K˜—šœ.™.šžœœœ+œ.˜Kšœ"™"Kšœ=™=Kšœ œ˜K˜Kšœ.™.šœœœœ˜,K˜"Kš œ œœœœœ˜*Kšœ œ!˜/K˜Kšœ˜Kšœ˜—šœœ˜K˜Kšœ™šœœœ˜Kšœœœœ˜OKšœ œœ˜Kšœ!™!K˜!Kšœœœ˜7Kšœ œœ˜4Kšœ˜—K˜Kšœ˜—K˜—šœ™Kšœ œœ˜#šœœœ˜Kšœœ˜Kšœœ˜šœœœœ˜0Kšœœ˜Kšœœ˜K˜——šžœœ)œœ˜KKšœ&˜&Kšœ˜Kšœ˜K˜—š ž œœœœœ˜šœ$œœ˜7K˜&Kšœ˜—Kšœ˜—Kšœ™š œœœ œœ˜>šœ$œœ˜7K˜!Kšœ˜—Kšœ˜—Kšœ™š œœœœœ˜;šœ$œœ˜7Kšœœœœ˜*K˜1Kšœœœ'˜KKšœ˜—Kšœ˜—Kšœ˜K˜—šž œœ˜š œœœœœ˜;šœ$œœ˜7Kšœ Ÿ˜;šœ!œœ˜4Kšœœœ˜Kšœœœ˜š œœœ*œœ˜HKšœœ œœ˜,Kšœ˜—Kšœ#™#Kšœœœ˜GKšœ˜—Kšœ˜—Kšœ˜—Kšœ˜K˜—šž œœ˜(šœœœ˜/Kšœ˜Kšœœœœ˜Kšœ˜Kšœœœœ˜Kšœ˜Kšœ˜—Kšœ˜K˜—šž œœœœ˜BKšœA™AKšœœ˜š œœœ"œœ˜@KšœœœŸ˜4šœœœ˜!Kšœ7˜7Kšœœœœ˜K˜—Kšœœœœ˜$Kšœ˜Kš œœœœœ Ÿ˜EKšœ˜—Kšœœ˜Kšœ˜K˜—šž œœœ˜<š˜Kšœœœ˜šœ˜$Kšœœœ˜#Kšœœœ˜Kšœ˜—šœ˜$Kšœœœ˜#Kšœœœ˜Kšœ˜—Kš œœœœœ˜8K˜K˜Kšœ˜—Kšœ˜——K˜šœ™šžœœ œ˜*Kšœ œ˜Kšœ œœ˜Kšœ™Kšœ œ?˜Lšœ6˜8Kšœ,œ˜6—šœ ˜šœ7˜:KšœO˜Q—Kšœœ˜ Kšœœ˜—Kšœ:˜šœœ˜Kšœ%˜'K˜-K˜—šœ œ˜Kšœ0˜2K˜&K˜—šœœ˜.Kšœœ˜šœ œ˜Kšœ6˜8Kšœ&˜&K˜—Kšœ˜—Kšœ˜K™K™šœ œœ˜Kšœœ˜ Kšœœœ˜šœ ˜Kšœ;˜;K˜MKšœ.˜5—šœœ ˜ Kšœœ˜Kš œœœœœ˜+šœœ˜Kšœ˜Kšœ˜Kšœ˜—šœ œœ˜,Kšœ˜Kšœ˜K˜—Kšœ,˜,Kšœ˜—Kšœ˜Kšœ˜—Kšœ˜K˜—šžœœ œ˜,Kšœτ˜φKšœ˜K˜—šžœœ œ˜.šœœœ ˜GKšœ œœ ˜0—Kšœ<˜>šœœœ˜Kšœœ˜šœ œ˜Kšœ@˜BKšœ)˜)Kšœ˜—Kšœ˜—šœœ œœ˜$Kšœ™Kšœ(˜*K˜K˜—KšœO˜Qšœ˜Kšœp˜r—šœ ˜KšœV˜X—šœ˜KšœR˜T—KšœI˜KKšœJ˜LKšœK˜MKšœ˜—K˜šž œœœœ˜-K˜-Kšœ7˜7K˜—šž œœœ œ$˜KKš œœ œœœ˜>Kšœ'˜)Kšœ œœ)˜Kšœœ*˜6Kšœœ˜Kšœœ œ˜Kšœœ œ˜*šœ œ ˜KšœœD˜KKšœœK˜R—Kšœ˜K˜——šœ™šžœœœœ˜/Kšœœœ˜"š œœœœœ˜8Kšœ œœ ˜8Kšœœœ˜šœ$œœ˜7Kšœ%œœ˜BKšœ˜—Kšœ˜—Kšœœ˜ Kšœ˜K˜——Kšœ˜K˜K˜K˜K˜—…—h|–£