Skip to content

Instantly share code, notes, and snippets.

@hamaluik
Last active April 6, 2020 23:11
Show Gist options
  • Save hamaluik/412e2109a5f5fbcf12e1 to your computer and use it in GitHub Desktop.
Save hamaluik/412e2109a5f5fbcf12e1 to your computer and use it in GitHub Desktop.
Simple Haxe Profiler
package ;
import haxe.ds.StringMap;
import haxe.macro.Context;
import haxe.macro.Expr;
import haxe.macro.Printer;
import haxe.macro.Type.ClassType;
import neko.Lib;
using haxe.macro.ExprTools;
typedef MethodProfile = {
var calls:Int;
var startTime:Float;
var elapsedTime:Float;
}
class Profiler
{
/**
* An internal tool for determining the fully-qualified-name of a class
* @param cls a macro classtype
* @return the fully-qualified-name of the class
*/
private static function getFullClassName(cls:ClassType):String
{
return (cls.pack.length > 0 ? cls.pack.join(".") + "." : "") + cls.name;
}
private static var lastWasReturn:Bool = false;
private static var clsName:String = "";
private static var methodName:String = "";
/**
* This is a recursive function which will tunnel into a function's expressions and replace any
* occurrances of a return expression with a custom profiling return expressions
* @param expr the expression to recursively search through
* @return the transformed expression
*/
private static function remapReturn(expr:Expr):Expr
{
lastWasReturn = false;
switch(expr.expr)
{
case EReturn(retExpr):
{
lastWasReturn = true;
if (retExpr == null)
{
return macro {
Profiler.endProfile($v { clsName }, $v { methodName } );
return;
};
}
else
{
return macro {
var ___tempProfilingReturnValue = ${retExpr};
Profiler.endProfile($v { clsName }, $v { methodName } );
return ___tempProfilingReturnValue;
};
}
}
case _:
return ExprTools.map(expr, remapReturn);
}
}
/**
* This function, when used in a build macro, will inject profiling code at the beginning
* and ending of each function. Call using a build macro such as:
* @:build(Profiler.profile())
* class SomeClass {
* ...
* }
*/
macro public static function profile():Array<Field>
{
// get the fields of the class
var fields:Array<Field> = Context.getBuildFields();
var printer:Printer = new Printer();
// and the fully qualified class name
clsName = getFullClassName(Context.getLocalClass().get());
// loop through each field to find the methods
for (field in fields)
{
switch(field.kind)
{
// yay, found a method!
case FFun(func):
{
// get the name of the method
methodName = field.name;
// prepend the start code to the function
func.expr = macro {
Profiler.startProfile($v { clsName }, $v { methodName } );
$ { func.expr };
};
// start the recursive expression transformation
lastWasReturn = false;
func.expr = remapReturn(func.expr);
if (!lastWasReturn)
{
func.expr = macro {
$ { func.expr };
Profiler.endProfile($v { clsName }, $v { methodName } );
return;
}
}
}
// skip properties and variables
default: { };
}
}
return fields;
}
private static var profiles:StringMap<StringMap<MethodProfile>> = new StringMap<StringMap<MethodProfile>>();
/**
* Reset all the profiling information. Doing this before reading / printing the information will
* cause all the data collected since the beginning (or last reset) to be lost
*/
public static function reset()
{
profiles = new StringMap<StringMap<MethodProfile>>();
}
/**
* Called at the start of a function to record when in time the method was called. This must always
* be called BEFORE an endProfile() call is made
* @param className the fully-qualified class name of the method's class
* @param methodName the name of the method being profiled
*/
public static function startProfile(className:String, methodName:String)
{
// make sure the profiles exist
if (!profiles.exists(className))
profiles.set(className, new StringMap<MethodProfile>());
if (!profiles.get(className).exists(methodName))
profiles.get(className).set(methodName, { calls: 0, startTime: 0, elapsedTime: 0 } );
profiles.get(className).get(methodName).startTime = Sys.cpuTime();
profiles.get(className).get(methodName).calls++;
Lib.println("> Starting " + className + "." + methodName);
}
/**
* Called at the end of a function to calculate the method's execution time. This must always
* be called AFTER a startProfile() call
* @param className the fully-qualified class name of the method's class
* @param methodName the name of the method being profiled
*/
public static function endProfile(className:String, methodName:String)
{
var t:Float = Sys.cpuTime();
if (!profiles.exists(className) || !profiles.get(className).exists(methodName))
throw "EndProfile was called on a function that was never started!";
profiles.get(className).get(methodName).elapsedTime += t - profiles.get(className).get(methodName).startTime;
Lib.println("< Ending " + className + "." + methodName);
}
/**
* Just a utility function to print the profiling data, separated by class.
*/
public static function printProfiles():Void
{
var totalTime:Float = 0;
for (className in profiles.keys())
{
var classTime:Float = 0;
Lib.println(className + ":");
for (methodName in profiles.get(className).keys())
{
Lib.println(" ." + methodName + ": " + profiles.get(className).get(methodName).elapsedTime + "s (" + profiles.get(className).get(methodName).calls + " calls)");
classTime += profiles.get(className).get(methodName).elapsedTime;
}
Lib.println(" ---");
Lib.println(" " + classTime + "s");
totalTime += classTime;
}
Lib.println("");
Lib.println("Total time: " + totalTime + "s");
}
}
package ;
import haxe.macro.Printer;
import neko.Lib;
class Main
{
static function main()
{
var worker:Worker = new Worker();
worker.doSomething();
Lib.println(worker.derp());
Lib.println("w/ 0: " + worker.doSomethingElse(0));
Lib.println("w/ 1: " + worker.doSomethingElse(1));
Lib.println("w/ 2: " + worker.doSomethingElse(2));
Lib.println("w/ 3: " + worker.doSomethingElse(3));
Lib.println("w/ 4: " + worker.doSomethingElse(4));
Lib.println("w/ 5: " + worker.doSomethingElse(5));
Profiler.printProfiles();
}
}
> Starting Worker.new
< Ending Worker.new
> Starting Worker.doSomething
< Ending Worker.doSomething
> Starting Worker.derp
< Ending Worker.derp
herp
> Starting Worker.doSomethingElse
< Ending Worker.doSomethingElse
w/ 0: 0
> Starting Worker.doSomethingElse
< Ending Worker.doSomethingElse
w/ 1: 1
> Starting Worker.doSomethingElse
< Ending Worker.doSomethingElse
w/ 2: 2
> Starting Worker.doSomethingElse
< Ending Worker.doSomethingElse
w/ 3: 3
> Starting Worker.doSomethingElse
< Ending Worker.doSomethingElse
w/ 4: 4
> Starting Worker.doSomethingElse
< Ending Worker.doSomethingElse
w/ 5: 4
Worker:
.new: 0s (1 calls)
.doSomething: 0.046875s (1 calls)
.derp: 0s (1 calls)
.doSomethingElse: 0s (6 calls)
---
0.046875s
package ;
import neko.Lib;
@:build(Profiler.profile())
@:autoBuild(Profiler.profile())
class Worker
{
public function new()
{
}
public function doSomething():Void
{
var q:Float = 0;
for (i in 0...1000000)
{
q += 3.14159;
}
}
public function doSomethingElse(x:Int):Float
{
try
{
if (x == 0)
return 0;
else if (x == 1)
throw "derp";
}
catch (exc:String) { return 1; }
switch(x)
{
case 2:
return 2;
case 3:
return 3;
}
return 4;
}
public function derp():String return "herp";
}
@chamberlainpi
Copy link

Great recommendation @pshtif!

@AlexHaxe
Copy link

I tried this on a php project and I found two issues:

  1. remapReturn should also have a case for EThrow expressions to make it handle exits via exceptions
  2. remapReturn should be inside a #if macro … #end condition, to make sure haxe does not try to compile it to target (you get an Class<haxe.macro.Context> has no field makeExpr error for every $v)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment