Create a gist now

Instantly share code, notes, and snippets.

What would you like to do?
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";
}

bigp commented Mar 31, 2015

This is a very tiny piece of advice, but for your lastWasReturn static variable, couldn't you just set it to "false" before you enter the switch statements, since most of its case XXXXX results in setting it to false, and only the EReturn case sets it to true?

Then you could remove those = false, and just have the one = true in the EReturn.

Owner

FuzzyWuzzie commented Apr 1, 2015

Ahh, good catch! Thanks!

I think I spent too long on this example trying to figure things out and went a little spacey 😁

pshtif commented Apr 1, 2015

Just curious why are you going about in such verbose way when you can utilize ExprTools for macros, maybe I am missing something but almost half the stuff you mentioned could be skipped and just remap all the returns recursively using map.

static public function remapReturn(expr) {
return
switch (expr.expr) {
case EReturn(e):
if (e == null) {
macro {
// Call end profile here
return;
}
} else {
macro {
var ___temp = ${e};
// Call end profile here
return ___temp;
}
}
case _:
ExprTools.map(expr,remapReturn);
}
}

Owner

FuzzyWuzzie commented Apr 1, 2015

Thanks @pshtif, you're totally right! I didn't know about the ExprTools (specifically the map capability). I've updated the gist to reflect your changes.

bigp commented Apr 1, 2015

Great recommendation @pshtif!

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