MODULE HierarchicalProfiler; (** AUTHOR "staubesv"; PURPOSE "Simple statistical hierarchical profiler"; *) IMPORT SYSTEM, Machine, Streams, Modules, Objects, Kernel, Reflection, Commands, Options, Strings, Errors, HierarchicalProfiler0; CONST Ok* = 0; AlreadyRunning* = 5101; NotRunning* = 5102; NoProfileDataAvailable* = 5103; SampleBufferFull* = 5104; SampleBufferNotInitialized* = 5105; (* profile creation parameters Note: The profiler always gathers all data necessary for any profile *) (* type *) Hierarchical* = 0; Flat* = 1; (* thread / processor information *) None* = 0; Threads* = 1; Processors* = 2; ThreadsProcessors* = 3; ProcessorsThreads* = 4; (* Profiler states *) NotRunningNoDataAvailable* = 0; NotRunningDataAvailable* = 1; Running* = 2; DefaultMaxTime = 30; MaxUnwindingDepth = 64; Invalid = 0; TYPE Name = ARRAY 256 OF CHAR; Sample = ARRAY MaxUnwindingDepth OF ADDRESS; Samples = POINTER TO ARRAY OF Sample; (* HUGE!! *) SampleInfo = RECORD processorID : LONGINT; process : Objects.Process; END; SampleInfos = POINTER TO ARRAY OF SampleInfo; TYPE (** 'Node's are use to represent the hierarchical profile *) Node* = OBJECT VAR parent- : Node; child- : Node; sibling- : Node; count- : LONGINT; percent- : REAL; nofChildren- : LONGINT; (* number of direct descendants *) name- : Name; (* for external profile processing *) extern* : BOOLEAN; marked* : BOOLEAN; next : Node; (* for internal purposes, e.g. sorting *) PROCEDURE GetCaption*() : Strings.String; VAR string : ARRAY 256 OF CHAR; number : ARRAY 16 OF CHAR; BEGIN string := "["; Strings.IntToStr(ENTIER(percent), number); Strings.AppendX(string, number); Strings.AppendX(string, "."); Strings.IntToStr(ENTIER(10 * (percent - ENTIER(percent))), number); Strings.AppendX(string, number); Strings.AppendX(string, "%, "); Strings.IntToStr(count, number); Strings.AppendX(string, number); Strings.AppendX(string, "]: "); Strings.AppendX(string, name); RETURN Strings.NewString(string); END GetCaption; PROCEDURE Show(out : Streams.Writer; indent : LONGINT); VAR i : LONGINT; BEGIN ASSERT(out # NIL); FOR i := 0 TO indent-1 DO out.Char(" "); END; out.String("["); out.Int(ENTIER(percent), 0); out.Char("."); out.Int(ENTIER(10*(percent - ENTIER(percent))), 0); out.String("%, "); out.Int(count, 0); out.String("]: "); out.String(name); out.Ln; out.Update; END Show; PROCEDURE &Init*; (* private *) BEGIN parent := NIL; child := NIL; sibling := NIL; count := 0; percent := 0; nofChildren := 0; name := ""; extern := FALSE; marked := TRUE; next := NIL; END Init; END Node; TYPE VisitorProcedure* = PROCEDURE {DELEGATE} (node : Node); Profile* = OBJECT VAR nodes- : Node; nofSamples- : LONGINT; nofProcessors- : LONGINT; nofRunsTooDeep- : LONGINT; nofUnwindingFaults- : LONGINT; nofSamplesNotStored- : LONGINT; pattern : ARRAY 64 OF CHAR; minPercent : LONGINT; PROCEDURE FindNode(CONST name : Name; list : Node) : Node; BEGIN WHILE (list # NIL) & (list.name # name) DO list := list.next; END; RETURN list; END FindNode; (** Insert node 'newNode' into 'parent.next' list. If a node with the same name is already present, merge it with the newNode *) PROCEDURE MergeNode(newNode, parent: Node); VAR node : Node; BEGIN ASSERT((newNode # NIL) & (parent # NIL)); node := FindNode(newNode.name, parent.next); IF (node = NIL) THEN newNode.next := parent.next; parent.next := newNode; ELSE node.count := node.count + newNode.count; newNode.next := NIL; END; END MergeNode; PROCEDURE Flatten*(parent: Node); VAR child : Node; PROCEDURE MergeChildren(child : Node); BEGIN WHILE (child # NIL) DO MergeNode(child, parent); MergeChildren(child.child); child := child.sibling; END; END MergeChildren; BEGIN {EXCLUSIVE} ASSERT(parent # NIL); (* Merge all children of 'parent' into the parent.next list *) parent.next := NIL; MergeChildren(parent.child); (* adjust sibling references *) parent.child := parent.next; parent.next := NIL; child := parent.child; WHILE (child # NIL) DO child.sibling := child.next; child := child.next; END; (* clear 'next' references *) parent.nofChildren := 0; child := parent.child; WHILE (child # NIL) DO child.parent := parent; INC(parent.nofChildren); child.child := NIL; child.nofChildren := 0; child.next := NIL; child := child.sibling; END; (* sort children *) PostProcessProfile(SELF); END Flatten; PROCEDURE VisitorClearMark(node : Node); BEGIN ASSERT(node # NIL); node.marked := FALSE; END VisitorClearMark; PROCEDURE Mark*(CONST pattern : ARRAY OF CHAR; minPercent : LONGINT); BEGIN {EXCLUSIVE} COPY(pattern, SELF.pattern); SELF.minPercent := minPercent; VisitNodes(nodes, VisitorClearMark); VisitNodes(nodes, VisitorSetMark); END Mark; PROCEDURE VisitorSetMark(node : Node); VAR parent : Node; BEGIN ASSERT(node # NIL); IF Strings.Match(pattern, node.name) & (node.percent >= minPercent) THEN (* mark leaf node and all its parents *) node.marked := TRUE; parent := node.parent; WHILE (parent # NIL) & (parent.marked = FALSE) DO parent.marked := TRUE; parent := parent.parent; END; END; END VisitorSetMark; PROCEDURE VisitNodes(node : Node; visitorProc : VisitorProcedure); BEGIN ASSERT(visitorProc # NIL); WHILE (node # NIL) DO VisitNodes(node.child, visitorProc); visitorProc(node); node := node.sibling; END; END VisitNodes; PROCEDURE Visit*(visitorProc : VisitorProcedure); BEGIN {EXCLUSIVE} VisitNodes(nodes, visitorProc); END Visit; PROCEDURE &Init*; BEGIN nodes := NIL; nofSamples := 0; nofProcessors := 0; nofRunsTooDeep := 0; nofUnwindingFaults := 0; nofSamplesNotStored := 0; pattern := "*"; minPercent := 0; END Init; END Profile; VAR (* sample data *) samples : Samples; sampleInfos : SampleInfos; maxNofSamples : LONGINT; (* statistics *) nofRunsTooDeep : LONGINT; nofUnwindingFaults : LONGINT; nofSamplesNotStored : LONGINT; nofSamples : LONGINT; (* current index into 'samples' array *) currentIndex : LONGINT; locked : BOOLEAN; (* protect 'currentIndex' *) (* Profiler state *) state : LONGINT; (* Find a node with name 'name' within the children of 'parent'. Returns NIL if no such node found *) PROCEDURE FindChildNode(CONST name : Name; parent : Node) : Node; VAR child : Node; BEGIN ASSERT(parent # NIL); child := parent.child; WHILE (child # NIL) & (child.name # name) DO child := child.sibling; END; RETURN child; END FindChildNode; (* Add node for procedure 'procedurename' to the children of 'parent'. If there is already a node for the procedure, just increment the 'Node.count' field *) PROCEDURE MergeChildNode(CONST procedureName : ARRAY OF CHAR; parent : Node) : Node; VAR child, temp : Node; name : Name; BEGIN ASSERT((procedureName # "") & (parent # NIL)); COPY(procedureName, name); child := FindChildNode(name, parent); IF (child # NIL) THEN (* merge *) INC(child.count); ELSE (* create and insert new child *) NEW(child); child.name := name; child.count := 1; child.parent := parent; INC(parent.nofChildren); IF (parent.child = NIL) THEN parent.child := child; ELSE temp := parent.child; WHILE (temp.sibling # NIL) DO temp := temp.sibling; END; temp.sibling := child; END; END; ASSERT(child # NIL); RETURN child; END MergeChildNode; (* Add 'sample' to 'profile' *) PROCEDURE AddSample(profile : Node; type, info : LONGINT; CONST sampleInfo : SampleInfo; CONST sample : Sample); VAR node : Node; module : Modules.Module; pc,startpc : ADDRESS; nodeName, name : Name; i : LONGINT; PROCEDURE GenerateNodeName(module : Modules.Module; CONST procedureName : ARRAY OF CHAR) : Name; VAR name : Name; BEGIN IF (module # NIL) THEN COPY(module.name, name); ELSE name := "Unknown"; END; Strings.AppendX(name, "."); Strings.AppendX(name, procedureName); RETURN name; END GenerateNodeName; PROCEDURE GenerateProcessorName(processorID : LONGINT) : Name; VAR name : Name; nbr : ARRAY 16 OF CHAR; BEGIN name := "Processor P"; Strings.IntToStr(processorID, nbr); Strings.AppendX(name, nbr); RETURN name; END GenerateProcessorName; PROCEDURE GenerateProcessName(process : Objects.Process) : Name; VAR name : Name; nbr : ARRAY 16 OF CHAR; module : Modules.Module; typeDescriptor : Modules.TypeDesc; adr : ADDRESS; BEGIN IF (process # NIL) THEN name := "Thread ID="; Strings.IntToStr(process.id, nbr); Strings.AppendX(name, nbr); Strings.AppendX(name, " ["); IF (process.obj # NIL) THEN SYSTEM.GET(SYSTEM.VAL(ADDRESS, process.obj)-SIZEOF(ADDRESS), adr); Modules.ThisTypeByAdr(adr, module, typeDescriptor); IF (module # NIL) THEN Strings.AppendX(name, module.name); Strings.AppendX(name, "."); IF (typeDescriptor # NIL) & (typeDescriptor.name # "") THEN Strings.AppendX(name, typeDescriptor.name); ELSE Strings.AppendX(name, "UnknownType"); END; ELSE Strings.AppendX(name, "UnknownModule"); END; ELSE Strings.AppendX(name, "Unknown"); END; Strings.AppendX(name, "]"); ELSE name := "Thread=NIL"; END; RETURN name; END GenerateProcessName; BEGIN node := profile; CASE info OF |None: (* skip *) |Threads: node := MergeChildNode(GenerateProcessName(sampleInfo.process) , node); |Processors: node := MergeChildNode(GenerateProcessorName(sampleInfo.processorID) , node); |ThreadsProcessors: node := MergeChildNode(GenerateProcessName(sampleInfo.process) , node); node := MergeChildNode(GenerateProcessorName(sampleInfo.processorID) , node); |ProcessorsThreads: node := MergeChildNode(GenerateProcessorName(sampleInfo.processorID) , node); node := MergeChildNode(GenerateProcessName(sampleInfo.process) , node); ELSE (* ignore *) END; IF (type = Hierarchical) THEN i := MaxUnwindingDepth-1; WHILE (i >= 1) & (sample[i] = Invalid) DO DEC(i); END; WHILE (i >= 0) DO (* get procedure name *) pc := sample[i]; module := Modules.ThisModuleByAdr(pc); Reflection.GetProcedureName(pc, name, startpc); nodeName := GenerateNodeName(module, name); node := MergeChildNode(nodeName, node); DEC(i); END; ELSE IF (sample[0] # Invalid) THEN pc := sample[0]; module := Modules.ThisModuleByAdr(pc); Reflection.GetProcedureName(pc, name,startpc); nodeName := GenerateNodeName(module, name); node := MergeChildNode(nodeName, node); END; END; END AddSample; PROCEDURE HandleTimer(id: LONGINT; process : Objects.Process; pc, bp, lowAdr, highAdr : ADDRESS); VAR index, depth : LONGINT; n: ADDRESS; BEGIN (* acquire lock that protects currentIndex *) WHILE Machine.AtomicTestSet(locked) DO Machine.SpinHint; (* busy wait *) END; index := currentIndex; INC(currentIndex); locked := FALSE; (* release lock *) IF (index < maxNofSamples) THEN Machine.AtomicInc(nofSamples); ELSE Machine.AtomicInc(nofSamplesNotStored); RETURN; END; sampleInfos[index].processorID := id; sampleInfos[index].process := process; (* unwind stack *) samples[index][0] := pc; depth := 1; WHILE (bp # 0) & (lowAdr <= bp) & (bp < highAdr) (* Machine.Less(bp, highAdr)*) & (depth < MaxUnwindingDepth) DO SYSTEM.GET(bp, n); IF ODD(n) THEN INC(bp, SIZEOF(ADDRESS)); END; SYSTEM.GET(bp + SIZEOF(ADDRESS), pc); SYSTEM.GET(bp, bp); samples[index][depth] := pc; INC(depth); END; IF (bp # 0) & ((bp < lowAdr) OR (bp > highAdr)) THEN InvalidateSample(samples[index]); Machine.AtomicInc(nofUnwindingFaults); END; IF (depth >= MaxUnwindingDepth) THEN (* run not valid *) InvalidateSample(samples[index]); Machine.AtomicInc(nofRunsTooDeep); END; END HandleTimer; PROCEDURE InvalidateSample(VAR sample : Sample); VAR i : LONGINT; BEGIN FOR i := 0 TO MaxUnwindingDepth-1 DO sample[i] := Invalid; END; END InvalidateSample; (* Sort children of node 'parent' using insertion sort *) PROCEDURE SortChildren(parent : Node); VAR temp, sortedNodes : Node; PROCEDURE InsertSorted(node : Node; VAR list : Node); VAR temp : Node; BEGIN ASSERT(node # NIL); IF (list = NIL) OR (node.count >= list.count) THEN node.next := list; list := node; ELSE temp := list; WHILE (temp.next # NIL) & (temp.next.count >= node.count) DO temp := temp.next; END; node.next := temp.next; temp.next := node; END; END InsertSorted; BEGIN IF (parent # NIL) & (parent.child # NIL) & (parent.child.sibling # NIL) THEN temp := parent.child; WHILE (temp # NIL) DO InsertSorted(temp, sortedNodes); temp := temp.sibling; END; parent.child := sortedNodes; temp := sortedNodes; WHILE (temp # NIL) DO temp.sibling := temp.next; temp := temp.next; END; END; END SortChildren; PROCEDURE PostProcessNode(profile : Profile; node : Node); BEGIN WHILE (node # NIL) DO (* calculate percentages *) node.extern := FALSE; node.percent := 100 * (node.count / profile.nofSamples); SortChildren(node); PostProcessNode(profile, node.child); node := node.sibling; END; END PostProcessNode; PROCEDURE PostProcessProfile(profile : Profile); BEGIN ASSERT(profile # NIL); PostProcessNode(profile, profile.nodes); END PostProcessProfile; PROCEDURE CreateProfile(type : LONGINT; info : LONGINT) : Profile; VAR profile : Profile; index : LONGINT; BEGIN (* {Caller holds module lock} *) ASSERT(samples # NIL); NEW(profile); profile.nofSamples := nofSamples; profile.nofProcessors := Machine.NumberOfProcessors(); profile.nofRunsTooDeep := nofRunsTooDeep; profile.nofUnwindingFaults := nofUnwindingFaults; profile.nofSamplesNotStored := nofSamplesNotStored; NEW(profile.nodes); profile.nodes.count := nofSamples; profile.nodes.name := "Profile"; FOR index := 0 TO nofSamples-1 DO AddSample(profile.nodes, type, info, sampleInfos[index], samples[index]); END; PostProcessProfile(profile); RETURN profile; END CreateProfile; (** Returns the size of the sampling buffer in bytes for a given maximum sampling time in seconds *) PROCEDURE GetBufferSize*(time : LONGINT) : LONGINT; BEGIN RETURN time * Kernel.Second * Machine.NumberOfProcessors() * MaxUnwindingDepth * SIZEOF(ADDRESS); END GetBufferSize; (** Generate hierarchical profile of the last profiler run's data. Returns NIL if no data available *) PROCEDURE GetProfile*(type, info : LONGINT; VAR profile : Profile; VAR res : WORD); BEGIN {EXCLUSIVE} profile := NIL; IF (state # Running) THEN IF (samples # NIL) THEN profile := CreateProfile(type, info); res := Ok; ELSE res := NoProfileDataAvailable; END; ELSE res := AlreadyRunning; END; END GetProfile; (** Start profiling. If the profiler is already running, it is stopped and the sample data is discarded before re-starting it *) PROCEDURE Start*(context : Commands.Context); (** [options] ~ *) VAR options : Options.Options; unit : ARRAY 4 OF CHAR; maxTime, bufferSize: LONGINT; res: WORD; BEGIN NEW(options); options.Add("t", "time", Options.Integer); (* in seconds *) IF options.Parse(context.arg, context.error) THEN IF ~options.GetInteger("time", maxTime) THEN maxTime := DefaultMaxTime; END; IF (maxTime > 0) THEN StartProfiling(maxTime, res); IF (res = Ok) THEN context.out.String("Profiler started. MaxTime: "); context.out.Int(maxTime, 0); context.out.String(" seconds, MaxDepth: "); context.out.Int(MaxUnwindingDepth, 0); context.out.String(" frames ["); unit := "B"; bufferSize := GetBufferSize(maxTime); IF (bufferSize DIV 1024 > 10) THEN bufferSize := bufferSize DIV 1024; unit := "KB"; END; IF (bufferSize DIV 1024 > 10000) THEN bufferSize := bufferSize DIV 1024; unit := "MB"; END; context.out.Int(bufferSize, 0); context.out.String(" "); context.out.String(unit); context.out.String(" buffer]"); ELSE Errors.ToStream(res, context.out) END; ELSE context.out.String("Parameter error: time must be >= 1"); END; context.out.Ln; END; END Start; (** Start profiling. If the profiler is already running, it is stopped and the sample data is discarded before re-starting it *) PROCEDURE StartProfiling*(maxTime : LONGINT; VAR res : WORD); BEGIN {EXCLUSIVE} ASSERT(maxTime > 0); IF (state # Running) THEN currentIndex := 0; nofSamples := 0; nofRunsTooDeep := 0; nofUnwindingFaults := 0; nofSamplesNotStored := 0; maxNofSamples := maxTime * Kernel.Second * Machine.NumberOfProcessors(); NEW(samples, maxNofSamples); NEW(sampleInfos, maxNofSamples); TRACE('enabling hprop0'); HierarchicalProfiler0.Enable(HandleTimer); state := Running; res := Ok; ELSE res := AlreadyRunning; END; END StartProfiling; (** Stop profiling. The profile data is not discarded. It can be retrieved using the procedure 'GetProfile' *) PROCEDURE Stop*(context : Commands.Context); VAR res : WORD; BEGIN StopProfiling(res); IF (res = Ok) THEN context.out.String("Profiler stopped, "); context.out.Int(nofSamples, 0); context.out.String(" samples"); ELSE Errors.ToStream(res, context.out); END; context.out.Ln; END Stop; (** Stop profiling. The profile data is not discarded. It can be retrieved using the procedure 'GetProfile' *) PROCEDURE StopProfiling*(VAR res : WORD); BEGIN {EXCLUSIVE} IF (state = Running) THEN HierarchicalProfiler0.Disable; state := NotRunningDataAvailable; res := Ok; ELSE res := NotRunning; END; END StopProfiling; PROCEDURE Continue*(context : Commands.Context); (** ~ *) VAR res : WORD; BEGIN ContinueProfiling(res); IF (res = Ok) THEN context.out.String("Continue profiling..."); ELSE Errors.ToStream(res, context.out); END; context.out.Ln; END Continue; PROCEDURE ContinueProfiling*(VAR res : WORD); BEGIN {EXCLUSIVE} IF (state # Running) THEN IF (samples # NIL) THEN IF (nofSamples < maxNofSamples) THEN HierarchicalProfiler0.Enable(HandleTimer); state := Running; res := Ok; ELSE res := SampleBufferFull; END; ELSE res := SampleBufferNotInitialized; END; ELSE res := AlreadyRunning; END; END ContinueProfiling; (** Returns TRUE if the profiler is currently running, FALSE otherwise *) PROCEDURE GetState*(VAR currentSamples, maxSamples : LONGINT) : LONGINT; BEGIN {EXCLUSIVE} IF (state = Running) THEN currentSamples := currentIndex; maxSamples := maxNofSamples; END; RETURN state; END GetState; (** Show the profile *) PROCEDURE Show*(context : Commands.Context); VAR profile : Profile; indent : LONGINT; PROCEDURE ShowNodes(parent : Node; indent : LONGINT; out : Streams.Writer); BEGIN WHILE (parent # NIL) DO parent.Show(out, indent); ShowNodes(parent.child, indent +4, out); parent := parent.sibling; END; END ShowNodes; BEGIN {EXCLUSIVE} IF (state # Running) THEN IF (samples # NIL) THEN profile := CreateProfile(Hierarchical, None); indent := 0; ShowNodes(profile.nodes, 0, context.out); ELSE context.out.String("No profile data available!"); END; ELSE context.out.String("Profiler is running!"); END; context.out.Ln; END Show; PROCEDURE Cleanup; VAR ignore : WORD; BEGIN StopProfiling(ignore); END Cleanup; BEGIN locked := FALSE; state := NotRunningNoDataAvailable; Modules.InstallTermHandler(Cleanup); END HierarchicalProfiler. HierarchicalProfiler.Start ~ HierarchicalProfiler.Stop ~ HierarchicalProfiler.Show ~ System.Free HierarchicalProfiler ~