Simple Haxe Profiler

!Profiler.hx

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");
	}
}

Main.hx

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();
	}
}

Output

 > 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

Worker.hx

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";
}

Ahh, good catch! Thanks!

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

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);
}
}

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.

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)