<> <> DIRECTORY AMBridge USING [TVForGFHReferent], AMTypes USING [TV], BBObjectLocation USING [Location, LocationFromGFandPC, LocationToSource], Convert USING [ValueToRope], IO USING [ card, char, CR, CreateViewerStreams, Error, int, Put, PutF, rope, STREAM, string, TAB, time, UserAbort], PrincOps USING [GFTIndex, GlobalFrameHandle], PrincOpsRuntime USING [GetFrame, GFT], Process USING [Priority], PSB USING [PsbIndex], Rope USING [Cat, FromChar, Length, ROPE, Substr], RTSymbolDefs USING [CallableBodyIndex, SymbolTableBase], RTSymbolOps USING [AcquireRope, BodyName], RTSymbols USING [AcquireSTBFromGFH, ReleaseSTB], RTTypesPrivate USING [GetCBTI, GetEp], Runtime USING [GetBcdTime], SpyClient USING [ClearBreaks, DataType, InitializeSpy, StartSpy, StopSpy], SpyLog USING [spy], SpyOps USING [ ProcessRef, Call, Count, DestroyLog, GFHFromGFI, justMe, levelData, modules, notScheduled, pageFaults, Procedure, processes, PrintBreaks, ReadLog, runningTime, skips, wakeups, watching, wordsAllocated, wordsReclaimed], System USING [PulsesToMicroseconds], Time USING [Append, Unpack]; SpyPrintImpl: PROGRAM IMPORTS AMBridge, BBObjectLocation, Convert, IO, PrincOpsRuntime, Rope, RTSymbolOps, RTSymbols, RTTypesPrivate, Runtime, SpyClient, SpyLog, SpyOps, System, Time EXPORTS SpyClient = BEGIN OPEN IO, SpyOps; ROPE: TYPE = Rope.ROPE; Error: SIGNAL = CODE; <<*********************************************>> <> <<*********************************************>> procMin: Count; total, min: Count; printAll: BOOLEAN _ FALSE; current: SpyClient.DataType; DisplayData: PUBLIC PROCEDURE[cutoff: CARDINAL, herald: ROPE, stream: IO.STREAM] = BEGIN BEGIN ENABLE { ABORTED => {stream.Put[rope[" . . . aborted.\n"]]; CONTINUE}; IO.Error => CONTINUE}; IF stream = NIL THEN stream _ IO.CreateViewerStreams["Spy log"].out; total _ SpyOps.wakeups; -- cache wakeups and watching because they will change current _ SpyOps.watching; -- if the Spy is watching itself PrintHeader[herald, stream]; PrintStatistics[stream]; PrintInstructions[stream]; IF cutoff # 0 THEN {min _ MAX[1, total/100]; procMin _ cutoff*min} ELSE {min _ procMin _ 1}; IF SpyLog.spy THEN { SpyClient.ClearBreaks[]; [] _ SpyClient.InitializeSpy[breakProcess]; SpyClient.StartSpy[]}; SpyOps.ReadLog[typescript: stream, datatype: current]; PrintTree[stream]; END; SpyOps.DestroyLog[]; IF SpyLog.spy THEN SpyClient.StopSpy[]; END; PrintHeader: PROCEDURE[herald: ROPE, stream: IO.STREAM] = BEGIN time: STRING _ [40]; stream.Put[rope["\n\n==========================================================\n"]]; Time.Append[time, Time.Unpack[Runtime.GetBcdTime[]]]; stream.Put[rope["Cedar Spy of: "], string[time], rope[".\n"]]; stream.Put[rope["Executed at: "], IO.time[], rope[".\n"]]; IF herald # NIL THEN stream.Put[rope[herald], char[CR]]; SELECT current FROM CPU, process, breakProcess => stream.Put[rope["Measuring CPU usage."]]; pagefaults => stream.Put[rope["Measuring page faults."]]; allocations => stream.Put[rope["Measuring allocations."]]; wordsAllocated => stream.Put[rope["Measuring words allocated."]]; spaces => stream.Put[rope["Measuring creations and deletions of spaces."]]; userDefined => stream.Put[rope["Measuring user breaks."]]; ENDCASE => ERROR; stream.Put[char[CR]]; IF SpyOps.watching IN [process..breakProcess] THEN stream.Put[rope["Watching process: "], rope[Octal[SpyOps.justMe]], rope[".\n"]]; SpyOps.PrintBreaks[stream]; stream.Put[char[CR]]; END; PrintStatistics: PROCEDURE[stream: IO.STREAM] = BEGIN seconds: INT; IF total = 0 THEN RETURN; <> seconds _ MAX[1, System.PulsesToMicroseconds[SpyOps.runningTime]/1000000]; stream.PutF["Spy ran for %g minutes %g seconds.\n", card[seconds/60], card[seconds MOD 60]]; stream.Put[rope["Total wakeups = "], card[total]]; stream.Put[rope[" ("], card[total/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 SpyOps.notScheduled # 0 THEN { stream.Put[rope[" processor idle"]]; PrintCount[stream, SpyOps.notScheduled, 0, total]}; IF SpyOps.skips # 0 THEN { stream.Put[rope[" processor waiting on disk"]]; PrintCount[stream, SpyOps.skips, 0, total]}; FOR i: Process.Priority IN Process.Priority DO IF SpyOps.levelData[i] = 0 THEN LOOP; stream.Put[rope[" priority "], rope[LevelName[i]]]; PrintCount[stream, SpyOps.levelData[i], 0, total]; ENDLOOP; stream.Put[char[CR]]; END; PrintInstructions: PROCEDURE[stream: IO.STREAM] = BEGIN stream.Put[rope["Instructions (see Spy.doc 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; PrintTree: PROCEDURE[stream: IO.STREAM] = BEGIN assorted: Count _ 0; procs: LIST OF Procedure _ NIL; next _ " "; <> SortProcesses[processes]; stream.Put[ rope["~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\n"], rope["Breakdown of interesting processes.\n"], rope["~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\n"]]; indention _ NIL; FOR p: LIST OF ProcessRef _ processes, p.rest DO IF p = NIL THEN EXIT; IF p.first.calls < min --AND RTProcess.GetPSBIPageFaults[p.first.psb] = 0 THEN {assorted _ assorted + p.first.calls; LOOP}; PrintProcess[stream, p.first]; ENDLOOP; IF assorted > 0 THEN { stream.Put[char[CR], rope["Assorted processes"]]; PrintCount[stream, assorted, 0, total]}; <> stream.Put[ rope["\n~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\n"], rope["Breakdown of interesting procedures.\n"], rope["~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\n\n"]]; PrintProcs[stream, FindProcs[NIL]]; IF procMin > 1 THEN stream.Put[ rope["\nThe remaining procedures had less than "], card[procMin], rope[" wakeups.\n"]] ELSE stream.Put[rope["\n~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\n"]]; procs _ NIL; END; -- handling processes -- SortProcesses: PROCEDURE[list: LIST OF ProcessRef] = BEGIN temp: ProcessRef; changed: BOOLEAN; l: LIST OF ProcessRef; IF list = NIL THEN RETURN; DO changed _ FALSE; l _ list; UNTIL l.rest = NIL DO IF l.first.calls < l.rest.first.calls THEN { temp _ l.first; l.first _ l.rest.first; l.rest.first _ temp; changed _ TRUE}; l _ l.rest; ENDLOOP; IF ~changed THEN EXIT; ENDLOOP; END; PrintProcess: PROCEDURE[stream: IO.STREAM, process: ProcessRef] = BEGIN faults: LONG CARDINAL _ 0; IF stream.UserAbort[] THEN ERROR ABORTED; stream.Put[ char[CR], rope["Process "], rope[Octal[process.psb]]]; <> stream.Put[ rope[" running at priority "], char['[], rope[LevelName[process.level[0]]]]; IF process.level[1] # 0 THEN FOR i:CARDINAL IN [1..4] DO IF process.level[i] = 0 THEN EXIT; stream.Put[ rope[", "], rope[LevelName[process.level[i]]]]; ENDLOOP; stream.Put[char[']]]; <> <> IF faults > 0 THEN stream.Put[ rope[" ("], int[faults], rope[" page faults)"]]; PrintCount[stream, process.calls, 0, total]; <> FOR p: LIST OF Call _ process.sons, p.rest DO IF p = NIL THEN EXIT; PrintCall[stream, NIL, p.first]; ENDLOOP; END; 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"]}; --printing procedures -- EnumerateProcs: PROCEDURE[userProc: PROC[Procedure] RETURNS[BOOLEAN]] RETURNS[last: Procedure] = INLINE 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 p.first.proc.count = 0 AND p.first.proc.calls = 0 THEN LOOP; IF userProc[p.first.proc] THEN RETURN[p.first.proc]; ENDLOOP; ENDLOOP; RETURN[NIL]; END; FindProcs: PROCEDURE[container: Procedure] RETURNS[list: LIST OF Procedure _ NIL] = BEGIN FindProc: PROCEDURE[next: Procedure] RETURNS[BOOLEAN] = { IF container = NIL THEN IF next.container = next THEN list _ CONS[next, list] ELSE RETURN[FALSE]; IF next.container = container THEN IF next.container = next THEN RETURN[FALSE] ELSE list _ CONS[next, list]; RETURN[FALSE]}; [] _ EnumerateProcs[FindProc]; IF list # NIL THEN SortProcs[list]; END; SortProcs: PROCEDURE[list: LIST OF Procedure] = BEGIN temp: Procedure; changed: BOOLEAN; l: LIST OF Procedure; xCount, yCount: Count; IF list = NIL THEN RETURN; DO changed _ FALSE; l _ list; UNTIL l.rest = NIL DO xCount _ l.first.count + l.first.calls; yCount _ l.rest.first.count + l.rest.first.calls; IF xCount < yCount THEN { temp _ l.first; l.first _ l.rest.first; l.rest.first _ temp; changed _ TRUE}; l _ l.rest; ENDLOOP; IF ~changed THEN EXIT; ENDLOOP; END; indention, next: ROPE _ NIL; PrintProcs: PROCEDURE[stream: IO.STREAM, procs: LIST OF Procedure] = BEGIN count: NAT _ 0; procsToPrint: BOOLEAN; keepLooping: BOOLEAN; break: BOOLEAN _ FALSE; list, last: LIST OF Procedure; allParentsPrinted: BOOLEAN; Printable: PROC[procs: LIST OF Procedure] RETURNS[BOOLEAN] = INLINE { RETURN[procs # NIL AND procs.first.calls + procs.first.count >= procMin]}; WHILE procs # NIL DO list _ NIL; <> <> keepLooping _ TRUE; WHILE keepLooping DO last _ NIL; keepLooping _ FALSE; FOR l: LIST OF Procedure _ procs, l.rest WHILE l # NIL DO allParentsPrinted _ TRUE; FOR f: LIST OF Procedure _ l.first.parents, f.rest WHILE f # NIL DO IF ~f.first.marked THEN {allParentsPrinted _ FALSE; EXIT}; ENDLOOP; IF ~allParentsPrinted THEN {last _ l; LOOP}; IF last = NIL THEN procs _ l.rest ELSE last.rest _ l.rest; IF break THEN count _ count + 1; -- a place to break on IF Printable[l] -- 'print' procs that won't be printed THEN list _ CONS[l.first, list] ELSE {PrintProc[stream, l.first]; keepLooping _ TRUE}; ENDLOOP; ENDLOOP; <> IF list = NIL THEN { IF procs = NIL THEN RETURN; list _ CONS[procs.first, NIL]; procs _ procs.rest}; <> IF list.rest # NIL THEN SortProcs[list]; IF break THEN count _ count + 1; -- a place to break on procsToPrint _ Printable[procs]; FOR list _ list, list.rest WHILE list # NIL DO IF Printable[list.rest] THEN next _ "! " ELSE IF procsToPrint THEN next _ ". " ELSE next _ " "; PrintProc[stream, list.first]; ENDLOOP; ENDLOOP; END; PrintProc: PROCEDURE[stream: IO.STREAM, proc: Procedure] = BEGIN looks: BOOLEAN _ FALSE; length: LONG INTEGER _ 0; list: LIST OF Procedure _ NIL; IF proc = NIL THEN RETURN; IF proc.marked THEN ERROR ELSE proc.marked _ TRUE; IF proc.gfi = 0 AND proc.entryPC = 0 THEN RETURN; -- "source" module IF proc.calls + proc.count >= procMin THEN { <> IF ~proc.named THEN SetName[proc]; stream.Put[rope[indention]]; IF proc.count > 0 AND ~(current IN [CPU..breakProcess]) THEN { looks _ TRUE; stream.PutF["%l", rope["b"]]}; IF proc.parents # NIL AND proc.parents.rest # NIL THEN { looks _ TRUE; stream.PutF["%l", rope["i"]]}; stream.Put[rope[proc.name]]; IF looks THEN stream.PutF["%l", rope[" "]]; stream.Put[rope[" ("], card[proc.refs], rope[" refs)"]]; PrintCount[stream, proc.count, proc.calls, total]; <> FOR p: LIST OF Call _ proc.sons, p.rest DO IF p = NIL THEN EXIT; IF p.first.calls < min THEN LOOP; PrintCall[stream, proc, p.first]; ENDLOOP; stream.Put[rope[indention], rope[next], char[CR]]}; <> list _ FindProcs[proc]; IF list = NIL THEN RETURN; indention _ Rope.Cat[indention, next]; PrintProcs[stream, list]; indention _ Rope.Substr[indention, 0, indention.Length[]-2]; END; PrintCall: PROCEDURE[stream: IO.STREAM, proc: Procedure, call: Call] = BEGIN IF ~call.proc.named THEN SetName[call.proc]; stream.Put[rope[indention], rope[next]]; IF proc # NIL AND proc.symbols THEN stream.Put[rope["("], card[Source[proc.gfi, call.pc]], rope[") "]]; stream.Put[rope[call.proc.name]]; PrintCount[stream, call.calls, 0, total]; IF stream.UserAbort[] THEN ERROR ABORTED; END; SetName: PROCEDURE[proc: Procedure] = BEGIN stb: RTSymbolDefs.SymbolTableBase _ [x[e: NIL]]; BEGIN ENABLE ANY => {IF stb # [x[e: NIL]] THEN RTSymbols.ReleaseSTB[stb]; CONTINUE}; name: ROPE; temp: Procedure; gfh: PrincOps.GlobalFrameHandle; gfh _ SpyOps.GFHFromGFI[proc.gfi]; stb _ RTSymbols.AcquireSTBFromGFH[gfh, TRUE ! ANY => CONTINUE]; <> FOR m: LIST OF Procedure _ modules, m.rest WHILE m # NIL DO IF m.first.gfi # proc.gfi THEN LOOP; FOR p: LIST OF Call _ m.first.sons, p.rest WHILE p # NIL DO IF p.first.proc # proc AND p.first.proc.count + p.first.proc.calls < min THEN LOOP; IF p.first.proc.named THEN LOOP; name _ NIL; temp _ p.first.proc; IF stb # [x[e: NIL]] THEN { -- get the name from the symbol table ep: CARDINAL _ RTTypesPrivate.GetEp[[temp.entryPC], gfh, stb].ep; cbti: RTSymbolDefs.CallableBodyIndex _ RTTypesPrivate.GetCBTI[stb, ep]; name _ RTSymbolOps.AcquireRope[stb, RTSymbolOps.BodyName[stb, cbti]]}; IF name = NIL THEN {temp.symbols _ FALSE; name _ Octal[temp.entryPC]}; temp.name _ Rope.Cat[temp.name, name]; temp.named _ TRUE; ENDLOOP; EXIT; ENDLOOP; IF stb # [x[e: NIL]] THEN RTSymbols.ReleaseSTB[stb]; END; END; Sons: PROCEDURE[list: LIST OF Call] RETURNS[BOOLEAN] = INLINE BEGIN FOR list _ list, list.rest DO IF list = NIL THEN EXIT; IF list.first.calls >= min THEN RETURN[TRUE]; ENDLOOP; RETURN[FALSE]; END; Source: PROCEDURE[gfi: PrincOps.GFTIndex, pc: CARDINAL] RETURNS[CARDINAL _ 0] = INLINE BEGIN ENABLE {ABORTED => NULL; ANY => CONTINUE}; loc: BBObjectLocation.Location; gfh: AMTypes.TV = AMBridge.TVForGFHReferent[PrincOpsRuntime.GetFrame[PrincOpsRuntime.GFT[gfi]]]; loc _ BBObjectLocation.LocationFromGFandPC[gfh, [pc]]; RETURN[IF loc # NIL THEN BBObjectLocation.LocationToSource[loc].sourceIndex ELSE 0]; END; -- utility procedures -- perCentCR: ROPE = Rope.Cat["%).", Rope.FromChar[CR]]; 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; Octal: PROCEDURE[n: CARDINAL] RETURNS[r: ROPE] = INLINE BEGIN r _ Convert.ValueToRope[[unsigned[n, 8]]]; r _ Rope.Cat[r, Rope.FromChar['B]]; END; END.. <> ev _ LOOPHOLE[gfh.code]; entryPC _ ev.entry[ep].initialpc*2; WITH stb SELECT FROM t: RTSymbolDefs.SymbolTableBase.x => WITH t.e.bb[NARROW[cbti, RTSymbolDefs.CallableBodyIndex.x].e].info SELECT FROM External=> exitPC _ entryPC + bytes - 1; ENDCASE=> SIGNAL Error; t: RTSymbolDefs.SymbolTableBase.y => WITH t.e.bb[NARROW[cbti, RTSymbolDefs.CallableBodyIndex.y].e].info SELECT FROM External=> exitPC _ entryPC + bytes - 1; ENDCASE=> SIGNAL Error; ENDCASE => ERROR; IF entryPC < temp.entryPC OR temp.exitPC < exitPC THEN name _ Rope.Cat[name, "[", Octal[temp.entryPC], "..", Octal[temp.exitPC], "]"]}; IF name = NIL THEN {temp.symbols _ FALSE; name _ Octal[temp.entryPC]};