profileKiss print macro, special form, and other statistics

kiss/src/kiss/Kiss.hx

@@ -322,7 +322,7 @@ class Kiss {
         }
         //trace('kiss build $kissFile');
 
-        return _try(() -> {
+        var result = _try(() -> {
             #if profileKiss
             Kiss.measure('Compiling kiss: $kissFile', () -> {
             #end
@@ -357,13 +357,23 @@ class Kiss {
                     });
                 }
 
-                k.fieldList;
             #if profileKiss
             });
+            for (label => timeSpent in profileAggregates) {
+                var usageCount = profileUsageCounts[label];
+                if (timeSpent >= SIGNIFICANT_TIME_SPENT) {
+                    Sys.println('${label} (x${usageCount}): ${timeSpent}');
+                }
+            }
+
             #end
+            k.fieldList;
         });
+        return result;
     }
 
+    static final SIGNIFICANT_TIME_SPENT = 0.05;
+
     public static function load(kissFile:String, k:KissState, ?loadingDirectory:String, loadAllExps = false, ?fromExp:ReaderExp):Null<ReaderExp> {
         if (loadingDirectory == null)
             loadingDirectory = k.loadingDirectory;
@@ -556,7 +566,7 @@ class Kiss {
                 checkNumArgs(mac);
                 macroUsed = true;
                 var expanded = try {
-                    macros[mac](exp, args.copy(), k);
+                    Kiss.measure(mac, ()->macros[mac](exp, args.copy(), k), true);
                 } catch (error:KissError) {
                     throw error;
                 } catch (error:Dynamic) {
@@ -572,7 +582,7 @@ class Kiss {
                 };
             case CallExp({pos: _, def: Symbol(specialForm)}, args) if (specialForms.exists(specialForm) && !macroExpandOnly):
                 checkNumArgs(specialForm);    
-                Right(specialForms[specialForm](exp, args.copy(), k));
+                Right(Kiss.measure(specialForm, ()->specialForms[specialForm](exp, args.copy(), k), true));
             case CallExp({pos: _, def: Symbol(alias)}, args) if (k.callAliases.exists(alias)):
                 convert(CallExp(k.callAliases[alias].withPosOf(exp), args).withPosOf(exp));
             case CallExp(func, args):
@@ -771,12 +781,27 @@ class Kiss {
         }
     }
 
-    public static function measure<T>(processLabel:String, process:Void->T) {
+    static var profileAggregates:Map<String,Float> = [];
+    static var profileUsageCounts:Map<String,Int> = [];
+
+    public static function measure<T>(processLabel:String,  process:Void->T, aggregate=false) {
         var start = Sys.time();
-        Sys.print('${processLabel}... ');
+        if (aggregate) {
+            if (!profileAggregates.exists(processLabel)) {
+                profileAggregates[processLabel] = 0.0;
+                profileUsageCounts[processLabel] = 0;
+            }
+        } else {
+            Sys.print('${processLabel}... ');
+        }
         var result = process();
         var end = Sys.time();
-        Sys.println('${end-start}s');
+        if (aggregate) {
+            profileAggregates[processLabel] += (end - start);
+            profileUsageCounts[processLabel] += 1;
+        } else {
+            Sys.println('${end-start}s');
+        }
         return result;
     }
 

kiss/src/kiss/Prelude.hx

@@ -584,44 +584,50 @@ class Prelude {
      * So don't use raw string literals in Kiss you want parsed and evaluated at runtime.
      */
     public static function convertToHScript(kissStr:String):String {
-        #if (!macro && hxnodejs)
-        var hscript = try {
-            assertProcess("haxelib", ["run", "kiss", "convert", "--all", "--hscript"], kissStr.split('\n'));
-        } catch (e) {
-            throw 'failed to convert ${kissStr} to hscript:\n$e';
-        }
-        if (hscript.startsWith(">>> ")) {
-            hscript = hscript.substr(4);
-        }
-        return hscript.trim();
-        #elseif (!macro && python)
-        var hscript = try {
-            assertProcess("haxelib", ["run", "kiss", "convert", "--hscript"], [kissStr.replace('\n', ' ')], false);
-        } catch (e) {
-            throw 'failed to convert ${kissStr} to hscript:\n$e';
-        }
-        if (hscript.startsWith(">>> ")) {
-            hscript = hscript.substr(4);
-        }
-        return hscript.trim();
-        #elseif sys
-        if (kissProcess == null)
-            kissProcess = new Process("haxelib", ["run", "kiss", "convert", "--hscript"]);
-
-        kissProcess.stdin.writeString('${kissStr.replace("\n", " ")}\n');
-
-        try {
-            var output = kissProcess.stdout.readLine();
-            if (output.startsWith(">>> ")) {
-                output = output.substr(4);
+        #if macro
+        return Kiss.measure("Prelude.convertToHScript", () -> {
+        #end
+            #if (!macro && hxnodejs)
+            var hscript = try {
+                assertProcess("haxelib", ["run", "kiss", "convert", "--all", "--hscript"], kissStr.split('\n'));
+            } catch (e) {
+                throw 'failed to convert ${kissStr} to hscript:\n$e';
             }
-            return output;
-        } catch (e) {
-            var error = kissProcess.stderr.readAll().toString();
-            throw 'failed to convert ${kissStr} to hscript: ${error}';
-        }
-        #else
-        throw "Can't convert Kiss to HScript on this target.";
+            if (hscript.startsWith(">>> ")) {
+                hscript = hscript.substr(4);
+            }
+            return hscript.trim();
+            #elseif (!macro && python)
+            var hscript = try {
+                assertProcess("haxelib", ["run", "kiss", "convert", "--hscript"], [kissStr.replace('\n', ' ')], false);
+            } catch (e) {
+                throw 'failed to convert ${kissStr} to hscript:\n$e';
+            }
+            if (hscript.startsWith(">>> ")) {
+                hscript = hscript.substr(4);
+            }
+            return hscript.trim();
+            #elseif sys
+            if (kissProcess == null)
+                kissProcess = new Process("haxelib", ["run", "kiss", "convert", "--hscript"]);
+
+            kissProcess.stdin.writeString('${kissStr.replace("\n", " ")}\n');
+
+            try {
+                var output = kissProcess.stdout.readLine();
+                if (output.startsWith(">>> ")) {
+                    output = output.substr(4);
+                }
+                return output;
+            } catch (e) {
+                var error = kissProcess.stderr.readAll().toString();
+                throw 'failed to convert ${kissStr} to hscript: ${error}';
+            }
+            #else
+            throw "Can't convert Kiss to HScript on this target.";
+            #end
+        #if macro
+        }, true);
         #end
     }
 

kiss/src/kiss/Stream.hx

@@ -139,19 +139,25 @@ class Stream {
     }
 
     public function putBackString(s:String) {
-        var idx = s.length - 1;
-        while (idx >= 0) {
-            absoluteChar -= 1;
-            switch (s.charAt(idx)) {
-                case "\n":
-                    line -= 1;
-                    column = lineLengths.pop();
-                default:
-                    column -= 1;
+        #if macro
+        Kiss.measure("Stream.putBackString", () -> {
+        #end
+            var idx = s.length - 1;
+            while (idx >= 0) {
+                absoluteChar -= 1;
+                switch (s.charAt(idx)) {
+                    case "\n":
+                        line -= 1;
+                        column = lineLengths.pop();
+                    default:
+                        column -= 1;
+                }
+                --idx;
             }
-            --idx;
-        }
-        content = s + content;
+            content = s + content;
+        #if macro
+        }, true);
+        #end
     }
 
     public function takeChars(count:Int):Option<String> {