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

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.

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)