Profiler

Belimoth

(Posted 2012) [#1]

This is the profiler code I use myself.

'=============================
'profiler.monkey by Belimoth
'uncomment the commented code to have the profiler profile itself :P
'=============================
Import mojo
'=============================
Class cProfilerMap Extends StringMap<cProfiler>
End
'=============================
Class Profiler
	Const NUMBER_OF_CALLS_TO_AVERAGE:Int = 100
	
	Global profilers := New cProfilerMap
	Global running := New List<cProfiler>
	'Global startProfiler := New cProfiler("Profiler Start", NUMBER_OF_CALLS_TO_AVERAGE, False)
	'Global stopProfiler := New cProfiler("Profiler Stop", NUMBER_OF_CALLS_TO_AVERAGE, False)
	
	Function Start:Void(profilerName:String, callsMax:Int = NUMBER_OF_CALLS_TO_AVERAGE)
		'startProfiler.Start()
		If profilers.Contains(profilerName)
			profilers.Get(profilerName).Start()
		Else
			Local parent:cProfiler
			If running.IsEmpty()
				parent = Null
			Else
				parent = running.Last()
			Endif
			
			If parent = Null
				Local profilerNew := New cProfiler(profilerName, callsMax, True)
				profilers.Add(profilerName, profilerNew)
				profilerNew.Start()
			Elseif parent.children.Contains(profilerName)
				parent.children.Get(profilerName).Start()
			Else
				Local profilerNew := New cProfiler(profilerName, callsMax, True)
				parent.children.Add(profilerName, profilerNew)
				profilerNew.Start()
			Endif
		Endif
		'startProfiler.Stop()
	End
	
	Function Stop:Void(profilerName:String = "this doesn't really matter")
		'stopProfiler.Start()
		running.Last().Stop()
		'stopProfiler.Stop()
	End
	
	Function Output:Void()
		Print ""
		Print "PROFILER RESULTS"
		Print ""
		'Print startProfiler
		'Print stopProfiler
		Local profilerTemp:cProfiler
		For profilerTemp = Eachin profilers.Values()
			PrintProfiler(profilerTemp)
		Next
		Print ""
	End
	
	Function PrintProfiler:Void(profiler:cProfiler, indent:String = "")
		Print indent + profiler
		If profiler.HasChildren()
			Local profilerTemp:cProfiler
			For profilerTemp = Eachin profiler.children.Values()
				PrintProfiler(profilerTemp, indent + "   ")
			Next
		Endif
	End
End
'=============================
Class cProfiler
	Field name:String
	
	Field timeStart:Int
	Field calls:Int
	Field callsMax:Int
	Field total:Float
	Field result:Float
	
	Field doneCounting:Bool
	Field children:cProfilerMap
	Field nest:Bool
	
	Method New(name:String, callsMax:Int, nest:Bool = False)
		Self.name = name
		Self.callsMax = callsMax
		Self.nest = nest
		If nest = True
			Self.children = New cProfilerMap
		Endif
	End
	
	Method New(callsMax:Int)
		Self.name = "Profiler"
		Self.callsMax = callsMax
		Self.nest = False
	End
	
	Method GetResult:Float()
		Return result
	End
	
	Method HasChildren:Bool()
		Return Not( children.IsEmpty() )
	End
	
	Method Start:Void()
		If nest Then Profiler.running.AddLast(Self)
		timeStart = Millisecs()
		If calls >= callsMax
			calls = 0
			total = 0.0
		Endif
	End
	
	Method Stop:Void()
		If nest Then Profiler.running.RemoveLast()	'should be self
		Local timePassed:Int = Millisecs() - timeStart
		total += timePassed
		calls += 1
		If calls >= callsMax
			doneCounting = True
			result = total / calls
		Endif
	End
	
	Method ToString:String()
		If doneCounting
			Return name + ": " + result
		Else
			Return name + " is not done counting"
		Endif
	End
End
'=============================

Belimoth

(Posted 2012) [#2]

Here is how it would be used:

'=============================
'example.monkey
'=============================
Strict
Import mojo
Import profiler
'=============================


'============MAIN=============
Function Main:Int()
	New MyApp()
	Return 1
End
'=============================



'=============APP=============
Class MyApp Extends App
	
	Field fpsProfiler:cProfiler

	'=============================
	Method OnCreate:Int()
		fpsProfiler = New cProfiler(10)
		Profiler.Start("OnCreate", 1)
		
		'initializing stuff

		SetUpdateRate(60)
		
		Profiler.Stop("OnCreate")
		Return 1
	End
	'=============================
	Method OnUpdate:Int()
		Profiler.Start("OnUpdate")
		
		'doing stuff
		
		Profiler.Stop("OnUpdate")
		If KeyHit(KEY_ENTER)
			Profiler.Output()
		Endif
		Return 1
	End
	'=============================
	Method OnRender:Int()
		Profiler.Start("OnRender")
		

		Profiler.Start("Drawing Stuff")
		'drawing stuff
		Profiler.Stop("Drawing Stuff")
	
		'drawing other stuff

		Profiler.Stop("OnRender")
		fpsProfiler.Stop()
		fpsProfiler.Start()
		DrawText("FPS: " + Int(1000 / fpsProfiler.GetResult()), 1, 1)
		Return 1
	End
	'=============================
End
'=============================

As you can see there are two ways to use it:
a) Standalone profilers that you manage yourself, as in fpsProfiler above.
b) Automatically managed profilers that are named and will show all of their results together when Profiler.Output() is called.

It is nifty :)

Belimoth

(Posted 2012) [#3]

The syntaxes are:

myProfiler = New cProfiler(numberOfCallsToAverage:Int)
myProfiler.Start()
myProfiler.Stop()
myProfiler.GetResult()

Profiler.Start("My Profile", numberOfCallsToAverage:Int = 100)
Profiler.Stop("My Profile")
Profiler.Output()

One caveat, don't do this with the named profilers:

Profiler.Start("Profile A")
	Profiler.Start("Profile B")
Profiler.Stop("Profile A")
	Profiler.Stop("Profile B")

I'm not sure why you would do that, but just so you are aware, it will expect named profilers to be nested properly.

Belimoth

(Posted 2012) [#4]

You can see it in action in this demo.

Difference

(Posted 2012) [#5]

Excellent. Thank you for sharing.

CopperCircle

(Posted 2012) [#6]

Great work I am going to use this on my current project that has a bottle neck.

Tri|Ga|De

(Posted 2012) [#7]

I know this could be a stupid question, but what do I use this for?

Belimoth

(Posted 2012) [#8]

You use it to see how long each part of your program takes on average, so if things are going slow you can find out where the problem is :)

Tri|Ga|De

(Posted 2012) [#9]

Okay thanks!

Belimoth

(Posted 2013) [#10]

EDIT: Double post :(

Belimoth

(Posted 2013) [#11]

Been putting some more work into this for my framework. The new version doesn't do any averaging yet, but it DOES have the ability to graph its results.

'abuprofiler.monkey by Belimoth

Strict
Import mojo
'Import abutoolbox



Public

#If CONFIG = "debug"

Class Profiler

Public
	Const FRAMES_TO_PROFILE:Int = 60 * 5				'5 seconds at 60 FPS

	Function Update:Void()
		For Local profiler:Profiler = EachIn profilers.Values()
			profiler.results[tracker] = profiler.timeConsumed
			profiler.timeConsumed = 0
		Next
		tracker = (tracker + 1) Mod FRAMES_TO_PROFILE
	End

	Function Start:Void(name:String, nest:Bool = True, rgb:Int[] = [255, 255, 255])
		Local profiler:Profiler = profilers.Get(name)
		If profiler = Null
			Local parent:Profiler
			If nest = True
				If Not activeProfilers.IsEmpty()
					parent = activeProfilers.Last()
				EndIf
			EndIf
			profiler = New Profiler(name, rgb, parent)
		EndIf
		profiler.Start()
	End
	
	Function Start:Void(name:String, rgb:Int[])
		Start(name, True, rgb)
	End
	
	Function Stop:Void(name:String = "this string isn't really necessary, it will just stop the most recent profiler to preserve nesting")
		If Not activeProfilers.IsEmpty()
			activeProfilers.Last().Stop()
		Else
			Error "Profiler nesting error."
		Endif
	End
	
	Function Mark:Void(label:String)
		'TODO
	End
	
	Function Draw:Void(x:Int, y:Int)
		_Render()
		SetColor(255, 255, 255)
		DrawImage _image, x, y
	End
	
Private
	Global _image:Image
	Global _pixels:Int[]
	Global _rgb:Int
	
	Global profilers := New StringMap<Profiler>
	Global activeProfilers := New List<Profiler>
		Field link:list.Node<Profiler>
	Global tracker:Int
	
	Field name:String
	Field rgb:Int[]
	Field parent:Profiler
	Field children := New StringMap<Profiler>
	
	Field timeStart:Int
	Field timeConsumed:Int
	Field calls:Int
	Field total:Int, totalCalls:Int
	Field results:Int[]
	
	Method New(name:String, rgb:Int[], parent:Profiler)
		Self.name = name
		Self.rgb = rgb
		Self.parent = parent
		If parent <> Null
			parent.children.Add(name, Self)
		Endif
		Self.results = New Int[FRAMES_TO_PROFILE]
		profilers.Add(name, Self)
	End
	
	Method Start:Void()
		link = activeProfilers.AddLast(Self)
		timeStart = Millisecs()
	End
	
	Method Stop:Void()
		Local timePassed:Int = Millisecs() - timeStart
		timeConsumed += timePassed
		calls += 1
		total += timePassed
		totalCalls += 1
		link.Remove()
	End
	
	Function _Render:Void()
		If _image = Null
			_image = CreateImage(FRAMES_TO_PROFILE, 40)
		EndIf
		
		_pixels = FillIntArray(_image.Width() * _image.Height(), $ff000000)
		For Local n := 0 Until FRAMES_TO_PROFILE
			Local x:Int = FRAMES_TO_PROFILE - 1 - (FRAMES_TO_PROFILE + tracker - n - 1) Mod FRAMES_TO_PROFILE				'what
			x = x
			Local y:Int = 39
			For Local profiler:Profiler = EachIn profilers.Values()
				If profiler.parent = Null
					If profiler.results[n] > 0
						_rgb = ($ff000000) | (profiler.rgb[0] Shl 16) | (profiler.rgb[1] Shl 8) | profiler.rgb[2]
						Local yNew:Int = y - profiler.results[n]
						_DrawColumn(x, y, yNew)
						y = yNew - 1
					Endif
				EndIf
			Next
		Next
		
		_image.WritePixels(_pixels, 0, 0, _image.Width(), _image.Height())
	End
	
	Function _DrawColumn:Void(x:Int, y0:Int, y1:Int)
		y1 = Max(0, y1)
		For Local y:Int = y1 To y0
			_DrawPoint(x, y)
		Next
	End
	
	Function _DrawPoint:Void(x:Int, y:Int)
		_pixels[x + y * _image.Width()] = _rgb
	End
End

#Else

Class Profiler
	Const FRAMES_TO_PROFILE:Int = 60 * 5				'5 seconds at 60 FPS
	Function Update:Void()
	Function Start:Void(name:String, nest:Bool = True, rgb:Int[] = [255, 255, 255]) End
	Function Start:Void(name:String, rgb:Int[]) End
	Function Stop:Void(name:String = "this string isn't really necessary, it will just stop the most recent profiler to preserve nesting") End
	Function Mark:Void(label:String) End
	Function Draw:Void(x:Int, y:Int) End
End

#End



Function UpdateProfiler:Void()
	Profiler.Update()
End



Private

Function FillIntArray:Int[](length:Int, value:Int)
	Local arr:Int[] = New Int[length]
	For Local n:= 0 Until length
		arr[n] = value
	Next
	Return arr
End

The DrawLine and DrawRect commands look like absolute garbage on HTML5, so I ended up using an image-based approach with WritePixels. I haven't used Monkey's WritePixels before so I'm sure there are plenty of optimizations to be made.

A basic usage would look like this:

Class MyApp Extends App
	Method OnUpdate()
		Profiler.Update()
		Profiler.Start("OnUpdate", [255, 0, 0])
		...
		Profiler.Stop("OnUpdate")
	End

	Method OnRender()
		Profiler.Start("OnRender", [0, 128, 255])
		...
		Profiler.Stop("OnRender")
		Profiler.Draw(0, 0)
	End
End

Still a work in progress.

EDIT: Also there is a "dummy" profiler that gets substituted for release mode. That way you don't have to go through and remove all the function calls.

EDIT: Fixed a small error with the rendering.

EDIT: More small fixes.